[BUG ? in 2.5.68] time and sleep...

[BUG ? in 2.5.68] time and sleep...

[Paolo Ciarrocchi]

Hi all,
I dunno if what I'm reporting is a real problem or not...
I was playing with both the time and sleep command,
I wrote a simple script like the following

for i in `seq 1 1 600`;
do
	time sleep 1
done;

Then I've run it in background and then I've run 'dbench 32'.

As soon as dbench finis its work I've killed the process in background.

The script was redirected to a file,
this is the result of a simple cat file.txt|grep elapsed|cut -d " " -f 3

0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.16elapsed <-
0:02.84elapsed <-
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.48elapsed <-
0:04.86elapsed <-
0:01.00elapsed
0:01.02elapsed
0:01.02elapsed
0:01.00elapsed
0:01.02elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.01elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.01elapsed
0:01.00elapsed
0:01.00elapsed
0:01.01elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.03elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.02elapsed
0:01.01elapsed
0:01.00elapsed
0:01.55elapsed <-
0:01.02elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.02elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.06elapsed
0:01.02elapsed
0:01.00elapsed
0:01.04elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.19elapsed <-
0:01.00elapsed <-
0:02.46elapsed <-
0:01.27elapsed <-
0:01.03elapsed <-
0:01.07elapsed <-
0:08.20elapsed <-
0:02.88elapsed <-
0:09.24elapsed <-
0:01.00elapsed
0:05.11elapsed <-
0:07.08elapsed <-
0:10.69elapsed <-
0:03.06elapsed <-
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
0:01.00elapsed
[...]

So in a few cases sleep 1 seems to last for a few seconds.

Is it OK ?

Kernel is 2.5.68 preemption on.

Ciao,
	Paolo
	

-- 
______________________________________________
http://www.linuxmail.org/
Now with e-mail forwarding for only US$5.95/yr

Powered by Outblaze

Re: [BUG ? in 2.5.68] time and sleep...

[Andrew Morton]

"Paolo Ciarrocchi" <ciarrocchi@linuxmail.org> wrote:
>
> for i in `seq 1 1 600`;
> do
> 	time sleep 1
> done;
> 
> Then I've run it in background and then I've run 'dbench 32'.
> ...
> 0:01.16elapsed <-
> 0:02.84elapsed <-

Yup, that's expected.  Normally the time command gets everything it needs
out of pagecache.  Sometimes it needs to go to disk, and gets whacked by
other disk activity.

It can be regenerative too: `time' gets throttled in the page allocator. 
This creates a larger time window in which the pages which it needs get
reclaimed.  So it has to read things from disk.  Which takes more time, so
more of its pages are reclaimed.  And for each page which was reclaimed,
`time' needs to allocate memory, so it gets throttled again...

So you see it feeds on itself.  What is normally a few millisecond delay
becomes a many-second delay.

There are probably games we can play in the page allocator to fix this up:
identifying heavy page allocators and preferentially stalling those. 
Tricky to get right.