From 44cc7190263e9a833dd4c65e385212ed79063635 Mon Sep 17 00:00:00 2001
From: Carsten Emde <Carsten.Emde@osadl.org>
Date: Mon, 2 Nov 2009 00:59:47 +0100
Subject: [PATCH] ftrace: Add latency histograms of missed timer offsets

commit d2ac742de047029bb44d0f1b7d4b01c35678a19a in tip.

A source of system latencies not yet considered in the histograms
of effective latencies are delayed timer interrupts. Such latencies
are mainly due to disabled interrupts. Recording of effective latencies
allows to continuously monitor a system's real-time capabilities
under real-world conditions.

This patch adds latency histograms of missed timer offsets. If the
timer belongs to a sleeper that is about to wakeup a task and the
latency is higher than previous latencies of such timers, some data
of this task are recorded as well.

Adapted and expanded Documentation/trace/histograms.txt.

Signed-off-by: Carsten Emde <C.Emde@osadl.org>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
Signed-off-by: Paul Gortmaker <paul.gortmaker@windriver.com>
---
 Documentation/trace/histograms.txt |  104 +++++++-----
 include/trace/events/hist.h        |   29 +++-
 init/main.c                        |   13 ++-
 kernel/hrtimer.c                   |   11 ++
 kernel/trace/Kconfig               |   34 ++++-
 kernel/trace/Makefile              |    1 +
 kernel/trace/latency_hist.c        |  317 +++++++++++++++++++++++++-----------
 7 files changed, 370 insertions(+), 139 deletions(-)

diff --git a/Documentation/trace/histograms.txt b/Documentation/trace/histograms.txt
index 3f6070a..2f17967 100644
--- a/Documentation/trace/histograms.txt
+++ b/Documentation/trace/histograms.txt
@@ -26,24 +26,41 @@ 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 this latency or not.
 - Configuration items (in the Kernel hacking/Tracers submenu)
-  CONFIG_INTERRUPT_OFF_LATENCY
-  CONFIG_PREEMPT_OFF_LATENCY
+  CONFIG_INTERRUPT_OFF_HIST
+  CONFIG_PREEMPT_OFF_HIST
 
 
 * Effective latencies
-
-Effective latencies are actually occuring during wakeup of a process. To
-determine effective latencies, 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 considerably longer,
-since
-i) interrupts may be disabled preventing the scheduler from initiating
-the wakeup mechanism, and
+There are two types of effective latencies, wakeup latencies and missed
+timer latencies
+
+* Wakeup latencies
+Wakeup latencies may occur during wakeup of a process. To determine
+wakeup latencies, 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 considerably longer, since
+i) interrupts may be disabled preventing the timer from waking up a process
+in time
 ii) the process may be interrupted after control is passed over to it
 but before user space execution takes place.
+If a particular wakeup latency is highest so far, details of the task
+that is suffering from this latency are stored as well (see below).
+- Configuration item (in the Kernel hacking/Tracers submenu)
+  CONFIG_WAKEUP_LATENCY_HIST
+
+* Missed timer latencies
+
+Missed timer latencies occur when a timer interrupt is serviced later
+than it should. This is mainly due to disabled interrupts. To determine
+the missed timer latency, the expected and the real execution time of a
+timer are compared. If the former precedes the latter, the difference is
+entered into the missed timer offsets histogram. If the timer is
+responsible to wakeup a sleeping process and the latency is highest so
+far among previous wakeup timers, details of the related task are stored
+as well (see below).
 - Configuration item (in the Kernel hacking/Tracers submenu)
-  CONFIG_WAKEUP_LATENCY
+  CONFIG_MISSED_TIMER_OFFSETS_HIST
 
 
 * Usage
@@ -59,19 +76,23 @@ from shell command line level, or add
 nodev	/sys			sysfs	defaults	0 0
 nodev	/sys/kernel/debug	debugfs	defaults	0 0
 
-to the file /etc/fstab. All latency histogram related files are
+to the file /etc/fstab in order to implicitly mount the debug file
+system at every reboot. All latency histogram related files are
 available in the directory /sys/kernel/debug/tracing/latency_hist. A
 particular histogram type is enabled by writing non-zero to the related
 variable in the /sys/kernel/debug/tracing/latency_hist/enable directory.
-Select "preemptirqsoff" for the histograms of potential sources of
-latencies and "wakeup" for histograms of effective latencies. The
-histogram data - one per CPU - are available in the files
+Select "preemptirqsoff" for histograms of potential sources of
+latencies, "wakeup" for histograms of wakeup latencies and
+"missed_timer_offsets" for histograms of missed timer offsets,
+respectively.
 
+The histogram data - one per CPU - are available in the files
 /sys/kernel/debug/tracing/latency_hist/preemptoff/CPUx
 /sys/kernel/debug/tracing/latency_hist/irqsoff/CPUx
 /sys/kernel/debug/tracing/latency_hist/preemptirqsoff/CPUx
 /sys/kernel/debug/tracing/latency_hist/wakeup/CPUx.
 /sys/kernel/debug/tracing/latency_hist/wakeup/sharedprio/CPUx.
+/sys/kernel/debug/tracing/latency_hist/missed_timer_offsets/CPUx.
 
 The histograms are reset by writing non-zero to the file "reset" in a
 particular latency directory. To reset all latency data, use
@@ -94,19 +115,19 @@ fi
 * Data format
 
 Latency data are stored with a resolution of one microsecond. The
