From patchwork Thu Aug 18 07:09:25 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Binoy Jayan X-Patchwork-Id: 74137 Delivered-To: patch@linaro.org Received: by 10.140.29.52 with SMTP id a49csp205550qga; Thu, 18 Aug 2016 00:10:07 -0700 (PDT) X-Received: by 10.98.75.219 with SMTP id d88mr1429199pfj.91.1471504206825; Thu, 18 Aug 2016 00:10:06 -0700 (PDT) Return-Path: Received: from vger.kernel.org (vger.kernel.org. [209.132.180.67]) by mx.google.com with ESMTP id w4si1032064pfk.173.2016.08.18.00.10.06; Thu, 18 Aug 2016 00:10:06 -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 S1753665AbcHRHJs (ORCPT + 27 others); Thu, 18 Aug 2016 03:09:48 -0400 Received: from mail-pa0-f41.google.com ([209.85.220.41]:35831 "EHLO mail-pa0-f41.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753233AbcHRHJp (ORCPT ); Thu, 18 Aug 2016 03:09:45 -0400 Received: by mail-pa0-f41.google.com with SMTP id i5so3909437pat.2 for ; Thu, 18 Aug 2016 00:09:44 -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=CT27H65A749EM7FWw9dHao9QrYp7bLXX3LhA83MfNaQ=; b=k2Ln0lNRHqHKMkZI0gjN+M1CbiSs7Hs8zm03PLfqmKCrS/7rmIc4Kmcx/Pgl08wlK0 hVCoPcNcoqr/VlaByrOGk9ypfoygxjKkEgIS9seSMpXHk58dwk3NkXsNEzPv1cDkaGvb mLJCmp7qLO1b7GlirTWKYUSnxdHyK/80LqL9A= 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=CT27H65A749EM7FWw9dHao9QrYp7bLXX3LhA83MfNaQ=; b=B0MEsUra0OMv5ifSUXPkzCaSiuFBVj1NRBUFuCG60N3Egc//0d0+xvLN82Grew4eBW QxIGWBTnPKCQeHmyv/aaAJRsYq2fI5fI5eW2zw9Fj4temS34to0/RGYPVrT55bXNNKLr o9hvGumVft84ePvsv9+DtchZVQpysRBZeqKg9UlQZXUsn4f7Xg4pejzDpq3CQHsZFfIQ tMCjLIS5goFa27+AFJ2l7gggptZa3DtfcqR64At8uirbFHiBWV/HgBTr8ZDgaZZ06oFa TuqvHpP66qYImZW/6o+t0QGfG/Wg307e3EL4DfAKD+UsGwPNBJSUe79NgM6H6H3QenmI OC+A== X-Gm-Message-State: AEkoouvCvXyrcfdJqnXWuKHnPiud2T9UcuwG8f0w7G09Te8v52Q/vYRAUxUpPu/Sr6EvRvCj X-Received: by 10.66.161.225 with SMTP id xv1mr1482983pab.20.1471504184080; Thu, 18 Aug 2016 00:09:44 -0700 (PDT) Received: from blr-ubuntu-59.ap.qualcomm.com ([202.46.23.61]) by smtp.gmail.com with ESMTPSA id ra13sm1414849pac.29.2016.08.18.00.09.40 (version=TLS1_1 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Thu, 18 Aug 2016 00:09:43 -0700 (PDT) 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 2/3] tracing: Add trace_irqsoff tracepoints Date: Thu, 18 Aug 2016 12:39:25 +0530 Message-Id: <1471504166-27665-3-git-send-email-binoy.jayan@linaro.org> X-Mailer: git-send-email 1.8.2.1 In-Reply-To: <1471504166-27665-1-git-send-email-binoy.jayan@linaro.org> References: <1471504166-27665-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=cpu,latency:val=hitcount:sort=latency if cpu==1' 'hist:key=common_pid.execname' 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 | 42 ++++++++++++++++++++++++++++++++++++ kernel/trace/trace_irqsoff.c | 48 +++++++++++++++++++++++++++++++++++++++++- 2 files changed, 89 insertions(+), 1 deletion(-) 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..b279e2d --- /dev/null +++ b/include/trace/events/latency.h @@ -0,0 +1,42 @@ +#undef TRACE_SYSTEM +#define TRACE_SYSTEM latency + +#if !defined(_TRACE_HIST_H) || defined(TRACE_HEADER_MULTI_READ) +#define _TRACE_HIST_H + +#include + +DECLARE_EVENT_CLASS(latency_template, + TP_PROTO(int cpu, cycles_t latency), + + TP_ARGS(cpu, latency), + + TP_STRUCT__entry( + __field(int, cpu) + __field(cycles_t, latency) + ), + + TP_fast_assign( + __entry->cpu = cpu; + __entry->latency = latency; + ), + + TP_printk("cpu=%d, latency=%lu", __entry->cpu, __entry->latency) +); + +DEFINE_EVENT(latency_template, latency_irqs, + TP_PROTO(int cpu, cycles_t latency), + TP_ARGS(cpu, latency)); + +DEFINE_EVENT(latency_template, latency_preempt, + TP_PROTO(int cpu, cycles_t latency), + TP_ARGS(cpu, latency)); + +DEFINE_EVENT(latency_template, latency_critical_timings, + TP_PROTO(int cpu, cycles_t latency), + TP_ARGS(cpu, 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..08d8d05 100644 --- a/kernel/trace/trace_irqsoff.c +++ b/kernel/trace/trace_irqsoff.c @@ -14,13 +14,20 @@ #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, ts_irqs); +static DEFINE_PER_CPU(cycle_t, ts_preempt); +static DEFINE_PER_CPU(cycle_t, ts_critical_timings); static DEFINE_RAW_SPINLOCK(max_trace_lock); enum { @@ -419,9 +426,22 @@ stop_critical_timing(unsigned long ip, unsigned long parent_ip) atomic_dec(&data->disabled); } +static inline void mark_timestamp(cycle_t __percpu *ts) +{ + int cpu = raw_smp_processor_id(); + per_cpu(*ts, cpu) = ftrace_now(cpu); +} + +static inline cycle_t get_delta(int cpu, cycle_t __percpu *ts) +{ + return ftrace_now(cpu) - per_cpu(*ts, cpu); +} /* start and stop critical timings used to for stoppage (in idle) */ void start_critical_timings(void) { + if (trace_latency_critical_timings_enabled()) + mark_timestamp(&ts_critical_timings); + if (preempt_trace() || irq_trace()) start_critical_timing(CALLER_ADDR0, CALLER_ADDR1); } @@ -431,6 +451,13 @@ void stop_critical_timings(void) { if (preempt_trace() || irq_trace()) stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1); + + if (trace_latency_critical_timings_enabled()) { + int cpu = raw_smp_processor_id(); + trace_latency_critical_timings(cpu, + get_delta(cpu, &ts_critical_timings)); + } + } EXPORT_SYMBOL_GPL(stop_critical_timings); @@ -438,6 +465,10 @@ EXPORT_SYMBOL_GPL(stop_critical_timings); #ifdef CONFIG_PROVE_LOCKING void time_hardirqs_on(unsigned long a0, unsigned long a1) { + if (trace_latency_irqs_enabled()) { + int cpu = raw_smp_processor_id(); + trace_latency_irqs(cpu, get_delta(cpu, &ts_irqs)); + } if (!preempt_trace() && irq_trace()) stop_critical_timing(a0, a1); } @@ -446,6 +477,10 @@ void time_hardirqs_off(unsigned long a0, unsigned long a1) { if (!preempt_trace() && irq_trace()) start_critical_timing(a0, a1); + + if (trace_latency_irqs_enabled()) { + mark_timestamp(&ts_irqs); + } } #else /* !CONFIG_PROVE_LOCKING */ @@ -500,9 +535,16 @@ EXPORT_SYMBOL(trace_hardirqs_off_caller); #endif /* CONFIG_PROVE_LOCKING */ #endif /* CONFIG_IRQSOFF_TRACER */ +int count = 0; + #ifdef CONFIG_PREEMPT_TRACER void trace_preempt_on(unsigned long a0, unsigned long a1) { + if (trace_latency_preempt_enabled()) { + int cpu = raw_smp_processor_id(); + trace_latency_preempt(cpu, get_delta(cpu, &ts_preempt)); + } + if (preempt_trace() && !irq_trace()) stop_critical_timing(a0, a1); } @@ -511,6 +553,10 @@ void trace_preempt_off(unsigned long a0, unsigned long a1) { if (preempt_trace() && !irq_trace()) start_critical_timing(a0, a1); + + if (trace_latency_preempt_enabled()) { + mark_timestamp(&ts_preempt); + } } #endif /* CONFIG_PREEMPT_TRACER */