time and sleep...

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

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.