How to find long execution times in kernel threads?

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

Stano,

Sure, record everything (trace-cmd record -e all) and analyze the traces. Use kernelshark, if you prefer a GUI. I wrote a blog article on this topic about three years ago:
https://www.osadl.org/Single-View.111+M5dc445b8ee7.0.html

Once you get an idea what is going on and which traces, events and/or processes are particularly interesting, you may filter the recording (trace-cmd record --help) in order to focus on your case and to reduce Heisenberg.

Hope this helps,
-Carsten.

Well, the problem is that with record -e all I get 20 ms instead of 1 ms, so I'd say Mr. Heisenberg laughs at me loudly here ;)

Thanks for the pointer anyway, I'll try to thoroughly read the available documentation and come up with some sane set of filters to start with.

Thanks

                                      Stano

Even i had some issues in schedule latencies. i tried to use trace-cmd record -e all and kernelshark.
What i found was since it is run as a separate process it also need to get scheduled to get the traces and by default it is get scheduled in SCHED_OTHER. This tracing is also affected by the values in
/proc/sys/kernel/sched_rt_runtime_us and sched_rt_period_us.

So what i understood is for initial measurements kernelshark is a good tool, but to go more deep this is not enough.
May be profiling tools like OPROF should be good. I am still exploring this.

Regards
Ashoka. K

Stano,

He who laughs last, laughs loudest. Since the entire system slows down, you may only need to adapt cycles and thresholds accordingly. Tracing is a very useful tool to identify sources of latencies and has helped a lot to make Linux RT as good as it is today. As a role of thumb, for example, we use five times longer cycles when enabling function tracing. If, for example, the output of

cyclictest -m -M -Sp90 -i100 -d0

most of the time indicates a worst-case latency of about 50 microseconds but is interspersed with sporadic latencies of more than 500 microseconds,

cyclictest -m -M -Sp90 -i500 -d0 -fb1000

probably will break at the first occurrence of the latency in question and let you diagnose its origin at the end of the trace output.

-Carsten.

Yep, I will try it. However as this is connected to a real application running parallel and generating some load pattern this is not so easy - for example I'll need to go down with the HZ, otherwise the timer ticking once per ms can be already too much, which in turn will probably affect the RR threads etc. There are also constraints from the outside world that have to be met while running - these are still far, but with tracing enabled not anymore an order of magnitude far.

That I am running this on a low-spec embedded systems that already struggles with saving the data does not make it easier either.

that seems plainly wrong, the ksoftirqd just had really a lot of work with hrtimers, RCU, network etc. But I am not sure whether I caught _the_ situation.

Yep, the infrastructure is fantastic.

I tried this but I was unable to load a trace.dat produced by breaking the tracing this way into kernelshark on at least two occasions. Only stopping the trace from trace-cmd itself worked. Are there some known issues?

I am using trace-cmd from git. The recording and examining system are not the same, but are reasonably similar library-wise (both are Debian squeeze-based).

Thanks

                                  Stano