[PATCH 0/3] *** Latency trace events

* [PATCH 0/3] *** Latency trace events - irqs, preempt, critical timing ***
@ 2016-08-18  7:09 Binoy Jayan
  2016-08-18  7:09 ` [PATCH 1/3] tracing: Deference pointers without RCU checks Binoy Jayan
                   ` (2 more replies)
  0 siblings, 3 replies; 11+ messages in thread
From: Binoy Jayan @ 2016-08-18  7:09 UTC (permalink / raw)
  To: Arnd Bergmann, linaro-kernel
  Cc: Daniel Wagner, Carsten Emde, linux-kernel,
	Steven Rostedt (Red Hat),
	Binoy Jayan

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

-- 
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
a Linux Foundation Collaborative Project

^ permalink raw reply	[flat|nested] 11+ messages in thread