Re: 2.6.15-ck1

[Dave Jones <davej@redhat.com>]

On Thu, Jan 05, 2006 at 11:12:51AM +1100, Con Kolivas wrote:
 > On Thursday 05 January 2006 08:40, Radoslaw Szkodzinski wrote:
 > > Arjan van de Ven wrote:
 > > > On Wed, 2006-01-04 at 14:57 -0500, Dave Jones wrote:
 > > >
 > > > sounds like we need some sort of profiler or benchmarker or at least a
 > > > tool that helps finding out which timers are regularly firing, with the
 > > > aim at either grouping them or trying to reduce their disturbance in
 > > > some form.
 > >
 > > You mean something like a modification to timer debugging patch to
 > > record the last time the timer fired, right?
 > > Timertop could then detect the pattern and provide frequency, standard
 > > deviation and other statistical data.
 > > It would be much more expensive to test of course.
 > 
 > I don't think the timer debugging patch needs to give out any more info. The 
 > userspace tool should be able to do this with the amount of info the timer 
 > debugging patch is giving already.

In the absense of a pointer to a userspace tool, I found the following handy.
(It also fixes a bug where it was printing garbage as process names).

[this is just an opencoded print_address().  I would have used that but it
 printk's instead of sprintf's to a buffer which made it useless for use by seq_print]

With this, it prints output like..

cfq_idle_slice_timer+0x0/0xb3 4 0 <kthread>
...
process_timeout+0x0/0x5 1025 147 pdflush
process_timeout+0x0/0x5 1701 3 watchdog/0
it_real_fn+0x0/0x5a 1907 2309 Xorg
process_timeout+0x0/0x5 2896 2356 gdmgreeter
process_timeout+0x0/0x5 3634 1940 python
i8042_timer_func+0x0/0xb 8699 0 <no data>
rh_timer_func+0x0/0x5 16499 4

There's still 1 case though it seems where some timers get garbage printed as their ->comm
If I get motivation to hack on this some more, I'll look further into it, but
this gets me 99% of the way there.  (Actually, it's missing timers launched
on behalf of init it seems (they all have a pid of '1'.
Wonder why init hasn't got a sane ->comm though).

		Dave

diff -urpN --exclude-from=/home/davej/.exclude linux-2.6.15/kernel/timer_top.c timertop/kernel/timer_top.c
--- linux-2.6.15/kernel/timer_top.c	2006-01-04 19:20:41.000000000 -0500
+++ timertop/kernel/timer_top.c	2006-01-04 18:37:35.000000000 -0500
@@ -27,12 +27,13 @@
 #include <linux/spinlock.h>
 #include <linux/sched.h>
 #include <linux/seq_file.h>
+#include <linux/kallsyms.h>
 #include <asm/uaccess.h>
 
 #define VERSION		"Timer Top v0.9.8"
 
 struct timer_top_info {
-	unsigned int		func_pointer;
+	unsigned long		func_pointer;
 	unsigned long		counter;
 	pid_t			pid;
 	char 			comm[TASK_COMM_LEN];
@@ -88,7 +89,11 @@ int account_timer(unsigned long function
 		if ((task_info->pid > 0) && (task_info->pid < PID_MAX_LIMIT)) {
 			pid_info = task_info->pid;
 			strncpy(name, task_info->comm, sizeof(task_info->comm));
+		} else {
+			strcpy(name, "<kthread>");
 		}
+	} else {
+		strcpy(name,"<no data>");
 	}
 
 	if (update_top_info(function, pid_info))
@@ -138,12 +143,30 @@ static struct proc_dir_entry *top_info_f
 static int proc_read_top_info(struct seq_file *m, void *v)
 {
 	struct timer_top_info *top;
+	char *modname;
+	const char *name;
+	unsigned long offset, size;
+	char namebuf[KSYM_NAME_LEN+1];
+	char buffer[sizeof("%s+%#lx/%#lx [%s]") + KSYM_NAME_LEN +
+            2*(BITS_PER_LONG*3/10) + MODULE_NAME_LEN + 1];
 
 	seq_printf(m, "Function counter - %s\n", VERSION);
 
 	list_for_each_entry(top, timer_list, list) {
-		seq_printf(m, "%x %lu %d %s\n", top->func_pointer,
-			top->counter, top->pid, top->comm);
+
+		name = kallsyms_lookup(top->func_pointer, &size, &offset, &modname, namebuf);
+		if (!name)
+			sprintf(buffer, "0x%lx", top->func_pointer);
+		else {
+			if (modname)
+				sprintf(buffer, "%s+%#lx/%#lx [%s]", name, offset,
+					size, modname);
+			else
+				sprintf(buffer, "%s+%#lx/%#lx", name, offset, size);
+		}
+
+		seq_printf(m, "%s %lu %d %s\n",
+			buffer, top->counter, top->pid, top->comm ? top->comm : "<>");
 	}
 
 	if (!top_root.record)