Poor-man's ftrace has more context
authorBarret Rhoden <brho@cs.berkeley.edu>
Wed, 30 Apr 2014 20:14:41 +0000 (13:14 -0700)
committerBarret Rhoden <brho@cs.berkeley.edu>
Wed, 30 Apr 2014 20:22:43 +0000 (13:22 -0700)
Will output whether we're in a process, IRQ, or ktask context.

Careful using this on certain devices in k/d/dev/, like acpi and console.  One
of the devs locks up if you try to print.

I usually turn off the 'print' bool in kdebug.c for booting, then turn it on
via 'kfunc toggle_print_func'.

To spatch the networking code, try something like:

$ for i in kern/src/net kern/drivers/net kern/drivers/dev/ether.c; do
spatch --sp-file scripts/spatch/poor-ftrace.cocci  --in-place $i; done

Documentation/howtos/poor-mans-ftrace.txt [new file with mode: 0644]
kern/src/kdebug.c

diff --git a/Documentation/howtos/poor-mans-ftrace.txt b/Documentation/howtos/poor-mans-ftrace.txt
new file mode 100644 (file)
index 0000000..818921d
--- /dev/null
@@ -0,0 +1,16 @@
+Poor-man's Ftrace is a live printk function tracer.  It does not handle
+concurrency well, whether that is interleaved IRQs or especially parallelism.
+Everything gets printed at the same time, and shares the same global
+indentation variable.  Still, it works reasonably well for IRQs, ktasks, and
+syscalls.
+
+Careful using this on certain devices in k/d/dev/, like acpi and console.  One
+of the devs locks up if you try to print.
+
+I usually turn off the 'print' bool in kdebug.c for booting, then turn it on
+via 'kfunc toggle_print_func'.
+
+To spatch the networking code, try something like:
+
+$ for i in kern/src/net kern/drivers/net kern/drivers/dev/ether.c; do
+    spatch --sp-file scripts/spatch/poor-ftrace.cocci  --in-place $i; done
index c9a4f2c..5ab058a 100644 (file)
@@ -59,6 +59,7 @@ static const char *blacklist[] = {
        "calcd",
        "freeroute",
        "genrandom",    /* not noisy, just never returns */
+       "limborexmit",
        "rangecompare",
        "walkadd",
 };
@@ -89,6 +90,22 @@ void toggle_print_func(void)
 
 static spinlock_t lock = SPINLOCK_INITIALIZER_IRQSAVE;
 
+static void __print_hdr(void)
+{
+       struct per_cpu_info *pcpui = &per_cpu_info[core_id()];
+       printd("Core %2d ", core_id()); /* may help with multicore output */
+       if (in_irq_ctx(pcpui)) {
+               printk("IRQ       :");
+       } else {
+               assert(pcpui->cur_kthread);
+               if (pcpui->cur_kthread->is_ktask) {
+                       printk("%10s:", pcpui->cur_kthread->name);
+               } else {
+                       printk("PID %3d   :", pcpui->cur_proc ? pcpui->cur_proc->pid : 0);
+               }
+       }
+}
+
 void __print_func_entry(const char *func, const char *file)
 {
        if (!print)
@@ -96,7 +113,7 @@ void __print_func_entry(const char *func, const char *file)
        if (is_blacklisted(func))
                return;
        spin_lock_irqsave(&lock);
-       printd("Core %2d", core_id());  /* helps with multicore output */
+       __print_hdr();
        for (int i = 0; i < tab_depth; i++)
                printk("\t");
        printk("%s() in %s\n", func, file);
@@ -112,7 +129,7 @@ void __print_func_exit(const char *func, const char *file)
                return;
        tab_depth--;
        spin_lock_irqsave(&lock);
-       printd("Core %2d", core_id());
+       __print_hdr();
        for (int i = 0; i < tab_depth; i++)
                printk("\t");
        printk("---- %s()\n", func);