[PATCH] Add debugging feature /proc/timer_stat

Add /proc/timer_stats support: debugging feature to profile timer expiration.
Both the starting site, process/PID and the expiration function is captured.
This allows the quick identification of timer event sources in a system.

Sample output:

# echo 1 > /proc/timer_stats
# cat /proc/timer_stats
Timer Stats Version: v0.1
Sample period: 4.010 s
  24,     0 swapper          hrtimer_stop_sched_tick (hrtimer_sched_tick)
  11,     0 swapper          sk_reset_timer (tcp_delack_timer)
   6,     0 swapper          hrtimer_stop_sched_tick (hrtimer_sched_tick)
   2,     1 swapper          queue_delayed_work_on (delayed_work_timer_fn)
  17,     0 swapper          hrtimer_restart_sched_tick (hrtimer_sched_tick)
   2,     1 swapper          queue_delayed_work_on (delayed_work_timer_fn)
   4,  2050 pcscd            do_nanosleep (hrtimer_wakeup)
   5,  4179 sshd             sk_reset_timer (tcp_write_timer)
   4,  2248 yum-updatesd     schedule_timeout (process_timeout)
  18,     0 swapper          hrtimer_restart_sched_tick (hrtimer_sched_tick)
   3,     0 swapper          sk_reset_timer (tcp_delack_timer)
   1,     1 swapper          neigh_table_init_no_netlink (neigh_periodic_timer)
   2,     1 swapper          e1000_up (e1000_watchdog)
   1,     1 init             schedule_timeout (process_timeout)
100 total events, 25.24 events/sec

[ cleanups and hrtimers support from Thomas Gleixner <tglx@linutronix.de> ]
[bunk@stusta.de: nr_entries can become static]
Signed-off-by: Ingo Molnar <mingo@elte.hu>
Signed-off-by: Thomas Gleixner <tglx@linutronix.de>
Cc: john stultz <johnstul@us.ibm.com>
Cc: Roman Zippel <zippel@linux-m68k.org>
Cc: Andi Kleen <ak@suse.de>
Signed-off-by: Adrian Bunk <bunk@stusta.de>
Signed-off-by: Andrew Morton <akpm@linux-foundation.org>
Signed-off-by: Linus Torvalds <torvalds@linux-foundation.org>

5 files changed, 472 insertions, 4 deletions

diff --git a/kernel/hrtimer.c b/kernel/hrtimer.c
index 62aad8e1a383..476cb0c0b4a4 100644
--- a/kernel/hrtimer.c
+++ b/kernel/hrtimer.c
@@ -585,6 +585,18 @@ static inline void hrtimer_init_timer_hres(struct hrtimer *timer) { }
 
 #endif /* CONFIG_HIGH_RES_TIMERS */
 
+#ifdef CONFIG_TIMER_STATS
+void __timer_stats_hrtimer_set_start_info(struct hrtimer *timer, void *addr)
+{
+        if (timer->start_site)
+                return;
+
+        timer->start_site = addr;
+        memcpy(timer->start_comm, current->comm, TASK_COMM_LEN);
+        timer->start_pid = current->pid;
+}
+#endif
+
 /*
  * Counterpart to lock_timer_base above:
  */
@@ -743,6 +755,7 @@ remove_hrtimer(struct hrtimer *timer, struct hrtimer_clock_base *base)
                  * reprogramming happens in the interrupt handler. This is a
                  * rare case and less expensive than a smp call.
                  */
+                timer_stats_hrtimer_clear_start_info(timer);
                 reprogram = base->cpu_base == &__get_cpu_var(hrtimer_bases);
                 __remove_hrtimer(timer, base, HRTIMER_STATE_INACTIVE,
                                  reprogram);
@@ -791,6 +804,8 @@ hrtimer_start(struct hrtimer *timer, ktime_t tim, const enum hrtimer_mode mode)
         }
         timer->expires = tim;
 
+        timer_stats_hrtimer_set_start_info(timer);
+
         enqueue_hrtimer(timer, new_base, base == new_base);
 
         unlock_hrtimer_base(timer, &flags);
@@ -925,6 +940,12 @@ void hrtimer_init(struct hrtimer *timer, clockid_t clock_id,
 
         timer->base = &cpu_base->clock_base[clock_id];
         hrtimer_init_timer_hres(timer);
+
+#ifdef CONFIG_TIMER_STATS
+        timer->start_site = NULL;
+        timer->start_pid = -1;
+        memset(timer->start_comm, 0, TASK_COMM_LEN);
+#endif
 }
 EXPORT_SYMBOL_GPL(hrtimer_init);
 
@@ -1006,6 +1027,7 @@ void hrtimer_interrupt(struct clock_event_device *dev)
 
                         __remove_hrtimer(timer, base,
                                          HRTIMER_STATE_CALLBACK, 0);
