Hook into hrtimer to report large latencies

2 files changed, 32 insertions, 0 deletions

diff --git a/include/linux/hrtimer.h b/include/linux/hrtimer.h
index 5e00f80b1535..720063df0ac0 100644
--- a/include/linux/hrtimer.h
+++ b/include/linux/hrtimer.h
@@ -109,6 +109,9 @@ struct hrtimer {
         void                            *start_site;
         char                            start_comm[16];
 #endif
+#ifdef CONFIG_REPORT_TIMER_LATENCY
+        ktime_t when_added;
+#endif
 };
 
 /**
diff --git a/kernel/time/hrtimer.c b/kernel/time/hrtimer.c
index a78e3558d0b6..b4824e1dbc6d 100644
--- a/kernel/time/hrtimer.c
+++ b/kernel/time/hrtimer.c
@@ -990,6 +990,10 @@ void hrtimer_start_range_ns(struct hrtimer *timer, ktime_t tim,
 
         tim = hrtimer_update_lowres(timer, tim, mode);
 
+#ifdef CONFIG_REPORT_TIMER_LATENCY
+        timer->when_added = base->get_time();
+#endif
+
         hrtimer_set_expires_range_ns(timer, tim, delta_ns);
 
         /* Switch the timer base, if necessary: */
@@ -1274,6 +1278,9 @@ static void __hrtimer_run_queues(struct hrtimer_cpu_base *cpu_base, ktime_t now)
 {
         struct hrtimer_clock_base *base = cpu_base->clock_base;
         unsigned int active = cpu_base->active_bases;
+#ifdef CONFIG_REPORT_TIMER_LATENCY
+        ktime_t was_exp_nxt = cpu_base->expires_next;
+#endif
 
         for (; active; base++, active >>= 1) {
                 struct timerqueue_node *node;
@@ -1304,6 +1311,28 @@ static void __hrtimer_run_queues(struct hrtimer_cpu_base *cpu_base, ktime_t now)
                         if (basenow.tv64 < hrtimer_get_softexpires_tv64(timer))
                                 break;
 
+#ifdef CONFIG_REPORT_TIMER_LATENCY
+                        if (cpu_base->hres_active &&
+                            (basenow.tv64 >=
+                             hrtimer_get_expires_tv64(timer) +
+                             ((s64) CONFIG_REPORT_TIMER_LATENCY_THRESHOLD))) {
+                                printk_ratelimited(KERN_WARNING
+                                    "WARNING: P%d timer latency:%lld now:%lld "
+                                    "basenow:%lld exp:%lld soft-exp:%lld "
+                                    "nxt:%lld added:%lld "
+                                    "timer:%p fn:%p"
+                                    "\n",
+                                    smp_processor_id(),
+                                    basenow.tv64 - hrtimer_get_expires_tv64(timer),
+                                    now.tv64, basenow.tv64,
+                                    hrtimer_get_expires_tv64(timer),
+                                    hrtimer_get_softexpires_tv64(timer),
+                                    was_exp_nxt.tv64,
+                                    timer->when_added.tv64,
+                                    timer, timer->function);
+                        }
+#endif
+
                         __run_hrtimer(cpu_base, base, timer, &basenow);
                 }
         }