These set of patches capture latency events caused by interrupts and premption disabled in kernel. The patches are based on the hist trigger feature developed by Tom Zanussi.
Git-commit: 7ef224d1d0e3a1ade02d02c01ce1dcffb736d2c3
As mentioned by Daniel, there is also a good write up in the following blog by Brendan Gregg: http://www.brendangregg.com/blog/2016-06-08/linux-hist-triggers.html
The perf interface for the same have not been developed yet. Related efforts: https://patchwork.kernel.org/patch/8439401
hwlat_detector tracer: https://lkml.org/lkml/2016/8/4/348 https://lkml.org/lkml/2016/8/4/346
The patch series also contains histogram triggers for missed hrtimer offsets.
Dependencies: CONFIG_IRQSOFF_TRACER CONFIG_PREEMPT_TRACER CONFIG_PROVE_LOCKING CONFIG_ARCH_HAVE_NMI_SAFE_CMPXCHG
Usage of triggers to generate histograms:
mount -t debugfs nodev /sys/kernel/debug echo 'hist:key=latency.log2:val=hitcount:sort=latency' > /sys/kernel/debug/tracing/events/latency/latency_irqs/trigger echo 'hist:key=common_pid.execname' > /sys/kernel/debug/tracing/events/latency/latency_hrtimer_interrupt/trigger
CPU specific breakdown of events:
echo 'hist:key=cpu,latency:val=hitcount:sort=latency' > /sys/kernel/debug/tracing/events/latency/latency_preempt/trigger echo 'hist:key=cpu,latency:val=hitcount:sort=latency if cpu==1' > /sys/kernel/debug/tracing/events/latency/latency_preempt/trigger
Histogram output: cat /sys/kernel/debug/tracing/events/latency/latency_irqs/hist cat /sys/kernel/debug/tracing/events/latency/latency_preempt/hist cat /sys/kernel/debug/tracing/events/latency/latency_critical_timings/hist cat /sys/kernel/debug/tracing/events/latency/latency_hrtimer_interrupt/hist
Disable a trigger: echo '!hist:key=latency.log2' > /sys/kernel/debug/tracing/events/latency/latency_irqs/trigger
Also, not reusing the time diff from the tracer as it only keeps only the preempt_timestamp in 'trace_array_cpu' but there are additional timestamp variables to be added for irqs, and critical timings. And not sure if it is okay to use the *_enabled() in this way, splitting the time stamping and adding the tracepoint in two sections.
Also, Daniel mentioned that Steven was tossing the idea around to introduce a 'variable' to the tracepoints which can be used for timestamping etc to which he wanted to avoid i.e. placing two tracepoints and doing later the time diff. It sounds like too much overhead.
TODO: 1. perf interface. Not sure if this is needed 2. Effective wakeup latencies of individual processes due to irqs/premption being disabled or due to missed timers.
Excerpt from Carsten Emde's patches: Effective latencies occurs during wakeup of a process. To determine effective latencies, the time stamp when a process is scheduled to be woken up has to be stored, and determines the duration of the wakeup time shortly before control is passed over to this process. Note that the apparent latency in user space may be somewhat longer, since the process may be interrupted after control is passed over to it but before the execution in user space takes place. Simply measuring the interval between enqueuing and wakeup may also not appropriate in cases when a process is scheduled as a result of a timer expiration. The timer may have missed its deadline, e.g. due to disabled interrupts, but this latency would not be registered. Therefore, the offsets of missed timers are recorded in a separate histogram. If both wakeup latency and missed timer offsets are configured and enabled, a third histogram may be enabled that records the overall latency as a sum of the timer latency, if any, and the wakeup latency. This histogram is called "timerandwakeup".
I will be working on the above points while some one can look at the patches listed below.
Binoy Jayan (2): tracing: Add trace_irqsoff tracepoints tracing: Histogram for missed timer offsets
Daniel Wagner (1): tracing: Deference pointers without RCU checks
include/linux/hrtimer.h | 1 + include/linux/rculist.h | 36 ++++++++++++++++++ include/linux/tracepoint.h | 4 +- include/trace/events/latency.h | 73 +++++++++++++++++++++++++++++++++++++ kernel/time/hrtimer.c | 27 ++++++++++++++ kernel/trace/trace_events_trigger.c | 6 +-- kernel/trace/trace_irqsoff.c | 48 +++++++++++++++++++++++- 7 files changed, 189 insertions(+), 6 deletions(-) create mode 100644 include/trace/events/latency.h