How to find long execution times in kernel threads?

[Stanislav Meduna <stano@meduna.org>]

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