severe jitter experienced with "select()" in linux 2.6.14-rt22

severe jitter experienced with "select()" in linux 2.6.14-rt22

[Gautam Thaker]

I have been conduting some jitter tests on 2.6.14-rt22.  (Many thanks
to Ingo Molnar who has helped in various ways.) I wanted to share the
results with others and seek comments as to the problems I see and
whether it is  possible to overcome them and how might I go about it.

My tests are rather simple. I take 1 million samples of the actual
durations of nanosleep() versus the requested 1000 usec duration.

a = gettimeofday();    		/* measure delta time since last sleep */
for (i = 0; i < NUM_SAMPLES; i++) {	/* one million iterations,
typically */
   nanosleep(1000000);   	/* sleep for 1 msec; = 1000 HZ  */
   b = gettimeofday();    	/* measure delta time since last sleep */
   record (b - a);        	/* record the measurement in a histogram */
   a = b;
}

The histogram of the "nanosleep()" tests can be viewed at:

http://www.atl.external.lmco.com/projects/QoS/compare/j_data/linux/2.6.14-rt22/2.6.14-rt22-UNIPROC-tracing-kernel-no-tracing-done.nano.hist.png

The results are excellent with actual sleep durations for
nanosleep(1000 usec) being:

minimum: 1020  (usec)
maximum: 1052
mean: 1030
variance: 3.876
num_points: 1000000

I then repeated this test by replacing nanosleep(1000 usec) with

select(0, 0, 0, 0, 1000usec)

And again measure the observed jitter. The test application is run in
SCHED_FIFO class at priority 60; the softirq-* processes are run at
SCHED_FIFO priority 90. In no case does select() return anything other
than value of zero.

The select() test exepriences severe jitter. Histogram can be viewed
at:

http://www.atl.external.lmco.com/projects/QoS/compare/j_data/linux/2.6.14-rt22/2.6.14-rt22-UNIPROC-tracing-kernel-no-tracing-done.select.out_with_chrt_on_softirq_procs.hist.png

and the summary of observed select() sleep duration samples is:

minimum: 35 (usec)
maximum: 239525
mean: 1373.24
variance: 8.99334e+07
num_points: 1000000

The computer is otherwise unloaded and unused and in a small, private
network. The h/w is a 2.8 GHZ dual Xeon IBM Blade, but I have been
testing with 2.6.14-rt22 UniProcessor  kernel configured with full
preemption and 1000 HZ clock. The kernel is compiled with "preemption
latencry tracing" flags but no tracing is enabled during either of
these two tests.

Data summry in a table form can be seen here:

http://www.atl.external.lmco.com/projects/QoS/compare/cgi-bin/tmp/table_7518.html

My queries are this:

1) are these results believable? I like to think that i am careful
tester, but  error in testing is always possible.

2) Can this jitter in  select() be overcome and can select() get as
good as nanosleep() is now under the "rt" kernel patches?

3) I have tried to do some latency tracing, but I can't seem to learn
anything valulabe as to the cause. I have followed the procedure
outlined by Ingo Molnar, but it is  not clear if "dmesg" or
"/proc/latency_trace" reveal anything of value.

/proc/latency trace is full of lines such as these:

   <...>-3     0.... 20317us : __down_mutex (rt_run_flush)
   <...>-3     0.... 20317us : __up_mutex_savestate (rt_run_flush)
   <...>-3     0.... 20317us : __down_mutex (rt_run_flush)
   <...>-3     0.... 20317us : __up_mutex_savestate (rt_run_flush)
   <...>-3     0.... 20317us : __down_mutex (rt_run_flush)
   <...>-3     0.... 20317us : __up_mutex_savestate (rt_run_flush)
   <...>-3     0.... 20318us : __down_mutex (rt_run_flush)
   <...>-3     0.... 20318us : __up_mutex_savestate (rt_run_flush)
   <...>-3     0.... 20318us : __down_mutex (rt_run_flush)
   <...>-3     0.... 20318us : __up_mutex_savestate (rt_run_flush)
   <...>-3     0.... 20318us : __down_mutex (rt_run_flush)
   <...>-3     0.... 20318us : __up_mutex_savestate (rt_run_flush)
   <...>-3     0.... 20319us : __down_mutex (rt_run_flush)