+                        timer_stats_account_hrtimer(timer);
 
                         /*
                          * Note: We clear the CALLBACK bit after
@@ -1050,6 +1072,8 @@ static void run_hrtimer_softirq(struct softirq_action *h)
                 timer = list_entry(cpu_base->cb_pending.next,
                                    struct hrtimer, cb_entry);
 
+                timer_stats_account_hrtimer(timer);
+
                 fn = timer->function;
                 __remove_hrtimer(timer, timer->base, HRTIMER_STATE_CALLBACK, 0);
                 spin_unlock_irq(&cpu_base->lock);
@@ -1106,6 +1130,8 @@ static inline void run_hrtimer_queue(struct hrtimer_cpu_base *cpu_base,
                 if (base->softirq_time.tv64 <= timer->expires.tv64)
                         break;
 
+                timer_stats_account_hrtimer(timer);
+
                 fn = timer->function;
                 __remove_hrtimer(timer, base, HRTIMER_STATE_CALLBACK, 0);
                 spin_unlock_irq(&cpu_base->lock);
diff --git a/kernel/time/Makefile b/kernel/time/Makefile
index f246bc836b9a..252b4b5d9dd0 100644
--- a/kernel/time/Makefile
+++ b/kernel/time/Makefile
@@ -5,3 +5,4 @@ obj-$(CONFIG_GENERIC_CLOCKEVENTS)		+= tick-common.o
 obj-$(CONFIG_GENERIC_CLOCKEVENTS_BROADCAST)     += tick-broadcast.o
 obj-$(CONFIG_TICK_ONESHOT)                      += tick-oneshot.o
 obj-$(CONFIG_TICK_ONESHOT)                      += tick-sched.o
+obj-$(CONFIG_TIMER_STATS)                       += timer_stats.o
diff --git a/kernel/time/timer_stats.c b/kernel/time/timer_stats.c
new file mode 100644
index 000000000000..1bc4882e28e0
--- /dev/null
+++ b/kernel/time/timer_stats.c
@@ -0,0 +1,411 @@
+/*
+ * kernel/time/timer_stats.c
+ *
+ * Collect timer usage statistics.
+ *
+ * Copyright(C) 2006, Red Hat, Inc., Ingo Molnar
+ * Copyright(C) 2006 Timesys Corp., Thomas Gleixner <tglx@timesys.com>
+ *
+ * timer_stats is based on timer_top, a similar functionality which was part of
+ * Con Kolivas dyntick patch set. It was developed by Daniel Petrini at the
+ * Instituto Nokia de Tecnologia - INdT - Manaus. timer_top's design was based
+ * on dynamic allocation of the statistics entries and linear search based
+ * lookup combined with a global lock, rather than the static array, hash
+ * and per-CPU locking which is used by timer_stats. It was written for the
+ * pre hrtimer kernel code and therefore did not take hrtimers into account.
+ * Nevertheless it provided the base for the timer_stats implementation and
+ * was a helpful source of inspiration. Kudos to Daniel and the Nokia folks
+ * for this effort.
+ *
+ * timer_top.c is
+ *      Copyright (C) 2005 Instituto Nokia de Tecnologia - INdT - Manaus
+ *      Written by Daniel Petrini <d.pensator@gmail.com>
+ *      timer_top.c was released under the GNU General Public License version 2
+ *
+ * We export the addresses and counting of timer functions being called,
+ * the pid and cmdline from the owner process if applicable.
+ *
+ * Start/stop data collection:
+ * # echo 1[0] >/proc/timer_stats
+ *
+ * Display the information collected so far:
+ * # cat /proc/timer_stats
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License version 2 as
+ * published by the Free Software Foundation.
+ */
+
+#include <linux/proc_fs.h>
+#include <linux/module.h>
+#include <linux/spinlock.h>
+#include <linux/sched.h>
+#include <linux/seq_file.h>
+#include <linux/kallsyms.h>
+
+#include <asm/uaccess.h>
+
+/*
+ * This is our basic unit of interest: a timer expiry event identified
+ * by the timer, its start/expire functions and the PID of the task that
+ * started the timer. We count the number of times an event happens:
+ */
+struct entry {
+        /*
+         * Hash list:
+         */
+        struct entry            *next;
+
+        /*
+         * Hash keys:
+         */
+        void                    *timer;
+        void                    *start_func;
+        void                    *expire_func;
+        pid_t                   pid;
+
+        /*
+         * Number of timeout events:
+         */
+        unsigned long           count;
+
+        /*
+         * We save the command-line string to preserve
+         * this information past task exit:
+         */
+        char                    comm[TASK_COMM_LEN + 1];
+
+} ____cacheline_aligned_in_smp;
+
+/*
+ * Spinlock protecting the tables - not taken during lookup: