[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>

1 files changed, 29 insertions, 2 deletions

diff --git a/kernel/timer.c b/kernel/timer.c
index f058e6cfd50c..c3c67f3c0190 100644
--- a/kernel/timer.c
+++ b/kernel/timer.c
@@ -35,6 +35,7 @@
 #include <linux/syscalls.h>
 #include <linux/delay.h>
 #include <linux/tick.h>
+#include <linux/kallsyms.h>
 
 #include <asm/uaccess.h>
 #include <asm/unistd.h>
@@ -263,6 +264,18 @@ static void internal_add_timer(tvec_base_t *base, struct timer_list *timer)
         list_add_tail(&timer->entry, vec);
 }
 
+#ifdef CONFIG_TIMER_STATS
+void __timer_stats_timer_set_start_info(struct timer_list *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
+
 /**
  * init_timer - initialize a timer.
  * @timer: the timer to be initialized
@@ -274,11 +287,16 @@ void fastcall init_timer(struct timer_list *timer)
 {
         timer->entry.next = NULL;
         timer->base = __raw_get_cpu_var(tvec_bases);
+#ifdef CONFIG_TIMER_STATS
+        timer->start_site = NULL;
+        timer->start_pid = -1;
+        memset(timer->start_comm, 0, TASK_COMM_LEN);
+#endif
 }
 EXPORT_SYMBOL(init_timer);
 
 static inline void detach_timer(struct timer_list *timer,
-                                        int clear_pending)
+                                int clear_pending)
 {
         struct list_head *entry = &timer->entry;
 
@@ -325,6 +343,7 @@ int __mod_timer(struct timer_list *timer, unsigned long expires)
         unsigned long flags;
         int ret = 0;
 
+        timer_stats_timer_set_start_info(timer);
         BUG_ON(!timer->function);
 
         base = lock_timer_base(timer, &flags);
@@ -375,6 +394,7 @@ void add_timer_on(struct timer_list *timer, int cpu)
         tvec_base_t *base = per_cpu(tvec_bases, cpu);
         unsigned long flags;
 
+        timer_stats_timer_set_start_info(timer);
         BUG_ON(timer_pending(timer) || !timer->function);
         spin_lock_irqsave(&base->lock, flags);
         timer->base = base;
@@ -407,6 +427,7 @@ int mod_timer(struct timer_list *timer, unsigned long expires)
 {
         BUG_ON(!timer->function);
 
+        timer_stats_timer_set_start_info(timer);
         /*
          * This is a common optimization triggered by the
          * networking code - if the timer is re-modified
@@ -437,6 +458,7 @@ int del_timer(struct timer_list *timer)
         unsigned long flags;
         int ret = 0;
 
+        timer_stats_timer_clear_start_info(timer);
         if (timer_pending(timer)) {
                 base = lock_timer_base(timer, &flags);
                 if (timer_pending(timer)) {
@@ -570,6 +592,8 @@ static inline void __run_timers(tvec_base_t *base)
                         fn = timer->function;
                         data = timer->data;
 
+                        timer_stats_account_timer(timer);
+
                         set_running_timer(base, timer);
                         detach_timer(timer, 1);
                         spin_unlock_irq(&base->lock);
@@ -1229,7 +1253,8 @@ static void run_timer_softirq(struct softirq_action *h)
 {
         tvec_base_t *base = __get_cpu_var(tvec_bases);
 
-        hrtimer_run_queues();
+        hrtimer_run_queues();
+
         if (time_after_eq(jiffies, base->timer_jiffies))
                 __run_timers(base);
 }
@@ -1675,6 +1700,8 @@ void __init init_timers(void)
         int err = timer_cpu_notify(&timers_nb, (unsigned long)CPU_UP_PREPARE,
                                 (void *)(long)smp_processor_id());
 
+        init_timer_stats();
+
         BUG_ON(err == NOTIFY_BAD);
         register_cpu_notifier(&timers_nb);
         open_softirq(TIMER_SOFTIRQ, run_timer_softirq, NULL);