How to find long execution times in kernel threads?

Stanislav Meduna
2013-04-30T13:48:28Z

Hi,

I am experimenting with the cyclictest on a system running
several RT threads to find out where some latencies are
coming from and to get a better undertanding how the system
behaves.

The setup is:

class prio thread
FF 99 posixcputmr
FF 50 irq threads
FF 47 ksoftirqd
RR 45-25 my application exercising hrtimers, network, ...

Now I am trying to run
cyclictest -l100000000 -m -n -a0 -t1 -i200 -h400
at several priorities. The results after a few minutes are:

prio avg max
55 31 74
49 33 1124 (takes tens of seconds to record >1000)
46 33 1190 (nearly immediately >1000)

This is with 3.4.41-rt55 on a 500 MHz Geode LX, so 1 ms is quite
a lot of work.

What is the best approach to find
- which irq generates the occasional spikes
- why the ksoftirqd regularly generates spikes and what
soft-irq is responsible

These are obviously not 'hard' latencies - a runnable higher prio
thread gets the CPU - so the latency histograms won't show them.

Basically I'd like to trace what happened between a particular
process (not the highest priority one) was woken up until
it got scheduled, and stop if this took longer than some
defined time. Can this be done with the current tracing
infrastructure?

Thanks
--
Stano