-maximum latency is 10,240 microseconds. The data are only valid, if the
-overflow register is empty. Every output line contains the latency in
-microseconds in the first row and the number of samples in the second
-row. To display only lines with a positive latency count, use, for
-example,
+maximum latency is 10,240 microseconds. Every output line contains the
+latency in microseconds in the first row and the number of samples in
+the second row. To display only lines with a positive latency count,
+use, for example,
 
 grep -v " 0$" /sys/kernel/debug/tracing/latency_hist/preemptoff/CPU0
 
-#Minimum latency: 0 microseconds.
-#Average latency: 0 microseconds.
-#Maximum latency: 25 microseconds.
+#Minimum latency: 0 microseconds
+#Average latency: 0 microseconds
+#Maximum latency: 25 microseconds
 #Total samples: 3104770694
-#There are 0 samples greater or equal than 10240 microseconds
+#There are 0 samples lower than 0 microseconds.
+#There are 0 samples greater or equal than 10240 microseconds.
 #usecs	         samples
     0	      2984486876
     1	        49843506
@@ -140,11 +161,16 @@ grep -v " 0$" /sys/kernel/debug/tracing/latency_hist/preemptoff/CPU0
 Two different algorithms are used to determine the wakeup latency of a
 process. One of them only considers processes that exclusively use the
 highest priority of the system, the other one records the wakeup latency
-of a process even if it shares the highest systemm latency with other
-processes. The former is used to improve hardware and system software;
-the related histograms are located it the wakeup subdirectory. The
-latter is used to optimize the priority design of a given system; the
-related histograms are located in the wakeup/sharedprio subdirectory.
+of a process even if it shares the highest system latency with other
+processes. The former is used to determine the worst-case latency of a
+system; if higher than expected, the hardware and or system software
+(e.g. the Linux kernel) may need to be debugged and fixed. The latter
+reflects the priority design of a given system; if higher than expected,
+the system design may need to be re-evaluated - the hardware
+manufacturer or the kernel developers must not be blamed for such
+latencies. The exclusive-priority wakeup latency histograms are located
+in the "wakeup" subdirectory, the shared-priority histograms are located
+in the "wakeup/sharedprio" subdirectory.
 
 
 * Wakeup latency of a selected process
@@ -157,20 +183,18 @@ PID of the requested process to
 PIDs are not considered, if this variable is set to 0.
 
 
-* Details of the process with the highest wakeup latency so far
+* Details of processes with the highest wakeup or missed timer
+latency so far
 
-Selected data of the process that suffered from the highest wakeup
-latency that occurred in a particular CPU are available in the files
+Selected data of processes that suffered from the highest wakeup or
+missed timer latency that occurred on a particular CPU are available in
+the files
 
 /sys/kernel/debug/tracing/latency_hist/wakeup/max_latency-CPUx
-
-and
-
-/sys/kernel/debug/tracing/latency_hist/wakeup/sharedprio/max_latency-CPUx,
-
-respectively.
+/sys/kernel/debug/tracing/latency_hist/wakeup/sharedprio/max_latency-CPUx
+/sys/kernel/debug/tracing/latency_hist/missed_timer_offsets/max_latency-CPUx
 
 The format of the data is
 <PID> <Priority> <Latency> <Command>
 
