Hi,
Thank you Steven and Daniel for reviewing v1 and providing suggestions. These set of patches [v2] 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
Changes from v1 as per comments from Steven/Daniel - Use single tracepoint for irq/preempt/critical timings by introducing a trace type field to differentiate trace type in the same tracepoint. A suspicious RCU usage error was introduced, while using the trigger command by mentioning the trace type as a key along with cpu. I couldn't figure out why. Also, this type of arrangement may also be substandard performance vice. - Using a more accurate fast local clock instead of a global ftrace clock.
TODO: 1. perf interface. Not sure if this is needed 2. Latency histograms - process wakeup latency - Suggestion from Daniel to not introduce tracepoints in scheduler's hotpaths - Alternative to attach kprobes to functions which falls in critical paths and find diff of timestamps using event trigger commands.
For example:
echo "p:myprobe1 start_critical_timings" > /sys/kernel/debug/tracing/kprobe_events echo "p:myprobe2 stop_critical_timings" >> /sys/kernel/debug/tracing/kprobe_events cat /sys/kernel/debug/tracing/kprobe_events echo 1 > /sys/kernel/debug/tracing/events/kprobes/myprobe1/enable echo 1 > /sys/kernel/debug/tracing/events/kprobes/myprobe2/enable cat /sys/kernel/debug/tracing/kprobe_events
And somehow save the timestamps for 'myprobe1' and 'myprobe2' in 'event_hist_trigger()'. This seems not feasible now as the histogram data is saved as a 'sum' only for the conditions met in the key definition. This makes it impossible to save timestamps for individual events.
kernel/trace/trace_events_hist.c +840: hist_trigger_elt_update()
Mhiramat and Steve, suggested an alternative to keep this timestamp is to create a new ftrace map, store the timestamp with context "key" on the named map upon event start. Then, at the event end trigger the histogram, pick timestamp from the map by using context "key" and calculate the difference. Basically this needs is a "map" which can be accessed from both the events, .i.e that is the "global variable".
Binoy
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 | 3 ++ include/linux/rculist.h | 36 ++++++++++++++++++ include/linux/tracepoint.h | 4 +- include/trace/events/latency.h | 74 +++++++++++++++++++++++++++++++++++++ kernel/time/hrtimer.c | 39 +++++++++++++++++++ kernel/trace/trace_events_trigger.c | 6 +-- kernel/trace/trace_irqsoff.c | 42 ++++++++++++++++++++- 7 files changed, 198 insertions(+), 6 deletions(-) create mode 100644 include/trace/events/latency.h