From patchwork Wed Sep 7 11:13:54 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Binoy Jayan X-Patchwork-Id: 75636 Delivered-To: patch@linaro.org Received: by 10.140.106.11 with SMTP id d11csp269642qgf; Wed, 7 Sep 2016 04:14:48 -0700 (PDT) X-Received: by 10.98.96.193 with SMTP id u184mr81135725pfb.85.1473246887658; Wed, 07 Sep 2016 04:14:47 -0700 (PDT) Return-Path: Received: from vger.kernel.org (vger.kernel.org. [209.132.180.67]) by mx.google.com with ESMTP id r23si1132286pfi.37.2016.09.07.04.14.47; Wed, 07 Sep 2016 04:14:47 -0700 (PDT) Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67; Authentication-Results: mx.google.com; dkim=pass header.i=@linaro.org; spf=pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) smtp.mailfrom=linux-kernel-owner@vger.kernel.org; dmarc=pass (p=NONE dis=NONE) header.from=linaro.org Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S936342AbcIGLOb (ORCPT + 27 others); Wed, 7 Sep 2016 07:14:31 -0400 Received: from mail-pf0-f178.google.com ([209.85.192.178]:35271 "EHLO mail-pf0-f178.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S936135AbcIGLOZ (ORCPT ); Wed, 7 Sep 2016 07:14:25 -0400 Received: by mail-pf0-f178.google.com with SMTP id w87so5809700pfk.2 for ; Wed, 07 Sep 2016 04:14:24 -0700 (PDT) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=linaro.org; s=google; h=from:to:cc:subject:date:message-id:in-reply-to:references; bh=5c98gvnhIkZJBlgZiqqpjzuK0hqwx7cHhoodG8eherU=; b=YCE1nkBbfvhr1c87ASaMbyioizgh+6kZXLPdO2JEcY6/iJ/SzWsvLv9UMmLkMS5n9m 7kHjTz0DTDIQXYWNE+qnp9brvjGInuZATFZHtY3CHZ2r/j0pxURzzBkicS8uzkV1rpwH 6FHTRjAJxyQ9ub6nJ7pY+JzDELXyf+L8q5gPY= X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references; bh=5c98gvnhIkZJBlgZiqqpjzuK0hqwx7cHhoodG8eherU=; b=d2c/N+F3ZhXuMaRaa3aOyy5WD2H1TWpdA83PeHRwf83B2DxlGgLDLfXhQgWclIJc0g THyQ4rL01bnZxZKZj/qnrr/8iU0y8hT+O9Y1E0P0oqZEWFBhdA0xBHpF1iaCpULBWsOK NE0V76TfBWP6bHauYFwqkI71b5NMO4o9XhlxmgESpqC4t2zKSb7kUbcDZjhS8fvEiHdy /25Ya2yG1fZYPt240UdTAVgK3YgiLdY0vwhcwChm4Y/c3JYD1MTyA0a5DRIod7PBhE3V Y0r3QhAOQoZdzSYLEtuJyIreu9OCCOE7UN/o5UyRJMgEw8gbb+lStrscnJSkkiGRR2rS 0z/g== X-Gm-Message-State: AE9vXwOUvnCwwkuGKfgjYlz8AEoF7gJ7DJV4HyNXpxhutB4Z+pA2DDa42sun5iBl3HN9C0Ew X-Received: by 10.98.70.8 with SMTP id t8mr81883992pfa.36.1473246864150; Wed, 07 Sep 2016 04:14:24 -0700 (PDT) Received: from blr-ubuntu-59.ap.qualcomm.com ([202.46.23.61]) by smtp.gmail.com with ESMTPSA id n10sm48202616pap.16.2016.09.07.04.14.20 (version=TLS1_1 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Wed, 07 Sep 2016 04:14:23 -0700 (PDT) From: Binoy Jayan To: "Steven Rostedt (Red Hat)" Cc: Ingo Molnar , Daniel Wagner , Arnd Bergmann , linux-kernel@vger.kernel.org, Masami , Thomas Gleixner , Binoy Jayan Subject: [PATCH v6 3/4] tracing: Add trace_irqsoff tracepoints Date: Wed, 7 Sep 2016 16:43:54 +0530 Message-Id: <1473246835-30075-4-git-send-email-binoy.jayan@linaro.org> X-Mailer: git-send-email 1.8.2.1 In-Reply-To: <1473246835-30075-1-git-send-email-binoy.jayan@linaro.org> References: <1473246835-30075-1-git-send-email-binoy.jayan@linaro.org> Sender: linux-kernel-owner@vger.kernel.org Precedence: bulk List-ID: X-Mailing-List: linux-kernel@vger.kernel.org This work is based on work by Daniel Wagner. A few tracepoints are added at the end of the critical section. With the hist trigger in place, the hist trigger plots may be generated, with per-cpu breakdown of events captured. It is based on linux kernel's event infrastructure. The following filter(s) may be used 'hist:key=latency.log2:val=hitcount:sort=latency' 'hist:key=ltype,latency:val=hitcount:sort=latency if cpu==1' 'hist:key=ltype:val=latency:sort=ltype if ltype==0 && cpu==2' Where ltype is 0: IRQSOFF latency 1: PREEMPTOFF Latency 2: Critical Timings This captures only the latencies introduced by disabled irqs and preemption. Additional per process data has to be captured to calculate the effective latencies introduced for individual processes. Initial work - latency.patch [1] https://git.kernel.org/cgit/linux/kernel/git/rt/linux-stable-rt.git/commit/?h=v3.14-rt-rebase&id=56d50cc34943bbba12b8c5942ee1ae3b29f73acb Signed-off-by: Binoy Jayan --- include/trace/events/latency.h | 56 ++++++++++++++++++++++++++++++++++++++++++ kernel/trace/trace_irqsoff.c | 35 ++++++++++++++++++++++++++ 2 files changed, 91 insertions(+) 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 diff --git a/include/trace/events/latency.h b/include/trace/events/latency.h new file mode 100644 index 0000000..96c8757 --- /dev/null +++ b/include/trace/events/latency.h @@ -0,0 +1,56 @@ +#undef TRACE_SYSTEM +#define TRACE_SYSTEM latency + +#if !defined(_TRACE_HIST_H) || defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_HIST_H + +#include + +#ifndef __TRACE_LATENCY_TYPE +#define __TRACE_LATENCY_TYPE + +enum latency_type { + LT_IRQ, + LT_PREEMPT, + LT_CRITTIME, + LT_MAX +}; + +TRACE_DEFINE_ENUM(LT_IRQ); +TRACE_DEFINE_ENUM(LT_PREEMPT); +TRACE_DEFINE_ENUM(LT_CRITTIME); + +#define show_ltype(type) \ + __print_symbolic(type, \ + { LT_IRQ, "IRQ" }, \ + { LT_PREEMPT, "PREEMPT" }, \ + { LT_CRITTIME, "CRIT_TIME" }) +#endif + +DECLARE_EVENT_CLASS(latency_template, + TP_PROTO(int ltype, cycles_t latency), + + TP_ARGS(ltype, latency), + + TP_STRUCT__entry( + __field(int, ltype) + __field(cycles_t, latency) + ), + + TP_fast_assign( + __entry->ltype = ltype; + __entry->latency = latency; + ), + + TP_printk("ltype=%s(%d), latency=%lu", show_ltype(__entry->ltype), + __entry->ltype, (unsigned long) __entry->latency) +); + +DEFINE_EVENT(latency_template, latency_preempt, + TP_PROTO(int ltype, cycles_t latency), + TP_ARGS(ltype, latency)); + +#endif /* _TRACE_HIST_H */ + +/* This part must be outside protection */ +#include diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c index 03cdff8..60ee660 100644 --- a/kernel/trace/trace_irqsoff.c +++ b/kernel/trace/trace_irqsoff.c @@ -13,13 +13,19 @@ #include #include #include +#include +#include #include "trace.h" +#define CREATE_TRACE_POINTS +#include + static struct trace_array *irqsoff_trace __read_mostly; static int tracer_enabled __read_mostly; static DEFINE_PER_CPU(int, tracing_cpu); +static DEFINE_PER_CPU(cycle_t, lat_ts[LT_MAX]); static DEFINE_RAW_SPINLOCK(max_trace_lock); @@ -419,9 +425,23 @@ stop_critical_timing(unsigned long ip, unsigned long parent_ip) atomic_dec(&data->disabled); } +static inline void latency_preempt_timing_start(enum latency_type ltype) +{ + this_cpu_write(lat_ts[ltype], (cycle_t) trace_clock_local()); +} + +static inline void latency_preempt_timing_stop(enum latency_type type) +{ + trace_latency_preempt(type, + (cycle_t) trace_clock_local() - this_cpu_read(lat_ts[type])); +} + /* start and stop critical timings used to for stoppage (in idle) */ void start_critical_timings(void) { + if (unlikely(trace_latency_preempt_enabled())) + latency_preempt_timing_start(LT_CRITTIME); + if (preempt_trace() || irq_trace()) start_critical_timing(CALLER_ADDR0, CALLER_ADDR1); } @@ -431,6 +451,9 @@ void stop_critical_timings(void) { if (preempt_trace() || irq_trace()) stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1); + + if (unlikely(trace_latency_preempt_enabled())) + latency_preempt_timing_stop(LT_CRITTIME); } EXPORT_SYMBOL_GPL(stop_critical_timings); @@ -438,6 +461,9 @@ EXPORT_SYMBOL_GPL(stop_critical_timings); #ifdef CONFIG_PROVE_LOCKING void time_hardirqs_on(unsigned long a0, unsigned long a1) { + if (unlikely(trace_latency_preempt_enabled())) + latency_preempt_timing_stop(LT_IRQ); + if (!preempt_trace() && irq_trace()) stop_critical_timing(a0, a1); } @@ -446,6 +472,9 @@ void time_hardirqs_off(unsigned long a0, unsigned long a1) { if (!preempt_trace() && irq_trace()) start_critical_timing(a0, a1); + + if (unlikely(trace_latency_preempt_enabled())) + latency_preempt_timing_start(LT_IRQ); } #else /* !CONFIG_PROVE_LOCKING */ @@ -503,6 +532,9 @@ EXPORT_SYMBOL(trace_hardirqs_off_caller); #ifdef CONFIG_PREEMPT_TRACER void trace_preempt_on(unsigned long a0, unsigned long a1) { + if (unlikely(trace_latency_preempt_enabled())) + latency_preempt_timing_stop(LT_PREEMPT); + if (preempt_trace() && !irq_trace()) stop_critical_timing(a0, a1); } @@ -511,6 +543,9 @@ void trace_preempt_off(unsigned long a0, unsigned long a1) { if (preempt_trace() && !irq_trace()) start_critical_timing(a0, a1); + + if (unlikely(trace_latency_preempt_enabled())) + latency_preempt_timing_start(LT_PREEMPT); } #endif /* CONFIG_PREEMPT_TRACER */