From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753088AbcHRHJj (ORCPT ); Thu, 18 Aug 2016 03:09:39 -0400 Received: from mail-pf0-f178.google.com ([209.85.192.178]:33829 "EHLO mail-pf0-f178.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751092AbcHRHJi (ORCPT ); Thu, 18 Aug 2016 03:09:38 -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 0/3] *** Latency trace events - irqs, preempt, critical timing *** Date: Thu, 18 Aug 2016 12:39:23 +0530 Message-Id: <1471504166-27665-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 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