Date:   Wed, 24 Aug 2016 16:47:27 +0530
From:   Binoy Jayan <binoy.jayan@...aro.org>
To:     Arnd Bergmann <arnd@...db.de>, linaro-kernel@...ts.linaro.org
Cc:     Daniel Wagner <daniel.wagner@...-carit.de>,
        Carsten Emde <C.Emde@...dl.org>, linux-kernel@...r.kernel.org,
        "Steven Rostedt (Red Hat)" <rostedt@...dmis.org>,
        Binoy Jayan <binoy.jayan@...aro.org>
Subject: [PATCH v2 0/3] *** Latency histograms - IRQSOFF,PREEMPTOFF ***

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

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

Powered by blists - more mailing lists