Hi all,
I am sending this patch series here before public review. Please have a look and provide your insight into its correctness.
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
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".
Thanks, Binoy
Binoy Jayan (1): latency: Histogram for missed timer offsets
Daniel Wagner (2): tracing: Deference pointers without RCU checks tracing: Add trace_irqsoff tracepoints
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 | 47 +++++++++++++++++++++++- 7 files changed, 188 insertions(+), 6 deletions(-) create mode 100644 include/trace/events/latency.h