From mboxrd@z Thu Jan  1 00:00:00 1970
Return-Path: <linux-kernel-owner@vger.kernel.org>
Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand
	id S1753748AbcHRHJv (ORCPT <rfc822;w@1wt.eu>);
	Thu, 18 Aug 2016 03:09:51 -0400
Received: from mail-pf0-f169.google.com ([209.85.192.169]:33854 "EHLO
	mail-pf0-f169.google.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org
	with ESMTP id S1753636AbcHRHJs (ORCPT
	<rfc822;linux-kernel@vger.kernel.org>);
	Thu, 18 Aug 2016 03:09:48 -0400
From: Binoy Jayan <binoy.jayan@linaro.org>
To: Arnd Bergmann <arnd@arndb.de>, linaro-kernel@lists.linaro.org
Cc: Daniel Wagner <daniel.wagner@bmw-carit.de>,
        Carsten Emde <C.Emde@osadl.org>, linux-kernel@vger.kernel.org,
        "Steven Rostedt (Red Hat)" <rostedt@goodmis.org>,
        Binoy Jayan <binoy.jayan@linaro.org>
Subject: [PATCH 3/3] tracing: Histogram for missed timer offsets
Date: Thu, 18 Aug 2016 12:39:26 +0530
Message-Id: <1471504166-27665-4-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
List-ID: <linux-kernel.vger.kernel.org>
X-Mailing-List: linux-kernel@vger.kernel.org

Latencies of missed timer offsets. Generate a histogram of missed
timer offsets in microseconds. This will be a based along with irq
and preemption latencies to calculate the effective process wakeup
latencies.

The following filter(s) may be used

'hist:key=common_pid.execname'
'hist:key=common_pid.execname,cpu:val=toffset,hitcount'

Signed-off-by: Binoy Jayan <binoy.jayan@linaro.org>
---
 include/linux/hrtimer.h        |  1 +
 include/trace/events/latency.h | 31 +++++++++++++++++++++++++++++++
 kernel/time/hrtimer.c          | 27 +++++++++++++++++++++++++++
 3 files changed, 59 insertions(+)

diff --git a/include/linux/hrtimer.h b/include/linux/hrtimer.h
index 5e00f80..19cb76c 100644
--- a/include/linux/hrtimer.h
+++ b/include/linux/hrtimer.h
@@ -104,6 +104,7 @@ struct hrtimer {
 	struct hrtimer_clock_base	*base;
 	u8				state;
 	u8				is_rel;
+	ktime_t				praecox;
 #ifdef CONFIG_TIMER_STATS
 	int				start_pid;
 	void				*start_site;
diff --git a/include/trace/events/latency.h b/include/trace/events/latency.h
index b279e2d..32317a7 100644
--- a/include/trace/events/latency.h
+++ b/include/trace/events/latency.h
@@ -36,6 +36,37 @@ DEFINE_EVENT(latency_template, latency_critical_timings,
 	    TP_PROTO(int cpu, cycles_t latency),
 	    TP_ARGS(cpu, latency));
 
+TRACE_EVENT(latency_hrtimer_interrupt,
+
+	TP_PROTO(int cpu, long long toffset, struct task_struct *curr,
+		struct task_struct *task),
+
+	TP_ARGS(cpu, toffset, curr, task),
+
+	TP_STRUCT__entry(
+		__field(int,		cpu)
+		__field(long long,	toffset)
+		__array(char,		ccomm,	TASK_COMM_LEN)
+		__field(int,		cprio)
+		__array(char,		tcomm,	TASK_COMM_LEN)
+		__field(int,		tprio)
+	),
+
+	TP_fast_assign(
+		__entry->cpu	 = cpu;
+		__entry->toffset = toffset;
+		memcpy(__entry->ccomm, curr->comm, TASK_COMM_LEN);
+		__entry->cprio  = curr->prio;
+		memcpy(__entry->tcomm, task != NULL ? task->comm : "<none>",
+			task != NULL ? TASK_COMM_LEN : 7);
+		__entry->tprio  = task != NULL ? task->prio : -1;
+	),
+
+	TP_printk("cpu=%d toffset=%lld curr=%s[%d] thread=%s[%d]",
+		__entry->cpu, __entry->toffset, __entry->ccomm,
+		__entry->cprio, __entry->tcomm, __entry->tprio)
+);
+
 #endif /* _TRACE_HIST_H */
 
 /* This part must be outside protection */
diff --git a/kernel/time/hrtimer.c b/kernel/time/hrtimer.c
index 9ba7c82..71e6fcb 100644
--- a/kernel/time/hrtimer.c
+++ b/kernel/time/hrtimer.c
@@ -53,9 +53,12 @@
 #include <asm/uaccess.h>
 
 #include <trace/events/timer.h>
+#include <trace/events/latency.h>
 
 #include "tick-internal.h"
 
+static enum hrtimer_restart hrtimer_wakeup(struct hrtimer *timer);
+
 /*
  * The timer bases:
  *
@@ -992,6 +995,15 @@ void hrtimer_start_range_ns(struct hrtimer *timer, ktime_t tim,
 
 	timer_stats_hrtimer_set_start_info(timer);
 
+	if (trace_latency_hrtimer_interrupt_enabled()) {
+		ktime_t now = new_base->get_time();
+
+		if (ktime_to_ns(tim) < ktime_to_ns(now))
+			timer->praecox = now;
+		else
+			timer->praecox = ktime_set(0, 0);
+	}
+
 	leftmost = enqueue_hrtimer(timer, new_base);
 	if (!leftmost)
 		goto unlock;
@@ -1265,6 +1277,19 @@ static void __run_hrtimer(struct hrtimer_cpu_base *cpu_base,
 	cpu_base->running = NULL;
 }
 
+static inline void trace_missed_hrtimer(struct hrtimer *timer, ktime_t basenow)
+{
+	if (trace_latency_hrtimer_interrupt_enabled())
+		trace_latency_hrtimer_interrupt(raw_smp_processor_id(),
+			ktime_to_ns(ktime_sub(ktime_to_ns(timer->praecox) ?
+				timer->praecox : hrtimer_get_expires(timer),
+				basenow)),
+			current,
+			timer->function == hrtimer_wakeup ?
+				container_of(timer, struct hrtimer_sleeper,
+					timer)->task : NULL);
+
+}
 static void __hrtimer_run_queues(struct hrtimer_cpu_base *cpu_base, ktime_t now)
 {
 	struct hrtimer_clock_base *base = cpu_base->clock_base;
@@ -1284,6 +1309,8 @@ static void __hrtimer_run_queues(struct hrtimer_cpu_base *cpu_base, ktime_t now)
 
 			timer = container_of(node, struct hrtimer, node);
 
+			trace_missed_hrtimer(timer, basenow);
+
 			/*
 			 * The immediate goal for using the softexpires is
 			 * minimizing wakeups, not running timers at the
-- 
The Qualcomm Innovation Center, Inc. is a member of the Code Aurora Forum,
a Linux Foundation Collaborative Project