Re: voluntary-preemption: understanding latency trace

[Ingo Molnar <mingo@elte.hu>]

* 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