and

"dmesg" says somethign like this:

(        ubersock-4032 |#0): new 131 us user-latency.
(        ubersock-4032 |#0): new 131 us user-latency.
(        ubersock-4032 |#0): new 133 us user-latency.
(        ubersock-4032 |#0): new 221 us user-latency.
(        ubersock-4032 |#0): new 223 us user-latency.
(        ubersock-4032 |#0): new 20629 us user-latency.
root@blade8>

When tracing I exit my test when a large latency is observed (in the
case above a 20,629 usec value was observed by the "select()" test. 

If there is a more specific real-time newsgroup please direct me to it.

G. Thaker

Re: severe jitter experienced with "select()" in linux 2.6.14-rt22

[Steven Rostedt]

Please always CC Ingo Molnar on all -rt related issues.  And Thomas
Gleixner and John Stultz on timer issues with -rt. (CC John on timer
issues in mainline too).


On Thu, 2005-12-15 at 20:06 -0500, Gautam Thaker wrote:
> I have been conduting some jitter tests on 2.6.14-rt22.  (Many thanks
> to Ingo Molnar who has helped in various ways.) I wanted to share the
> results with others and seek comments as to the problems I see and
> whether it is  possible to overcome them and how might I go about it.

Hmm, it seems you know you should have CC'd Ingo ;)

> 
> My tests are rather simple. I take 1 million samples of the actual
> durations of nanosleep() versus the requested 1000 usec duration.
> 
> a = gettimeofday();    		/* measure delta time since last sleep */
> for (i = 0; i < NUM_SAMPLES; i++) {	/* one million iterations,
> typically */
>    nanosleep(1000000);   	/* sleep for 1 msec; = 1000 HZ  */
>    b = gettimeofday();    	/* measure delta time since last sleep */
>    record (b - a);        	/* record the measurement in a histogram */
>    a = b;
> }
> 
> The histogram of the "nanosleep()" tests can be viewed at:
> 
> http://www.atl.external.lmco.com/projects/QoS/compare/j_data/linux/2.6.14-rt22/2.6.14-rt22-UNIPROC-tracing-kernel-no-tracing-done.nano.hist.png
> 
> The results are excellent with actual sleep durations for
> nanosleep(1000 usec) being:
> 
> minimum: 1020  (usec)
> maximum: 1052
> mean: 1030
> variance: 3.876
> num_points: 1000000
> 
> I then repeated this test by replacing nanosleep(1000 usec) with
> 
> select(0, 0, 0, 0, 1000usec)

Well, I hope you passed in a variable here.  I'm sure you did.

> 
> And again measure the observed jitter. The test application is run in
> SCHED_FIFO class at priority 60; the softirq-* processes are run at
> SCHED_FIFO priority 90. In no case does select() return anything other
> than value of zero.
> 
> The select() test exepriences severe jitter. Histogram can be viewed
> at:

Is there any requirement that select must sleep the full time? At least
have you checked the value of the timeout to see if there was reported
time left?  The return value wont be zero.  I believe that the select my
return early with reported time left.
 
> 
> http://www.atl.external.lmco.com/projects/QoS/compare/j_data/linux/2.6.14-rt22/2.6.14-rt22-UNIPROC-tracing-kernel-no-tracing-done.select.out_with_chrt_on_softirq_procs.hist.png
> 
> and the summary of observed select() sleep duration samples is:

The simple answer is that the select system call uses the non high
resolution timers.  There's really no reason to use select for timing.
That's really just a side effect of the system call.  If you need
accurate timing, that's what nanosleep is for.  IIRC, others on LKML
have stated that it is considered bad programming to use select as a
timer when nanosleep is available.

So, what you show is what I would expect.

-- Steve

Re: severe jitter experienced with "select()" in linux 2.6.14-rt22

[Gautam Thaker]

Steven Rostedt wrote:

>Please always CC Ingo Molnar on all -rt related issues.  And Thomas
>Gleixner and John Stultz on timer issues with -rt. (CC John on timer
>issues in mainline too).
>  
>
Will do so in future, did not know anyone else well enough.

>
>Is there any requirement that select must sleep the full time? At least
>have you checked the value of the timeout to see if there was reported
>time left?  The return value wont be zero.  I believe that the select my
>return early with reported time left.
> 
>  
>

Yes, select is permitted to return before full timeout value, but on an 
idle, fast machine one hopes this does not happen too too often. And one 
also hopes that overruns are not too frequent. However, the results I 
get were, as can be seen from the select histogram, rather all over. 

>The simple answer is that the select system call uses the non high
>resolution timers.  There's really no reason to use select for timing.
>That's really just a side effect of the system call.  If you need
>accurate timing, that's what nanosleep is for.  IIRC, others on LKML
>have stated that it is considered bad programming to use select as a
>timer when nanosleep is available.
>  
>
well, there are a large number of applications that we have that use 
select(). These include CORBA ORBs etc and we would like to run them and 
get the benefits of excellent RT properties of -rt kernel.  It would be 
too too difficult for us, at least for now, to rewrite an ORB in such a 
way that it does not use any select() but instead uses nanosleep().  I 
assume high resolution timers must be more expensive - that is why they 
do not get used by select(). But there are cases where I don't mind 
paying the extra overhead, if any, to obtain good behaviour out of 
select().

>So, what you show is what I would expect.
>  
>
Sigh, but thanks for the comments.

>-- Steve
>  
>

Gautam

Re: severe jitter experienced with "select()" in linux 2.6.14-rt22

[Lee Revell]

On Thu, 2005-12-15 at 20:06 -0500, Gautam Thaker wrote:
> 
> /proc/latency trace is full of lines such as these:
> 
>    <...>-3     0.... 20317us : __down_mutex (rt_run_flush)
>    <...>-3     0.... 20317us : __up_mutex_savestate (rt_run_flush)
>    <...>-3     0.... 20317us : __down_mutex (rt_run_flush)
>    <...>-3     0.... 20317us : __up_mutex_savestate (rt_run_flush)
>    <...>-3     0.... 20317us : __down_mutex (rt_run_flush)
>    <...>-3     0.... 20317us : __up_mutex_savestate (rt_run_flush)
>    <...>-3     0.... 20318us : __down_mutex (rt_run_flush)
>    <...>-3     0.... 20318us : __up_mutex_savestate (rt_run_flush)
>    <...>-3     0.... 20318us : __down_mutex (rt_run_flush)
>    <...>-3     0.... 20318us : __up_mutex_savestate (rt_run_flush)
>    <...>-3     0.... 20318us : __down_mutex (rt_run_flush)
>    <...>-3     0.... 20318us : __up_mutex_savestate (rt_run_flush)
>    <...>-3     0.... 20319us : __down_mutex (rt_run_flush)
> 
> and
> 
> "dmesg" says somethign like this:
> 
> (        ubersock-4032 |#0): new 131 us user-latency.
> (        ubersock-4032 |#0): new 131 us user-latency.
> (        ubersock-4032 |#0): new 133 us user-latency.
> (        ubersock-4032 |#0): new 221 us user-latency.
> (        ubersock-4032 |#0): new 223 us user-latency.
> (        ubersock-4032 |#0): new 20629 us user-latency.
> root@blade8>
> 
> When tracing I exit my test when a large latency is observed (in the
> case above a 20,629 usec value was observed by the "select()" test. 
> 

AI've seen this in my tests too, I think it's still a problem that
rt_run_flush can cause a 20ms+ non preemptible section.

Ingo mentioned that he may push softirq preemption upstream which would
fix this.  You can also try tweaking these sysctls:

net.ipv4.route.gc_elasticity = 8
net.ipv4.route.gc_interval = 60
net.ipv4.route.gc_timeout = 300
net.ipv4.route.gc_min_interval_ms = 500
net.ipv4.route.gc_min_interval = 0
net.ipv4.route.gc_thresh = 4096

which AFAICT should let you tune the route cache garbage collection to
run more often and hopefully process fewer routes per run.

Lee