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/348https://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
--
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
a Linux Foundation Collaborative Project