From patchwork Tue Sep 20 13:51:57 2016 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Binoy Jayan X-Patchwork-Id: 76607 Delivered-To: patch@linaro.org Received: by 10.140.106.72 with SMTP id d66csp1498688qgf; Tue, 20 Sep 2016 06:52:54 -0700 (PDT) X-Received: by 10.98.148.2 with SMTP id m2mr24130792pfe.129.1474379574403; Tue, 20 Sep 2016 06:52:54 -0700 (PDT) Return-Path: Received: from vger.kernel.org (vger.kernel.org. [209.132.180.67]) by mx.google.com with ESMTP id q7si35164251pax.43.2016.09.20.06.52.54; Tue, 20 Sep 2016 06:52:54 -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 S1755024AbcITNwc (ORCPT + 27 others); Tue, 20 Sep 2016 09:52:32 -0400 Received: from mail-pf0-f181.google.com ([209.85.192.181]:33904 "EHLO mail-pf0-f181.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754998AbcITNw2 (ORCPT ); Tue, 20 Sep 2016 09:52:28 -0400 Received: by mail-pf0-f181.google.com with SMTP id p64so7732698pfb.1 for ; Tue, 20 Sep 2016 06:52:28 -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=rdlHvy/q6qO9gUK8aQnZJXjptw0Jybs5MKKWfohEhuo=; b=WcqxavHOwvPwEFFiiG1x2YBb8ZBKt/Li0IUIFSZ0aJnRPuOwc61+7BUR6mX+GIfIEI QzR+HfrCjNHLewX1q7cTfYdW1vi74ay5PpVVDQU53eMDoMkxTv7280LkpnywSztnWD7T 4j1sY/LcfQMxBJE2n1eymsjSY9CMgPvCfHqSA= 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=rdlHvy/q6qO9gUK8aQnZJXjptw0Jybs5MKKWfohEhuo=; b=bxrdEyIgzdduV7nQQVEHEaEbY3B56VNBGB1yNg3RT5z/pkW4uT9dDXgeaecc9bdFZo MkJsHcFE2EhR4ilGLL1Pb6F+s7JOFkQcndcrqLUrLr8EOAZbqFmTK8IQNNm3bFKiSidd utiWIS79SnDNg8S6sXJQiWt6Cau2s7o9XpiRAL/uqBf1etgpBDVkbMw9KYw2dtCIu99q wRcQsectFvgejrhx3LdGdwPtR4nVvGEZ1Gcv2aTKjaCDS2bOalThImmb+DkxUKgbGkxw pxYDF+JHDNV2jcRPo0m+MIYit53Lt9vF1FXlKLmq7pS+11oyG9whu7E55iVruhFnDHr1 Gjug== X-Gm-Message-State: AE9vXwMIFxDxULH5iqAv/YXY5KqItVrBvyfNN2QAdfOoknPQCp2/JkEQca3QGaVUhy6tyCWa X-Received: by 10.98.38.4 with SMTP id m4mr56100031pfm.47.1474379543097; Tue, 20 Sep 2016 06:52:23 -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.19 (version=TLS1_1 cipher=ECDHE-RSA-AES128-SHA bits=128/128); Tue, 20 Sep 2016 06:52:22 -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 5/5] tracing: wakeup latency events and histograms Date: Tue, 20 Sep 2016 19:21:57 +0530 Message-Id: <1474379517-7705-6-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 These latencies usually occurs during the wakeup of a process. To determine this latency, the kernel stores the time stamp when a process is scheduled to be woken up, 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 hrtimers are recorded in the same histogram. The missed hrtimer offsets and the wakeup latency together contribute to the total latency. With the histogram triggers in place, the plots may be generated, with per-cpu breakdown of events captured and the latency measured in nanoseconds. The following histogram triggers may be used: 'hist:key=cpu,ccomm:val=wakeup_lat,total_lat:sort=cpu' 'hist:key=cpu,ccomm:val=timeroffset,total_lat:sort=cpu' 'hist:key=cpu,ccomm:val=total_lat:sort=cpu' 'hist:key=ccomm:val=total_lat if cpu==0' Enable the tracer 'wakeup' or 'wakeup_rt' to capture wakeup latencies of the respective processes. In '/sys/kernel/debug/tracing' echo wakeup > current_tracer [ Initial work and idea by Carsten Link: https://git.kernel.org/cgit/linux/kernel/git/rt/linux-stable-rt.git/commit/?h=v3.14-rt-rebase&id=56d50cc34943bbba12b8c5942ee1ae3b29f73acb ] Cc: Carsten Emde Signed-off-by: Binoy Jayan --- include/linux/sched.h | 3 +++ include/trace/events/sched.h | 34 ++++++++++++++++++++++++++++++++++ kernel/trace/Kconfig | 10 ++++++++++ kernel/trace/trace_sched_wakeup.c | 35 ++++++++++++++++++++++++++++++++--- 4 files changed, 79 insertions(+), 3 deletions(-) -- The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum, a Linux Foundation Collaborative Project diff --git a/include/linux/sched.h b/include/linux/sched.h index 7bf67f8..82f3b62 100644 --- a/include/linux/sched.h +++ b/include/linux/sched.h @@ -1894,6 +1894,9 @@ struct task_struct { #ifdef CONFIG_TRACE_DELAYED_TIMER_OFFSETS long timer_offset; #endif /* CONFIG_TRACE_DELAYED_TIMER_OFFSETS */ +#ifdef CONFIG_TRACE_EVENTS_WAKEUP_LATENCY + u64 wakeup_timestamp_start; +#endif #ifdef CONFIG_KCOV /* Coverage collection mode enabled for this task (0 if disabled). */ enum kcov_mode kcov_mode; diff --git a/include/trace/events/sched.h b/include/trace/events/sched.h index 9b90c57..c8b81d0 100644 --- a/include/trace/events/sched.h +++ b/include/trace/events/sched.h @@ -562,6 +562,40 @@ TRACE_EVENT(sched_wake_idle_without_ipi, TP_printk("cpu=%d", __entry->cpu) ); + +#ifdef CONFIG_TRACE_EVENTS_WAKEUP_LATENCY +/** + * latency_wakeup - Called when process is woken up + * @next: task to be woken up + * @wakeup_lat: process wakeup latency in nano seconds + */ +TRACE_EVENT(latency_wakeup, + + TP_PROTO(struct task_struct *next, u64 wakeup_latency), + TP_ARGS(next, wakeup_latency), + + TP_STRUCT__entry( + __array(char, ccomm, TASK_COMM_LEN) + __field(int, cprio) + __field(unsigned long, wakeup_lat) + __field(unsigned long, timeroffset) + __field(unsigned long, total_lat) + ), + + TP_fast_assign( + memcpy(__entry->ccomm, next->comm, TASK_COMM_LEN); + __entry->cprio = next->prio; + __entry->wakeup_lat = wakeup_latency; + __entry->timeroffset = next->timer_offset; + __entry->total_lat = wakeup_latency + next->timer_offset; + ), + + TP_printk("curr=%s[%d] wakeup_lat=%lu timeroffset=%ld total_lat=%lu", + __entry->ccomm, __entry->cprio, __entry->wakeup_lat, + __entry->timeroffset, __entry->total_lat) +); +#endif + #endif /* _TRACE_SCHED_H */ /* This part must be outside protection */ diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig index f4b86e8..20cf135 100644 --- a/kernel/trace/Kconfig +++ b/kernel/trace/Kconfig @@ -634,6 +634,16 @@ config RING_BUFFER_STARTUP_TEST If unsure, say N +config TRACE_EVENTS_WAKEUP_LATENCY + bool "Trace wakeup latency events" + depends on TRACE_DELAYED_TIMER_OFFSETS + depends on SCHED_TRACER + help + Generate the total wakeup latency of a process. It includes the + wakeup latency and the timer offset latency. Wakeup latency is the + difference in the time when a process is scheduled to be woken up + and when it is actually woken up. It depends on the wakeup tracer. + config TRACE_ENUM_MAP_FILE bool "Show enum mappings for trace events" depends on TRACING diff --git a/kernel/trace/trace_sched_wakeup.c b/kernel/trace/trace_sched_wakeup.c index 9d4399b..ec9e5a8 100644 --- a/kernel/trace/trace_sched_wakeup.c +++ b/kernel/trace/trace_sched_wakeup.c @@ -423,6 +423,29 @@ tracing_sched_wakeup_trace(struct trace_array *tr, trace_buffer_unlock_commit(tr, buffer, event, flags, pc); } +#ifdef CONFIG_TRACE_EVENTS_WAKEUP_LATENCY +static inline void latency_wakeup_start(struct task_struct *task, u64 ts) +{ + task->wakeup_timestamp_start = ts; +} + +static inline void latency_wakeup_stop(struct task_struct *next, u64 ts) +{ + if (next->wakeup_timestamp_start != 0) { + trace_latency_wakeup(next, ts - next->wakeup_timestamp_start); + next->wakeup_timestamp_start = 0; + } +} +#else +static inline void latency_wakeup_start(struct task_struct *task, u64 ts) +{ +} + +static inline void latency_wakeup_stop(struct task_struct *next, u64 ts) +{ +} +#endif + static void notrace probe_wakeup_sched_switch(void *ignore, bool preempt, struct task_struct *prev, struct task_struct *next) @@ -436,6 +459,10 @@ probe_wakeup_sched_switch(void *ignore, bool preempt, tracing_record_cmdline(prev); + cpu = raw_smp_processor_id(); + T1 = ftrace_now(cpu); + latency_wakeup_stop(next, (u64) T1); + if (unlikely(!tracer_enabled)) return; @@ -454,7 +481,6 @@ probe_wakeup_sched_switch(void *ignore, bool preempt, pc = preempt_count(); /* disable local data, not wakeup_cpu data */ - cpu = raw_smp_processor_id(); disabled = atomic_inc_return(&per_cpu_ptr(wakeup_trace->trace_buffer.data, cpu)->disabled); if (likely(disabled != 1)) goto out; @@ -473,7 +499,6 @@ probe_wakeup_sched_switch(void *ignore, bool preempt, tracing_sched_switch_trace(wakeup_trace, prev, next, flags, pc); T0 = data->preempt_timestamp; - T1 = ftrace_now(cpu); delta = T1-T0; if (!report_latency(wakeup_trace, delta)) @@ -525,6 +550,10 @@ probe_wakeup(void *ignore, struct task_struct *p) unsigned long flags; long disabled; int pc; + cycle_t T0; + + T0 = ftrace_now(cpu); + latency_wakeup_start(p, (u64) T0); if (likely(!tracer_enabled)) return; @@ -580,7 +609,7 @@ probe_wakeup(void *ignore, struct task_struct *p) local_save_flags(flags); data = per_cpu_ptr(wakeup_trace->trace_buffer.data, wakeup_cpu); - data->preempt_timestamp = ftrace_now(cpu); + data->preempt_timestamp = T0; tracing_sched_wakeup_trace(wakeup_trace, p, current, flags, pc); /*