Advice on tracking down latency

Advice on tracking down latency

[Steve Fink]

I am attempting to use SystemTap to track down an occasional wakeup
latency in a set of realtime threads. Specifically, I have a couple of
threads, each bound to different CPUs, that run with SCHED_RR. Every
10 minutes (within a few milliseconds' accuracy), one of my threads
wakes up several milliseconds too late.

In my first attempt (also my first attempt at using SystemTap), I
wrote a simple script that uses probe.cpu_on to watch whenever one of
these threads wakes up. I time the interval between wakeups. It is
nearly always 1-3ms, but every 10 minutes it shoots up to something
like 12ms. I also print out the current pid() and tid() for each of my
threads of interest, as well as all other wakeups. This way, I can
scan through the log after the fact and find the slow wakeup, then
look backwards to see everything that was scheduled since the previous
invocation.

Unfortunately, all I see are "systemtap/<num>", a rare "events/<num>",
and lots and lots of "swapper". (The "events/<num>" are not on the CPU
with the slow wakeup, however.)

How can I get information on eg what interrupts are being processed?
Or what advice can anyone give me in tackling this sort of problem?
latencytop looks interesting, but I hate to perturb my kernel that
much. (I already have preemption enabled; without it, things are much
worse.)

Thanks,
Steve

Re: Advice on tracking down latency

[Kiran]

On Sat, 2009-12-05 at 17:15 -0800, Steve Fink wrote:
> I am attempting to use SystemTap to track down an occasional wakeup
> latency in a set of realtime threads. Specifically, I have a couple of
> threads, each bound to different CPUs, that run with SCHED_RR. Every
> 10 minutes (within a few milliseconds' accuracy), one of my threads
> wakes up several milliseconds too late.
> 
> In my first attempt (also my first attempt at using SystemTap), I
> wrote a simple script that uses probe.cpu_on to watch whenever one of
> these threads wakes up. I time the interval between wakeups. It is
> nearly always 1-3ms, but every 10 minutes it shoots up to something
> like 12ms. I also print out the current pid() and tid() for each of my
> threads of interest, as well as all other wakeups. This way, I can
> scan through the log after the fact and find the slow wakeup, then
> look backwards to see everything that was scheduled since the previous
> invocation.
> 
> Unfortunately, all I see are "systemtap/<num>", a rare "events/<num>",
> and lots and lots of "swapper". (The "events/<num>" are not on the CPU
> with the slow wakeup, however.)
> 
> How can I get information on eg what interrupts are being processed?
> Or what advice can anyone give me in tackling this sort of problem?
> latencytop looks interesting, but I hate to perturb my kernel that
> much. (I already have preemption enabled; without it, things are much
> worse.)
> 
> Thanks,
> Steve

Hi Steve,

There's a script called sched_switch.stp in
testsuite/systemtap.examples/profiling in the systemtap folder. This
script takes a process pid / name as parameter and displays the list of
processes that were woken up by this process and also lists the
processes that caused this process to schedule out. I think this script
can help you trace the latency issue in your realtime threads. 

The syntax for using this script is 
stap sched_switch.stp name <process_name> 
or 
stap sched_switch.stp pid <process_pid>

Thanks,
Kiran