voluntary-preemption: understanding latency trace

voluntary-preemption: understanding latency trace

[Kevin Hilman]

I'm seeing a mismatch between my manually-measured timings and the
timings I see in /proc/latency_trace.

I've got a SCHED_FIFO kernel thread at the highest priority
(MAX_USER_RT_PRIO-1) and it's sleeping on a wait queue.  The wake is
called from an ISR.  Since this thread is the highest priority in the
system, I expect it to run before the ISR threads and softIRQ threads
etc. 

In the ISR I sample sched_clock() just before the call to wake_up()
and in the thread I sample sched_clock() again just after the call to
sleep.  I'm seeing an almost 4ms latency between the call to wake_up
and the actual wakeup.  However, in /proc/latency_trace, the worst
latency I see during the running of this test is <500us.

I must be misunderstanding how the latency traces are
started/stopped.  Can anyone shed some light?  Thanks.

My current setup is using -R5, running on a PII 400MHz system.

Kevin 
http://hilman.org/

Re: voluntary-preemption: understanding latency trace

[Lee Revell]

On Thu, 2004-09-09 at 06:41, Kevin Hilman wrote:
> I'm seeing a mismatch between my manually-measured timings and the
> timings I see in /proc/latency_trace.
> 
> I've got a SCHED_FIFO kernel thread at the highest priority
> (MAX_USER_RT_PRIO-1) and it's sleeping on a wait queue.  The wake is
> called from an ISR.  Since this thread is the highest priority in the
> system, I expect it to run before the ISR threads and softIRQ threads
> etc. 
> 
> In the ISR I sample sched_clock() just before the call to wake_up()
> and in the thread I sample sched_clock() again just after the call to
> sleep.  I'm seeing an almost 4ms latency between the call to wake_up
> and the actual wakeup.  However, in /proc/latency_trace, the worst
> latency I see during the running of this test is <500us.
> 
> I must be misunderstanding how the latency traces are
> started/stopped.  Can anyone shed some light?  Thanks.
> 
> My current setup is using -R5, running on a PII 400MHz system.
> 

Ingo, any ideas here?  Looks like maybe the use of sched_clock is the
problem.

Lee

Re: voluntary-preemption: understanding latency trace

[Ingo Molnar]

* Lee Revell <rlrevell@joe-job.com> wrote:

> > I've got a SCHED_FIFO kernel thread at the highest priority
> > (MAX_USER_RT_PRIO-1) and it's sleeping on a wait queue.  The wake is
> > called from an ISR.  Since this thread is the highest priority in the
> > system, I expect it to run before the ISR threads and softIRQ threads
> > etc. 
> > 
> > In the ISR I sample sched_clock() just before the call to wake_up()
> > and in the thread I sample sched_clock() again just after the call to
> > sleep.  I'm seeing an almost 4ms latency between the call to wake_up
> > and the actual wakeup.  However, in /proc/latency_trace, the worst
> > latency I see during the running of this test is <500us.

> Ingo, any ideas here?  Looks like maybe the use of sched_clock is the
> problem.

sched_clock() is not 100% accurate (it takes a few shortcuts to avoid a
division) but it should be better than 90% so 4 msec measured means
there's likely some big delay.

if the priority setup is indeed as described above then the RT task
should have run much faster. First i'd suggest to check whether it's not
console printing (printing of a stacktrace or a latency trace) that 
slows things down.

If the console is silent and sched_clock() still indicates a ~4msec
delay then i'd suggest the following thing to debug this:

- upgrade to the -S0 patch

- edit kernel/latency.c's MAX_TRACE value to be 20000 or so

- reboot into the modified kernel and do:

     echo 2 > /proc/sys/kernel/trace_enabled

  (this turns on 'user defined tracing')

- modify the second sched_clock() call to do this instead:

     user_trace_start();

  modify the second sched_clock() call to do:

     user_trace_stop();

you should have the full trace of what happens between the wakeup and
the process activation in /proc/latency_trace. Please send it to me
(off-list). [NOTE: the usecs item in this special kind of latency_trace
is not accurate because trace_enabled=2 does not measure the latency -
but the absolute timestamps and relative latencies displayed in the
latency_trace will still be accurate.]

	Ingo

Re: voluntary-preemption: understanding latency trace

[Lee Revell]

