From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S932504AbcHXLRl (ORCPT ); Wed, 24 Aug 2016 07:17:41 -0400 Received: from mail-pf0-f172.google.com ([209.85.192.172]:35308 "EHLO mail-pf0-f172.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751568AbcHXLRk (ORCPT ); Wed, 24 Aug 2016 07:17:40 -0400 From: Binoy Jayan To: Arnd Bergmann , linaro-kernel@lists.linaro.org Cc: Daniel Wagner , Carsten Emde , linux-kernel@vger.kernel.org, "Steven Rostedt (Red Hat)" , Binoy Jayan Subject: [PATCH v2 0/3] *** Latency histograms - IRQSOFF,PREEMPTOFF *** Date: Wed, 24 Aug 2016 16:47:27 +0530 Message-Id: <1472037450-8907-1-git-send-email-binoy.jayan@linaro.org> X-Mailer: git-send-email 1.8.2.1 Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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