From patchwork Tue Sep 20 13:51:55 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Binoy Jayan X-Patchwork-Id: 76608 Delivered-To: patch@linaro.org Received: by 10.140.106.72 with SMTP id d66csp1500223qgf; Tue, 20 Sep 2016 06:56:04 -0700 (PDT) X-Received: by 10.66.157.103 with SMTP id wl7mr55337316pab.116.1474379764863; Tue, 20 Sep 2016 06:56:04 -0700 (PDT) Return-Path: Received: from vger.kernel.org (vger.kernel.org. [209.132.180.67]) by mx.google.com with ESMTP id o88si6945127pfa.214.2016.09.20.06.56.04; Tue, 20 Sep 2016 06:56:04 -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 S932423AbcITN4B (ORCPT + 27 others); Tue, 20 Sep 2016 09:56:01 -0400 Received: from mail-pa0-f50.google.com ([209.85.220.50]:34917 "EHLO mail-pa0-f50.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754147AbcITNwQ (ORCPT ); Tue, 20 Sep 2016 09:52:16 -0400 Received: by mail-pa0-f50.google.com with SMTP id oz2so7397732pac.2 for ; Tue, 20 Sep 2016 06:52:16 -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=hTMNr8t+apwWsPKfaTeCD+SbeLtHEqpvArteiLAfx0E=; b=Hqm7zFOOWb7nRaLEhaUusnW7jPgBBF00mgw4vvMCa0ez5NKeYzhwKF4DiGKRnX0Pl9 FvKgMQ2Lvj+E0rSkuRQhsrQg4BATploOVIu0nXKz0V0ugVRvD3rxY3nFTbgCcpkeIPj5 Wn51lHjBpWQ1OfYH0xjJbBaaOAbncT0UHGW2g= 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=hTMNr8t+apwWsPKfaTeCD+SbeLtHEqpvArteiLAfx0E=; b=LZeBgI6wfG3Pp200yrly+6gP+8WE85TQwQEoGTVm7loBKuOcFTw2Tyef6lmgr0GtXQ IJ9HYRW1koW+B9M+FF3rNJD8Dry5SZvMgkIWsxvCYlV39c33vuAEuh8d/JyFowGxaGeJ tP5WBRp/nCpcPTjK31ORsa8Eexq3gJy9yo6QybVABcctCiGyIgqGUhbp2vlXtQ2awGli 3VPp9Xp/R8xKgfeUN3Ci0Wg3y/IZy/8PH6wqCQcTiHw2OROyfTdPPElw7d1jcaf420hV tcjuVvic+422iETGGku1q3p1e9c6H7+FVU6Re2q5Y1KTsxRgcoCqxxEw8LBV4s/osLYM lv/g== X-Gm-Message-State: AE9vXwO6LPGZ9yOORkNuoVPV83udu1C4npfU8hdS31ni9BpAzxnO2JJ/yZueN4gE7h/SUl1y X-Received: by 10.66.253.101 with SMTP id zz5mr56124230pac.32.1474379535814; Tue, 20 Sep 2016 06:52:15 -0700 (PDT) Received: from blr-ubuntu-59.ap.qualcomm.com ([202.46.23.61]) by smtp.gmail.com with ESMTPSA id yg10sm17614008pab.8.2016.09.20.06.52.12 (version=TLS1_1 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Tue, 20 Sep 2016 06:52:15 -0700 (PDT) From: Binoy Jayan To: "Steven Rostedt (Red Hat)" , Thomas Gleixner Cc: Ingo Molnar , Daniel Wagner , Arnd Bergmann , linux-kernel@vger.kernel.org, Masami , Mark Brown , Binoy Jayan , Carsten Emde Subject: [RFC PATCH v7 3/5] tracing: Add preemptirqsoff timing events Date: Tue, 20 Sep 2016 19:21:55 +0530 Message-Id: <1474379517-7705-4-git-send-email-binoy.jayan@linaro.org> X-Mailer: git-send-email 1.8.2.1 In-Reply-To: <1474379517-7705-1-git-send-email-binoy.jayan@linaro.org> References: <1474379517-7705-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 Potential sources of latencies are code segments where interrupts, preemption or both are disabled (aka critical sections). To create histograms of potential sources of latency, the kernel stores the time stamp at the start of a critical section, determines the time elapsed when the end of the section is reached, and increments the frequency counter of that latency value - irrespective of whether any concurrently running process is affected by latency or not. With the tracepoints for irqs off, preempt off and critical timing added at the end of the critical sections, the potential sources of latencies which occur in these sections can be measured in nanoseconds. With the hist triggers in place, the histogram 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 to with the histograms '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 1: IRQSOFF latency 2: PREEMPTOFF Latency 3: Critical Timings Enable one or more of the following tracers to capture the associated latencies i.e. irq/preempt/critical timing In '/sys/kernel/debug/tracing' echo irqsoff > current_tracer - irq and critical time latencies echo preemptoff > current_tracer - preempt and critical time latencies echo preemptirqsoff > current_tracer - irq, preempt and critical timing [ - Initial work and idea by Carsten as part of PREEMPT_RT patch series Link: https://git.kernel.org/cgit/linux/kernel/git/rt/linux-stable-rt.git/commit/?h=v3.14-rt-rebase&id=56d50cc34943bbba12b8c5942ee1ae3b29f73acb No code was taken from the RT patch. - RFC using hist infrastructure code by Daniel. - Got it re-written in shape as Daniel suggested to take over author ship. ] Cc: Carsten Emde Cc: Daniel Wagner Signed-off-by: Binoy Jayan --- include/trace/events/latency.h | 62 ++++++++++++++++++++++++++++++++++++++++++ kernel/trace/trace_irqsoff.c | 43 +++++++++++++++++++---------- 2 files changed, 91 insertions(+), 14 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 diff --git a/include/trace/events/latency.h b/include/trace/events/latency.h new file mode 100644 index 0000000..66442d5 --- /dev/null +++ b/include/trace/events/latency.h @@ -0,0 +1,62 @@ +#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_NONE, + 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, u64 latency), + + TP_ARGS(ltype, latency), + + TP_STRUCT__entry( + __field(int, ltype) + __field(u64, 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) +); + +/** + * latency_preemptirqsoff - called when a cpu exits state of preemption / irq + * @ltype: type of the critical section. Refer 'show_ltype' + * @latency: latency in nano seconds + */ +DEFINE_EVENT(latency_template, latency_preemptirqsoff, + TP_PROTO(int ltype, u64 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..4f7442d 100644 --- a/kernel/trace/trace_irqsoff.c +++ b/kernel/trace/trace_irqsoff.c @@ -13,9 +13,14 @@ #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; @@ -298,11 +303,18 @@ static bool report_latency(struct trace_array *tr, cycle_t delta) return true; } +static inline void latency_preemptirqsoff_timing(enum latency_type type, + cycle_t delta) +{ + trace_latency_preemptirqsoff(type, (u64) delta); +} + static void check_critical_timing(struct trace_array *tr, struct trace_array_cpu *data, unsigned long parent_ip, - int cpu) + int cpu, + enum latency_type ltype) { cycle_t T0, T1, delta; unsigned long flags; @@ -312,6 +324,7 @@ check_critical_timing(struct trace_array *tr, T1 = ftrace_now(cpu); delta = T1-T0; + latency_preemptirqsoff_timing(ltype, delta); local_save_flags(flags); pc = preempt_count(); @@ -351,7 +364,8 @@ out: } static inline void -start_critical_timing(unsigned long ip, unsigned long parent_ip) +start_critical_timing(unsigned long ip, unsigned long parent_ip, + enum latency_type ltype) { int cpu; struct trace_array *tr = irqsoff_trace; @@ -387,7 +401,8 @@ start_critical_timing(unsigned long ip, unsigned long parent_ip) } static inline void -stop_critical_timing(unsigned long ip, unsigned long parent_ip) +stop_critical_timing(unsigned long ip, unsigned long parent_ip, + enum latency_type ltype) { int cpu; struct trace_array *tr = irqsoff_trace; @@ -414,7 +429,7 @@ stop_critical_timing(unsigned long ip, unsigned long parent_ip) local_save_flags(flags); __trace_function(tr, ip, parent_ip, flags, preempt_count()); - check_critical_timing(tr, data, parent_ip ? : ip, cpu); + check_critical_timing(tr, data, parent_ip ? : ip, cpu, ltype); data->critical_start = 0; atomic_dec(&data->disabled); } @@ -423,14 +438,14 @@ stop_critical_timing(unsigned long ip, unsigned long parent_ip) void start_critical_timings(void) { if (preempt_trace() || irq_trace()) - start_critical_timing(CALLER_ADDR0, CALLER_ADDR1); + start_critical_timing(CALLER_ADDR0, CALLER_ADDR1, LT_CRITTIME); } EXPORT_SYMBOL_GPL(start_critical_timings); void stop_critical_timings(void) { if (preempt_trace() || irq_trace()) - stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1); + stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1, LT_CRITTIME); } EXPORT_SYMBOL_GPL(stop_critical_timings); @@ -439,13 +454,13 @@ EXPORT_SYMBOL_GPL(stop_critical_timings); void time_hardirqs_on(unsigned long a0, unsigned long a1) { if (!preempt_trace() && irq_trace()) - stop_critical_timing(a0, a1); + stop_critical_timing(a0, a1, LT_IRQ); } void time_hardirqs_off(unsigned long a0, unsigned long a1) { if (!preempt_trace() && irq_trace()) - start_critical_timing(a0, a1); + start_critical_timing(a0, a1, LT_IRQ); } #else /* !CONFIG_PROVE_LOCKING */ @@ -472,28 +487,28 @@ inline void print_irqtrace_events(struct task_struct *curr) void trace_hardirqs_on(void) { if (!preempt_trace() && irq_trace()) - stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1); + stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1, LT_IRQ); } EXPORT_SYMBOL(trace_hardirqs_on); void trace_hardirqs_off(void) { if (!preempt_trace() && irq_trace()) - start_critical_timing(CALLER_ADDR0, CALLER_ADDR1); + start_critical_timing(CALLER_ADDR0, CALLER_ADDR1, LT_IRQ); } EXPORT_SYMBOL(trace_hardirqs_off); __visible void trace_hardirqs_on_caller(unsigned long caller_addr) { if (!preempt_trace() && irq_trace()) - stop_critical_timing(CALLER_ADDR0, caller_addr); + stop_critical_timing(CALLER_ADDR0, caller_addr, LT_IRQ); } EXPORT_SYMBOL(trace_hardirqs_on_caller); __visible void trace_hardirqs_off_caller(unsigned long caller_addr) { if (!preempt_trace() && irq_trace()) - start_critical_timing(CALLER_ADDR0, caller_addr); + start_critical_timing(CALLER_ADDR0, caller_addr, LT_IRQ); } EXPORT_SYMBOL(trace_hardirqs_off_caller); @@ -504,13 +519,13 @@ EXPORT_SYMBOL(trace_hardirqs_off_caller); void trace_preempt_on(unsigned long a0, unsigned long a1) { if (preempt_trace() && !irq_trace()) - stop_critical_timing(a0, a1); + stop_critical_timing(a0, a1, LT_PREEMPT); } void trace_preempt_off(unsigned long a0, unsigned long a1) { if (preempt_trace() && !irq_trace()) - start_critical_timing(a0, a1); + start_critical_timing(a0, a1, LT_PREEMPT); } #endif /* CONFIG_PREEMPT_TRACER */