-These data are also reset when the related wakeup histograms are reset.
+These data are also reset when the related histograms are reset.
diff --git a/include/trace/events/hist.h b/include/trace/events/hist.h
index 73b0454..2dc4c70 100644
--- a/include/trace/events/hist.h
+++ b/include/trace/events/hist.h
@@ -17,8 +17,8 @@ TRACE_EVENT(preemptirqsoff_hist,
 	TP_ARGS(reason, starthist),
 
 	TP_STRUCT__entry(
-		__field(	int,	reason	)
-		__field(	int,	starthist	)
+		__field(int,	reason	)
+		__field(int,	starthist	)
 	),
 
 	TP_fast_assign(
@@ -31,6 +31,31 @@ TRACE_EVENT(preemptirqsoff_hist,
 );
 #endif
 
+#ifndef CONFIG_MISSED_TIMER_OFFSETS_HIST
+#define trace_hrtimer_interrupt(a,b,c)
+#else
+TRACE_EVENT(hrtimer_interrupt,
+
+	TP_PROTO(int cpu, long long offset, struct task_struct *task),
+
+	TP_ARGS(cpu, offset, task),
+
+	TP_STRUCT__entry(
+		__array(char,		comm,	TASK_COMM_LEN)
+		__field(int,		cpu	)
+		__field(long long,	offset	)
+	),
+
+	TP_fast_assign(
+		strncpy(__entry->comm, task != NULL ? task->comm : "", TASK_COMM_LEN);
+		__entry->cpu	= cpu;
+		__entry->offset	= offset;
+	),
+
+	TP_printk("cpu=%d offset=%lld thread=%s", __entry->cpu, __entry->offset, __entry->comm)
+);
+#endif
+
 #endif /* _TRACE_HIST_H */
 
 /* This part must be outside protection */
diff --git a/init/main.c b/init/main.c
index 6859102..36649af 100644
--- a/init/main.c
+++ b/init/main.c
@@ -917,7 +917,15 @@ static int __init kernel_init(void * unused)
 	WARN_ON(irqs_disabled());
 #endif
 
-#define DEBUG_COUNT (defined(CONFIG_DEBUG_RT_MUTEXES) + defined(CONFIG_IRQSOFF_TRACER) + defined(CONFIG_PREEMPT_TRACER) + defined(CONFIG_STACK_TRACER) + defined(CONFIG_INTERRUPT_OFF_HIST) + defined(CONFIG_PREEMPT_OFF_HIST) + defined(CONFIG_WAKEUP_LATENCY_HIST) + defined(CONFIG_DEBUG_SLAB) + defined(CONFIG_DEBUG_PAGEALLOC) + defined(CONFIG_LOCKDEP) + (defined(CONFIG_FTRACE) - defined(CONFIG_FTRACE_MCOUNT_RECORD)))
+#define DEBUG_COUNT (defined(CONFIG_DEBUG_RT_MUTEXES) + \
+	defined(CONFIG_IRQSOFF_TRACER) + defined(CONFIG_PREEMPT_TRACER) + \
+	defined(CONFIG_STACK_TRACER) + defined(CONFIG_INTERRUPT_OFF_HIST) + \
+	defined(CONFIG_PREEMPT_OFF_HIST) + \
+	defined(CONFIG_WAKEUP_LATENCY_HIST) + \
+	defined(CONFIG_MISSED_TIMER_OFFSETS_HIST) + \
+	defined(CONFIG_DEBUG_SLAB) + defined(CONFIG_DEBUG_PAGEALLOC) + \
+	defined(CONFIG_LOCKDEP) + \
+	(defined(CONFIG_FTRACE) - defined(CONFIG_FTRACE_MCOUNT_RECORD)))
 
 #if DEBUG_COUNT > 0
 	printk(KERN_ERR "*****************************************************************************\n");
@@ -949,6 +957,9 @@ static int __init kernel_init(void * unused)
 #ifdef CONFIG_WAKEUP_LATENCY_HIST
 	printk(KERN_ERR "*        CONFIG_WAKEUP_LATENCY_HIST                                         *\n");
 #endif
+#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST
+	printk(KERN_ERR "*        CONFIG_MISSED_TIMER_OFFSETS_HIST                                   *\n");
+#endif
 #ifdef CONFIG_DEBUG_SLAB
 	printk(KERN_ERR "*        CONFIG_DEBUG_SLAB                                                  *\n");
 #endif
diff --git a/kernel/hrtimer.c b/kernel/hrtimer.c
index 0499bd3..24607d6 100644
--- a/kernel/hrtimer.c
+++ b/kernel/hrtimer.c
@@ -49,6 +49,7 @@
 #include <asm/uaccess.h>
 
 #include <trace/events/timer.h>
+#include <trace/events/hist.h>
 
 /*
  * The timer bases:
@@ -1424,6 +1425,8 @@ static inline int hrtimer_rt_defer(struct hrtimer *timer) { return 0; }
 
 #ifdef CONFIG_HIGH_RES_TIMERS
 
+static enum hrtimer_restart hrtimer_wakeup(struct hrtimer *timer);
+
 /*
  * High resolution timer interrupt
  * Called with interrupts disabled
@@ -1466,6 +1469,14 @@ retry:
 
 			timer = rb_entry(node, struct hrtimer, node);
 
+			trace_hrtimer_interrupt(raw_smp_processor_id(),
+			    ktime_to_ns(ktime_sub(
+				hrtimer_get_expires(timer), basenow)),
+			    current,
+			    timer->function == hrtimer_wakeup ?
+			    container_of(timer, struct hrtimer_sleeper,
+				timer)->task : NULL);
+
 			/*
 			 * The immediate goal for using the softexpires is
 			 * minimizing wakeups, not running timers at the
diff --git a/kernel/trace/Kconfig b/kernel/trace/Kconfig
index 7c21937..e966f40 100644
--- a/kernel/trace/Kconfig
+++ b/kernel/trace/Kconfig
@@ -187,7 +187,10 @@ config INTERRUPT_OFF_HIST
 
 	  If PREEMPT_OFF_HIST is also selected, additional histograms (one
 	  per cpu) are generated that accumulate the duration of time periods
-	  when both interrupts and preemption are disabled.
+	  when both interrupts and preemption are disabled. The histogram data
+	  will be located in the debug file system at
+
+	      /sys/kernel/debug/tracing/latency_hist/irqsoff
 
 config PREEMPT_TRACER
 	bool "Preemption-off Latency Tracer"
@@ -224,7 +227,10 @@ config PREEMPT_OFF_HIST
 
 	  If INTERRUPT_OFF_HIST is also selected, additional histograms (one
 	  per cpu) are generated that accumulate the duration of time periods
-	  when both interrupts and preemption are disabled.
+	  when both interrupts and preemption are disabled. The histogram data
+	  will be located in the debug file system at
+
+	      /sys/kernel/debug/tracing/latency_hist/preemptoff
 
 config SCHED_TRACER
 	bool "Scheduling Latency Tracer"
@@ -251,7 +257,29 @@ config WAKEUP_LATENCY_HIST
 	  another one to determine the latency of processes that share the
 	  highest system priority with other processes. The former is used to
 	  improve hardware and system software, the latter to optimize the
-	  priority design of a given system.
+	  priority design of a given system. The histogram data will be
+	  located in the debug file system at
+
+	      /sys/kernel/debug/tracing/latency_hist/wakeup
+
+	  and
+
+	      /sys/kernel/debug/tracing/latency_hist/wakeup/sharedprio
+
+config MISSED_TIMER_OFFSETS_HIST
+	depends on GENERIC_TIME
+	select GENERIC_TRACER
+	bool "Missed timer offsets histogram"
+	help
+	  Generate a histogram of missed timer offsets in microseconds. The
+	  histograms are disabled by default. To enable them, write a non-zero
+	  number to
+
+	      /sys/kernel/debug/tracing/latency_hist/enable/missed_timer_offsets
+
+	  The histogram data will be located in the debug file system at
+
+	      /sys/kernel/debug/tracing/latency_hist/missed_timer_offsets
 
 config SYSPROF_TRACER
 	bool "Sysprof Tracer"
diff --git a/kernel/trace/Makefile b/kernel/trace/Makefile
index 0603f2e..1989265 100644
--- a/kernel/trace/Makefile
+++ b/kernel/trace/Makefile
@@ -38,6 +38,7 @@ obj-$(CONFIG_SCHED_TRACER) += trace_sched_wakeup.o
 obj-$(CONFIG_INTERRUPT_OFF_HIST) += latency_hist.o
 obj-$(CONFIG_PREEMPT_OFF_HIST) += latency_hist.o
 obj-$(CONFIG_WAKEUP_LATENCY_HIST) += latency_hist.o
+obj-$(CONFIG_MISSED_TIMER_OFFSETS_HIST) += latency_hist.o
 obj-$(CONFIG_NOP_TRACER) += trace_nop.o
 obj-$(CONFIG_STACK_TRACER) += trace_stack.o
 obj-$(CONFIG_MMIOTRACE) += trace_mmiotrace.o
diff --git a/kernel/trace/latency_hist.c b/kernel/trace/latency_hist.c
index 6fe972e..83d8d2f 100644
--- a/kernel/trace/latency_hist.c
+++ b/kernel/trace/latency_hist.c
@@ -35,6 +35,7 @@ enum {
 	PREEMPTIRQSOFF_LATENCY,
 	WAKEUP_LATENCY,
 	WAKEUP_LATENCY_SHAREDPRIO,
+	MISSED_TIMER_OFFSETS,
 	MAX_LATENCY_TYPE,
 };
 
@@ -42,9 +43,11 @@ enum {
 
 struct hist_data {
 	atomic_t hist_mode; /* 0 log, 1 don't log */
+	long offset; /* set it to MAX_ENTRY_NUM/2 for a bipolar scale */
 	unsigned long min_lat;
 	unsigned long max_lat;
-	unsigned long long beyond_hist_bound_samples;
+	unsigned long long below_hist_bound_samples;
+	unsigned long long above_hist_bound_samples;
 	unsigned long long accumulate_lat;
 	unsigned long long total_samples;
 	unsigned long long hist_array[MAX_ENTRY_NUM];
@@ -60,16 +63,22 @@ static char *latency_hist_dir_root = "latency_hist";
 #ifdef CONFIG_INTERRUPT_OFF_HIST
 static DEFINE_PER_CPU(struct hist_data, irqsoff_hist);
 static char *irqsoff_hist_dir = "irqsoff";
+static DEFINE_PER_CPU(cycles_t, hist_irqsoff_start);
+static DEFINE_PER_CPU(int, hist_irqsoff_counting);
 #endif
 
 #ifdef CONFIG_PREEMPT_OFF_HIST
 static DEFINE_PER_CPU(struct hist_data, preemptoff_hist);
 static char *preemptoff_hist_dir = "preemptoff";
+static DEFINE_PER_CPU(cycles_t, hist_preemptoff_start);
+static DEFINE_PER_CPU(int, hist_preemptoff_counting);
 #endif
 
 #if defined(CONFIG_PREEMPT_OFF_HIST) && defined(CONFIG_INTERRUPT_OFF_HIST)
 static DEFINE_PER_CPU(struct hist_data, preemptirqsoff_hist);
 static char *preemptirqsoff_hist_dir = "preemptirqsoff";
+static DEFINE_PER_CPU(cycles_t, hist_preemptirqsoff_start);
+static DEFINE_PER_CPU(int, hist_preemptirqsoff_counting);
 #endif
 
 #if defined(CONFIG_PREEMPT_OFF_HIST) || defined(CONFIG_INTERRUPT_OFF_HIST)
@@ -80,6 +89,16 @@ static struct enable_data preemptirqsoff_enabled_data = {
 };
 #endif
 
+#if defined(CONFIG_WAKEUP_LATENCY_HIST) || \
+    defined(CONFIG_MISSED_TIMER_OFFSETS_HIST)
+struct maxlatproc_data {
+	char comm[FIELD_SIZEOF(struct task_struct, comm)];
+	unsigned int pid;
+	unsigned int prio;
+	unsigned long latency;
+};
+#endif
+
 #ifdef CONFIG_WAKEUP_LATENCY_HIST
 static DEFINE_PER_CPU(struct hist_data, wakeup_latency_hist);
 static DEFINE_PER_CPU(struct hist_data, wakeup_latency_hist_sharedprio);
@@ -93,13 +112,6 @@ static struct enable_data wakeup_latency_enabled_data = {
 	.latency_type = WAKEUP_LATENCY,
 	.enabled = 0,
 };
-static struct task_struct *ts;
-struct maxlatproc_data {
-	char comm[sizeof(ts->comm)];
-	unsigned int pid;
-	unsigned int prio;
-	unsigned long latency;
-};
 static DEFINE_PER_CPU(struct maxlatproc_data, wakeup_maxlatproc);
 static DEFINE_PER_CPU(struct maxlatproc_data, wakeup_maxlatproc_sharedprio);
 static struct task_struct *wakeup_task;
@@ -107,11 +119,25 @@ static int wakeup_sharedprio;
 static int wakeup_pid;
 #endif
 
+#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST
+static DEFINE_PER_CPU(struct hist_data, missed_timer_offsets);
+static char *missed_timer_offsets_dir = "missed_timer_offsets";
+static notrace void probe_hrtimer_interrupt(int cpu,
+    long long offset, struct task_struct *task);
+static struct enable_data missed_timer_offsets_enabled_data = {
+	.latency_type = MISSED_TIMER_OFFSETS,
+	.enabled = 0,
+};
+static DEFINE_PER_CPU(struct maxlatproc_data,
+    missed_timer_offsets_maxlatproc);
+#endif
+
 void notrace latency_hist(int latency_type, int cpu, unsigned long latency,
 			  struct task_struct *p)
 {
 	struct hist_data *my_hist;
-#ifdef CONFIG_WAKEUP_LATENCY_HIST
+#if defined(CONFIG_WAKEUP_LATENCY_HIST) || \
+    defined(CONFIG_MISSED_TIMER_OFFSETS_HIST)
 	struct maxlatproc_data *mp = NULL;
 #endif
 
@@ -125,19 +151,16 @@ void notrace latency_hist(int latency_type, int cpu, unsigned long latency,
 		my_hist = &per_cpu(irqsoff_hist, cpu);
 		break;
 #endif
-
 #ifdef CONFIG_PREEMPT_OFF_HIST
 	case PREEMPTOFF_LATENCY:
 		my_hist = &per_cpu(preemptoff_hist, cpu);
 		break;
 #endif
-
 #if defined(CONFIG_PREEMPT_OFF_HIST) && defined(CONFIG_INTERRUPT_OFF_HIST)
 	case PREEMPTIRQSOFF_LATENCY:
 		my_hist = &per_cpu(preemptirqsoff_hist, cpu);
 		break;
 #endif
-
 #ifdef CONFIG_WAKEUP_LATENCY_HIST
 	case WAKEUP_LATENCY:
 		my_hist = &per_cpu(wakeup_latency_hist, cpu);
@@ -148,6 +171,12 @@ void notrace latency_hist(int latency_type, int cpu, unsigned long latency,
 		mp = &per_cpu(wakeup_maxlatproc_sharedprio, cpu);
 		break;
 #endif
+#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST
+	case MISSED_TIMER_OFFSETS:
+		my_hist = &per_cpu(missed_timer_offsets, cpu);
+		mp = &per_cpu(missed_timer_offsets_maxlatproc, cpu);
+		break;
+#endif
 	default:
 		return;
 	}
@@ -155,15 +184,21 @@ void notrace latency_hist(int latency_type, int cpu, unsigned long latency,
 	if (atomic_read(&my_hist->hist_mode) == 0)
 		return;
 
-	if (latency >= MAX_ENTRY_NUM)
-		my_hist->beyond_hist_bound_samples++;
-	else
+	latency += my_hist->offset;
+
+	if (latency < 0 || latency >= MAX_ENTRY_NUM) {
+		if (latency < 0)
+			my_hist->below_hist_bound_samples++;
+		else
+			my_hist->above_hist_bound_samples++;
+	} else
 		my_hist->hist_array[latency]++;
 
 	if (latency < my_hist->min_lat)
 		my_hist->min_lat = latency;
 	else if (latency > my_hist->max_lat) {
-#ifdef CONFIG_WAKEUP_LATENCY_HIST
+#if defined (CONFIG_WAKEUP_LATENCY_HIST) || \
+    defined(CONFIG_MISSED_TIMER_OFFSETS_HIST)
 		if (latency_type == WAKEUP_LATENCY ||
 		    latency_type == WAKEUP_LATENCY_SHAREDPRIO) {
 			strncpy(mp->comm, p->comm, sizeof(mp->comm));
@@ -174,7 +209,15 @@ void notrace latency_hist(int latency_type, int cpu, unsigned long latency,
 #endif
 		my_hist->max_lat = latency;
 	}
-
+#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST
+	if (latency_type == MISSED_TIMER_OFFSETS && p != NULL &&
+	    latency > mp->latency) {
+		strncpy(mp->comm, p->comm, sizeof(mp->comm));
+		mp->pid = task_pid_nr(p);
+		mp->prio = p->prio;
+		mp->latency = latency;
+	}
+#endif
 	my_hist->total_samples++;
 	my_hist->accumulate_lat += latency;
 	return;
@@ -190,30 +233,42 @@ static void *l_start(struct seq_file *m, loff_t *pos)
 		return NULL;
 
 	if (index == 0) {
-		char avgstr[32];
+		char minstr[32], avgstr[32], maxstr[32];
 
 		atomic_dec(&my_hist->hist_mode);
+
 		if (likely(my_hist->total_samples)) {
 			unsigned long avg = (unsigned long)
 			    div64_u64(my_hist->accumulate_lat,
 			    my_hist->total_samples);
-			sprintf(avgstr, "%lu", avg);
-		} else
-			strcpy(avgstr, "<undef>");
+			snprintf(minstr, sizeof(minstr), "%ld",
+			    (long) my_hist->min_lat - my_hist->offset);
+			snprintf(avgstr, sizeof(avgstr), "%ld",
+			    (long) avg - my_hist->offset);
+			snprintf(maxstr, sizeof(minstr), "%ld",
+			    (long) my_hist->max_lat - my_hist->offset);
+		} else {
+			strcpy(minstr, "<undef>");
+			strcpy(avgstr, minstr);
+			strcpy(maxstr, minstr);
+		}
 
-		seq_printf(m, "#Minimum latency: %lu microseconds.\n"
-			   "#Average latency: %s microseconds.\n"
-			   "#Maximum latency: %lu microseconds.\n"
+		seq_printf(m, "#Minimum latency: %s microseconds\n"
+			   "#Average latency: %s microseconds\n"
+			   "#Maximum latency: %s microseconds\n"
 			   "#Total samples: %llu\n"
+			   "#There are %llu samples lower than %ld"
+			   " microseconds.\n"
 			   "#There are %llu samples greater or equal"
-			   " than %d microseconds\n"
-			   "#usecs\t%16s\n"
-			   , my_hist->min_lat
-			   , avgstr
-			   , my_hist->max_lat
-			   , my_hist->total_samples
-			   , my_hist->beyond_hist_bound_samples
-			   , MAX_ENTRY_NUM, "samples");
+			   " than %ld microseconds.\n"
+			   "#usecs\t%16s\n",
+			   minstr, avgstr, maxstr,
+			   my_hist->total_samples,
+			   my_hist->below_hist_bound_samples,
+			   -my_hist->offset,
+			   my_hist->above_hist_bound_samples,
+			   MAX_ENTRY_NUM - my_hist->offset,
+			   "samples");
 	}
 	if (index >= MAX_ENTRY_NUM)
 		return NULL;
@@ -244,8 +299,15 @@ static int l_show(struct seq_file *m, void *p)
 {
 	int index = *(loff_t *) p;
 	struct hist_data *my_hist = m->private;
+	char *fmt;
+
+	if (my_hist->offset)
+		fmt = "%6d\t%16llu\n";
+	else
+		fmt = "%5d\t%16llu\n";
 
-	seq_printf(m, "%5d\t%16llu\n", index, my_hist->hist_array[index]);
+	seq_printf(m, fmt, index - my_hist->offset,
+	    my_hist->hist_array[index]);
 	return 0;
 }
 
@@ -280,7 +342,8 @@ static void hist_reset(struct hist_data *hist)
 	atomic_dec(&hist->hist_mode);
 
 	memset(hist->hist_array, 0, sizeof(hist->hist_array));
-	hist->beyond_hist_bound_samples = 0ULL;
+	hist->below_hist_bound_samples = 0ULL;
+	hist->above_hist_bound_samples = 0ULL;
 	hist->min_lat = 0xFFFFFFFFUL;
 	hist->max_lat = 0UL;
 	hist->total_samples = 0ULL;
@@ -295,13 +358,13 @@ latency_hist_reset(struct file *file, const char __user *a,
 {
 	int cpu;
 	struct hist_data *hist;
-#ifdef CONFIG_WAKEUP_LATENCY_HIST
+#if defined(CONFIG_WAKEUP_LATENCY_HIST) || \
+    defined(CONFIG_MISSED_TIMER_OFFSETS_HIST)
 	struct maxlatproc_data *mp = NULL;
 #endif
 	int latency_type = (int) file->private_data;
 
 	switch (latency_type) {
-
 #ifdef CONFIG_PREEMPT_OFF_HIST
 	case PREEMPTOFF_LATENCY:
 		for_each_online_cpu(cpu) {
@@ -310,7 +373,6 @@ latency_hist_reset(struct file *file, const char __user *a,
 		}
 		break;
 #endif
-
 #ifdef CONFIG_INTERRUPT_OFF_HIST
 	case IRQSOFF_LATENCY:
 		for_each_online_cpu(cpu) {
@@ -319,7 +381,6 @@ latency_hist_reset(struct file *file, const char __user *a,
 		}
 		break;
 #endif
-
 #if defined(CONFIG_INTERRUPT_OFF_HIST) && defined(CONFIG_PREEMPT_OFF_HIST)
 	case PREEMPTIRQSOFF_LATENCY:
 		for_each_online_cpu(cpu) {
@@ -328,7 +389,6 @@ latency_hist_reset(struct file *file, const char __user *a,
 		}
 		break;
 #endif
-
 #ifdef CONFIG_WAKEUP_LATENCY_HIST
 	case WAKEUP_LATENCY:
 		for_each_online_cpu(cpu) {
@@ -339,7 +399,6 @@ latency_hist_reset(struct file *file, const char __user *a,
 			mp->prio = mp->pid = mp->latency = 0;
 		}
 		break;
-
 	case WAKEUP_LATENCY_SHAREDPRIO:
 		for_each_online_cpu(cpu) {
 			hist = &per_cpu(wakeup_latency_hist_sharedprio, cpu);
@@ -350,6 +409,17 @@ latency_hist_reset(struct file *file, const char __user *a,
 		}
 		break;
 #endif
+#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST
+	case MISSED_TIMER_OFFSETS:
+		for_each_online_cpu(cpu) {
+			hist = &per_cpu(missed_timer_offsets, cpu);
+			hist_reset(hist);
+			mp = &per_cpu(missed_timer_offsets_maxlatproc, cpu);
+			mp->comm[0] = '\0';
+			mp->prio = mp->pid = mp->latency = 0;
+		}
+		break;
+#endif
 	}
 
 	return size;
@@ -388,7 +458,10 @@ latency_hist_pid(struct file *filp, const char __user *ubuf,
 	wakeup_pid = pid;
 	return cnt;
 }
+#endif
 
+#if defined(CONFIG_WAKEUP_LATENCY_HIST) || \
+    defined(CONFIG_MISSED_TIMER_OFFSETS_HIST)
 static ssize_t
 latency_hist_show_maxlatproc(struct file *filp, char __user *ubuf,
 		      size_t cnt, loff_t *ppos)
@@ -405,20 +478,6 @@ latency_hist_show_maxlatproc(struct file *filp, char __user *ubuf,
 
 #endif
 
-#if defined(CONFIG_INTERRUPT_OFF_HIST) || defined(CONFIG_PREEMPT_OFF_HIST)
-#ifdef CONFIG_INTERRUPT_OFF_HIST
-static DEFINE_PER_CPU(cycles_t, hist_irqsoff_start);
-static DEFINE_PER_CPU(int, hist_irqsoff_counting);
-#endif
-#ifdef CONFIG_PREEMPT_OFF_HIST
-static DEFINE_PER_CPU(cycles_t, hist_preemptoff_start);
-static DEFINE_PER_CPU(int, hist_preemptoff_counting);
-#endif
-#if defined(CONFIG_INTERRUPT_OFF_HIST) && defined(CONFIG_PREEMPT_OFF_HIST)
-static DEFINE_PER_CPU(cycles_t, hist_preemptirqsoff_start);
-static DEFINE_PER_CPU(int, hist_preemptirqsoff_counting);
-#endif
-
 static ssize_t
 latency_hist_show_enable(struct file *filp, char __user *ubuf,
 			 size_t cnt, loff_t *ppos)
@@ -457,6 +516,19 @@ latency_hist_enable(struct file *filp, const char __user *ubuf,
 		int ret;
 
 		switch (ed->latency_type) {
+#if defined(CONFIG_INTERRUPT_OFF_HIST) || defined(CONFIG_PREEMPT_OFF_HIST)
+		case PREEMPTIRQSOFF_LATENCY:
+			ret = register_trace_preemptirqsoff_hist(
+			    probe_preemptirqsoff_hist);
+			if (ret) {
+				pr_info("wakeup trace: Couldn't assign "
+				    "probe_preemptirqsoff_hist "
+				    "to trace_preemptirqsoff_hist\n");
+				return ret;
+			}
+			break;
+#endif
+#ifdef CONFIG_WAKEUP_LATENCY_HIST
 		case WAKEUP_LATENCY:
 			ret = register_trace_sched_wakeup(
 			    probe_wakeup_latency_hist_start);
@@ -489,23 +561,49 @@ latency_hist_enable(struct file *filp, const char __user *ubuf,
 				return ret;
 			}
 			break;
-		case PREEMPTIRQSOFF_LATENCY:
-			ret = register_trace_preemptirqsoff_hist(
-			    probe_preemptirqsoff_hist);
+#endif
+#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST
+		case MISSED_TIMER_OFFSETS:
+			ret = register_trace_hrtimer_interrupt(
+			    probe_hrtimer_interrupt);
 			if (ret) {
 				pr_info("wakeup trace: Couldn't assign "
-				    "probe_preemptirqsoff_hist "
-				    "to trace_preemptirqsoff_hist\n");
+				    "probe_hrtimer_interrupt "
+				    "to trace_hrtimer_interrupt\n");
 				return ret;
 			}
 			break;
+#endif
 		default:
 			break;
 		}
 	} else {
-		int cpu;
-
 		switch (ed->latency_type) {
+#if defined(CONFIG_INTERRUPT_OFF_HIST) || defined(CONFIG_PREEMPT_OFF_HIST)
+		case PREEMPTIRQSOFF_LATENCY:
+			{
+				int cpu;
+
+				unregister_trace_preemptirqsoff_hist(
+				    probe_preemptirqsoff_hist);
+				for_each_online_cpu(cpu) {
+#ifdef CONFIG_INTERRUPT_OFF_HIST
+					per_cpu(hist_irqsoff_counting,
+					    cpu) = 0;
+#endif
+#ifdef CONFIG_PREEMPT_OFF_HIST
+					per_cpu(hist_preemptoff_counting,
+					    cpu) = 0;
+#endif
+#if defined(CONFIG_INTERRUPT_OFF_HIST) && defined(CONFIG_PREEMPT_OFF_HIST)
+					per_cpu(hist_preemptirqsoff_counting,
+					    cpu) = 0;
+#endif
+				}
+			}
+			break;
+#endif
+#ifdef CONFIG_WAKEUP_LATEHCY_HIST
 		case WAKEUP_LATENCY:
 			unregister_trace_sched_wakeup(
 			    probe_wakeup_latency_hist_start);
@@ -516,21 +614,13 @@ latency_hist_enable(struct file *filp, const char __user *ubuf,
 			wakeup_task = NULL;
 			wakeup_sharedprio = 0;
 			break;
-		case PREEMPTIRQSOFF_LATENCY:
-			unregister_trace_preemptirqsoff_hist(
-			    probe_preemptirqsoff_hist);
-			for_each_online_cpu(cpu) {
-#ifdef CONFIG_INTERRUPT_OFF_HIST
-				per_cpu(hist_irqsoff_counting, cpu) = 0;
 #endif
-#ifdef CONFIG_PREEMPT_OFF_HIST
-				per_cpu(hist_preemptoff_counting, cpu) = 0;
-#endif
-#if defined(CONFIG_INTERRUPT_OFF_HIST) && defined(CONFIG_PREEMPT_OFF_HIST)
-				per_cpu(hist_preemptirqsoff_counting, cpu) = 0;
-#endif
-			}
+#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST
+		case MISSED_TIMER_OFFSETS:
+			unregister_trace_hrtimer_interrupt(
+			    probe_hrtimer_interrupt);
 			break;
+#endif
 		default:
 			break;
 		}
@@ -544,23 +634,29 @@ static const struct file_operations latency_hist_reset_fops = {
 	.write = latency_hist_reset,
 };
 
+static const struct file_operations latency_hist_enable_fops = {
+	.open = tracing_open_generic,
+	.read = latency_hist_show_enable,
+	.write = latency_hist_enable,
+};
+
+#ifdef CONFIG_WAKEUP_LATENCY_HIST
 static const struct file_operations latency_hist_pid_fops = {
 	.open = tracing_open_generic,
 	.read = latency_hist_show_pid,
 	.write = latency_hist_pid,
 };
+#endif
 
+#if defined(CONFIG_WAKEUP_LATENCY_HIST) || \
+    defined(CONFIG_MISSED_TIMER_OFFSETS_HIST)
 static const struct file_operations latency_hist_maxlatproc_fops = {
 	.open = tracing_open_generic,
 	.read = latency_hist_show_maxlatproc,
 };
+#endif
 
-static const struct file_operations latency_hist_enable_fops = {
-	.open = tracing_open_generic,
-	.read = latency_hist_show_enable,
-	.write = latency_hist_enable,
-};
-
+#if defined(CONFIG_INTERRUPT_OFF_HIST) || defined(CONFIG_PREEMPT_OFF_HIST)
 notrace void probe_preemptirqsoff_hist(int reason, int starthist)
 {
 	int cpu = raw_smp_processor_id();
@@ -660,11 +756,9 @@ notrace void probe_preemptirqsoff_hist(int reason, int starthist)
 #endif
 	}
 }
-
 #endif
 
 #ifdef CONFIG_WAKEUP_LATENCY_HIST
-static cycle_t wakeup_start;
 static DEFINE_RAW_SPINLOCK(wakeup_lock);
 
 notrace void probe_wakeup_latency_hist_start(struct rq *rq,
@@ -694,8 +788,8 @@ notrace void probe_wakeup_latency_hist_start(struct rq *rq,
 		put_task_struct(wakeup_task);
 	get_task_struct(p);
 	wakeup_task = p;
-	wakeup_start = ftrace_now(raw_smp_processor_id());
-	wakeup_task->preempt_timestamp_hist = wakeup_start;
+	wakeup_task->preempt_timestamp_hist =
+	    ftrace_now(raw_smp_processor_id());
 	raw_spin_unlock_irqrestore(&wakeup_lock, flags);
 }
 
@@ -714,30 +808,40 @@ notrace void probe_wakeup_latency_hist_stop(struct rq *rq,
 	stop = ftrace_now(cpu);
 
 	raw_spin_lock_irqsave(&wakeup_lock, flags);
+
+	latency = nsecs_to_usecs(stop - next->preempt_timestamp_hist);
 	if (next != wakeup_task) {
-		if (wakeup_task && next->prio == wakeup_task->prio) {
-			latency = nsecs_to_usecs(
-			    stop - next->preempt_timestamp_hist);
+		if (wakeup_task && next->prio == wakeup_task->prio)
 			latency_hist(WAKEUP_LATENCY_SHAREDPRIO, cpu, latency,
 			    next);
-		}
 		goto out;
 	}
 
-	latency = nsecs_to_usecs(stop - wakeup_start);
-	if (!wakeup_sharedprio)
-		latency_hist(WAKEUP_LATENCY, cpu, latency, next);
-	else {
+	if (wakeup_sharedprio) {
 		latency_hist(WAKEUP_LATENCY_SHAREDPRIO, cpu, latency, next);
 		wakeup_sharedprio = 0;
-	}
+	} else
+		latency_hist(WAKEUP_LATENCY, cpu, latency, next);
 
 	put_task_struct(wakeup_task);
 	wakeup_task = NULL;
 out:
 	raw_spin_unlock_irqrestore(&wakeup_lock, flags);
 }
+#endif
+
+#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST
+notrace void probe_hrtimer_interrupt(int cpu, long long latency_ns,
+    struct task_struct *task)
+{
+	if (latency_ns <= 0) {
+		unsigned long latency;
 
+		latency = (unsigned long) div_s64(-latency_ns, 1000);
+
+		latency_hist(MISSED_TIMER_OFFSETS, cpu, latency, task);
+	}
+}
 #endif
 
 static __init int latency_hist_init(void)
@@ -753,7 +857,10 @@ static __init int latency_hist_init(void)
 	struct hist_data *my_hist;
 	char name[64];
 	char *cpufmt = "CPU%d";
+#if defined(CONFIG_WAKEUP_LATENCY_HIST) || \
+    defined(CONFIG_MISSED_TIMER_OFFSETS_HIST)
 	char *cpufmt_maxlatproc = "max_latency-CPU%d";
+#endif
 
 	dentry = tracing_init_dentry();
 
@@ -855,6 +962,30 @@ static __init int latency_hist_init(void)
 	    latency_hist_enable_root, (void *)&wakeup_latency_enabled_data,
 	    &latency_hist_enable_fops);
 #endif
+
+#ifdef CONFIG_MISSED_TIMER_OFFSETS_HIST
+	dentry = debugfs_create_dir(missed_timer_offsets_dir,
+	    latency_hist_root);
+	for_each_possible_cpu(i) {
+		sprintf(name, cpufmt, i);
+		entry = debugfs_create_file(name, 0444, dentry,
+		    &per_cpu(missed_timer_offsets, i), &latency_hist_fops);
+		my_hist = &per_cpu(missed_timer_offsets, i);
+		atomic_set(&my_hist->hist_mode, 1);
+		my_hist->min_lat = 0xFFFFFFFFUL;
+
+		sprintf(name, cpufmt_maxlatproc, i);
+		entry = debugfs_create_file(name, 0444, dentry,
+		    &per_cpu(missed_timer_offsets_maxlatproc, i),
+		    &latency_hist_maxlatproc_fops);
+	}
+	entry = debugfs_create_file("reset", 0644, dentry,
+	    (void *)MISSED_TIMER_OFFSETS, &latency_hist_reset_fops);
+	entry = debugfs_create_file("missed_timer_offsets", 0644,
+	    latency_hist_enable_root,
+	    (void *)&missed_timer_offsets_enabled_data,
+	    &latency_hist_enable_fops);
+#endif
 	return 0;
 }
 
-- 
1.7.0.4