On Fri, 2004-09-10 at 02:37, Ingo Molnar wrote:
> * Lee Revell <rlrevell@joe-job.com> wrote:
> 
> > > I've got a SCHED_FIFO kernel thread at the highest priority
> > > (MAX_USER_RT_PRIO-1) and it's sleeping on a wait queue.  The wake is
> > > called from an ISR.  Since this thread is the highest priority in the
> > > system, I expect it to run before the ISR threads and softIRQ threads
> > > etc. 
> > > 
> > > In the ISR I sample sched_clock() just before the call to wake_up()
> > > and in the thread I sample sched_clock() again just after the call to
> > > sleep.  I'm seeing an almost 4ms latency between the call to wake_up
> > > and the actual wakeup.  However, in /proc/latency_trace, the worst
> > > latency I see during the running of this test is <500us.
> 
> > Ingo, any ideas here?  Looks like maybe the use of sched_clock is the
> > problem.
> 
> sched_clock() is not 100% accurate (it takes a few shortcuts to avoid a
> division) but it should be better than 90% so 4 msec measured means
> there's likely some big delay.
> 
> if the priority setup is indeed as described above then the RT task
> should have run much faster. First i'd suggest to check whether it's not
> console printing (printing of a stacktrace or a latency trace) that 
> slows things down.
> 

Ah, this is probably it, this is pretty close to the latency I get when
/proc/latency_trace is updated, and this is also the one latency that
doesn't show in the traces by design.

rlrevell@mindpipe:~$ ./amlat-rlr/amlat 
599.895 MHz
secondsPerTick=0.000000
ticksPerSecond=599894954.372806
599.895 MHz
Using rtc interval of 1024
u=0
latency = 53 microseconds
latency = 60 microseconds
latency = 60 microseconds
latency = 62 microseconds
latency = 66 microseconds
latency = 76 microseconds
latency = 78 microseconds
latency = 2548 microseconds

The last line is the latency trace being updated.  If I turn off tracing
or set preempt_max_latency to a high value then amlat doesn't show
these.

Lee

Re: voluntary-preemption: understanding latency trace

[Ingo Molnar]

> - modify the second sched_clock() call to do this instead:
                   ^--- first
> 
>      user_trace_start();
> 
>   modify the second sched_clock() call to do:
> 
>      user_trace_stop();

Re: voluntary-preemption: understanding latency trace

[Kevin Hilman]

Ingo Molnar <mingo@elte.hu> writes:

> * Lee Revell <rlrevell@joe-job.com> wrote:
> 
> > > I've got a SCHED_FIFO kernel thread at the highest priority
> > > (MAX_USER_RT_PRIO-1) and it's sleeping on a wait queue.  The wake is
> > > called from an ISR.  Since this thread is the highest priority in the
> > > system, I expect it to run before the ISR threads and softIRQ threads
> > > etc. 
> > > 
> > > In the ISR I sample sched_clock() just before the call to wake_up()
> > > and in the thread I sample sched_clock() again just after the call to
> > > sleep.  I'm seeing an almost 4ms latency between the call to wake_up
> > > and the actual wakeup.  However, in /proc/latency_trace, the worst
> > > latency I see during the running of this test is <500us.
> 
> > Ingo, any ideas here?  Looks like maybe the use of sched_clock is the
> > problem.
> 
> sched_clock() is not 100% accurate (it takes a few shortcuts to avoid a
> division) but it should be better than 90% so 4 msec measured means
> there's likely some big delay.
> 
> if the priority setup is indeed as described above then the RT task
> should have run much faster. First i'd suggest to check whether it's not
> console printing (printing of a stacktrace or a latency trace) that 
> slows things down.

It must've been the latency trace itself as with it turned off, I'm
not seeing the 4ms latency between sched_clock() calls anymore.

> If the console is silent and sched_clock() still indicates a ~4msec
> delay then i'd suggest the following thing to debug this:
> 
> - upgrade to the -S0 patch
> 
> - edit kernel/latency.c's MAX_TRACE value to be 20000 or so
> 
> - reboot into the modified kernel and do:
> 
>      echo 2 > /proc/sys/kernel/trace_enabled
> 
>   (this turns on 'user defined tracing')
> 
> - modify the second sched_clock() call to do this instead:
> 
>      user_trace_start();
> 
>   modify the second sched_clock() call to do:
> 
>      user_trace_stop();
> 
> you should have the full trace of what happens between the wakeup and
> the process activation in /proc/latency_trace.

Using -S0 and the user_trace, I indeed see that the high-priority task
is beeing switched in very quickly.

Kevin