Adds a pcpu tracer for spinlocks
authorBarret Rhoden <brho@cs.berkeley.edu>
Wed, 4 Sep 2013 22:36:19 +0000 (15:36 -0700)
committerBarret Rhoden <brho@cs.berkeley.edu>
Wed, 4 Sep 2013 22:55:07 +0000 (15:55 -0700)
Compile with SPINLOCK_DEBUG and TRACE_LOCKS, then access the info from the
monitor with 'trace pcpui'.

This is very spammy, and it'll clobber any other info in the trace, so be
careful using it.  It will also attempt to find the location of the lock, based
on the symtab.  This only works for locks above KLA (o/w, the lock is dynamic).

When building with TRACE_LOCKS, we also disable any of the fancier checks for
the console and printf locks, so that they don't clobber our results.
Otherwise, as you printed lines, you'd be adding to the trace.

Kconfig
kern/arch/x86/console.c
kern/include/smp.h
kern/src/atomic.c
kern/src/printf.c
kern/src/smp.c

diff --git a/Kconfig b/Kconfig
index 7501cec..93faeae 100644 (file)
--- a/Kconfig
+++ b/Kconfig
@@ -94,6 +94,8 @@ endmenu
 
 menu "Kernel Debugging"
 
+menu "Per-cpu Tracers"
+
 config TRACE_KMSGS
        bool "KMSG Tracing"
        default n
@@ -103,6 +105,18 @@ config TRACE_KMSGS
                this off for a slight performance improvement on every KMSG (and every
                MCP proc_yield).
 
+config TRACE_LOCKS
+       bool "Lock Tracing"
+       depends on SPINLOCK_DEBUG
+       default n
+       help
+               Turns on lock tracing, using the per-cpu ring buffer.  This records the
+               a timestamp and lock address, in an over-write tracing style (meaning
+               it'll clobber older events).  If you have locking issues, this may give
+               you clues as to which locks were grabbed recently.
+
+endmenu
+
 config SPINLOCK_DEBUG
        bool "Spinlock debugging"
        default n
index 2390c24..ffe085e 100644 (file)
@@ -640,13 +640,26 @@ int cons_get_any_char(void)
 /* output a character to all console outputs (monitor and all serials) */
 void cons_putc(int c)
 {
+       #ifdef CONFIG_TRACE_LOCKS
+       int8_t irq_state = 0;
+       disable_irqsave(&irq_state);
+       __spin_lock(&lock);
+       #else
        spin_lock_irqsave(&lock);
+       #endif
+
        #ifndef CONFIG_SERIAL_IO
                serial_spam_char(c);
        #endif
        //lpt_putc(c);  /* very slow on the nehalem */
        cga_putc(c);
+
+       #ifdef CONFIG_TRACE_LOCKS
+       __spin_unlock(&lock);
+       enable_irqsave(&irq_state);
+       #else
        spin_unlock_irqsave(&lock);
+       #endif
 }
 
 // `High'-level console I/O.  Used by readline and cprintf.
index 5ca27b9..168e80e 100644 (file)
@@ -102,7 +102,8 @@ struct pcpu_trace_event {
  * pcpui_tr_handlers in smp.c. */
 #define PCPUI_TR_TYPE_NULL             0
 #define PCPUI_TR_TYPE_KMSG             1
-#define PCPUI_NR_TYPES                 2
+#define PCPUI_TR_TYPE_LOCKS            2
+#define PCPUI_NR_TYPES                 3
 
 #ifdef CONFIG_TRACE_KMSGS
 
@@ -121,6 +122,25 @@ struct pcpu_trace_event {
 
 #endif /* CONFIG_TRACE_KMSGS */
 
+
+#ifdef CONFIG_TRACE_LOCKS
+
+# define pcpui_trace_locks(pcpui, lock)                                        \
+{                                                                              \
+       struct pcpu_trace_event *e = get_trace_slot_overwrite(&pcpui->traces);     \
+       if (e) {                                                                   \
+               e->type = PCPUI_TR_TYPE_LOCKS;                                         \
+               e->arg0 = (int)tsc2usec(read_tsc());                                   \
+               e->arg1 = (uintptr_t)lock;                                             \
+       }                                                                          \
+}
+
+#else
+
+# define pcpui_trace_locks(pcpui, lock)
+
+#endif /* CONFIG_TRACE_LOCKS */
+
 /* Run the handlers for all events in a pcpui ring.  Can run on all cores, or
  * just one core.  'type' selects which event type is handled (0 for all). */
 void pcpui_tr_foreach(int coreid, int type);
index a413d24..f019e03 100644 (file)
@@ -50,6 +50,7 @@ void spin_lock(spinlock_t *lock)
                        pcpui->__lock_checking_enabled++;
                }
        }
+       pcpui_trace_locks(pcpui, lock);
 lock:
        __spin_lock(lock);
        lock->call_site = get_caller_pc();
index 5254746..43b6d01 100644 (file)
@@ -48,8 +48,16 @@ int vcprintf(const char *fmt, va_list ap)
        int *cntp = &cnt;
        volatile int i;
 
-       // lock all output.  this will catch any printfs at line granularity
+       /* lock all output.  this will catch any printfs at line granularity.  when
+        * tracing, we short-circuit the main lock call, so as not to clobber the
+        * results as we print. */
+       #ifdef CONFIG_TRACE_LOCKS
+       int8_t irq_state = 0;
+       disable_irqsave(&irq_state);
+       __spin_lock(&output_lock);
+       #else
        spin_lock_irqsave(&output_lock);
+       #endif
 
        // do the buffered printf
        #ifdef __DEPUTY__
@@ -61,7 +69,12 @@ int vcprintf(const char *fmt, va_list ap)
        // write out remaining chars in the buffer
        buffered_putch(-1,&cntp);
 
+       #ifdef CONFIG_TRACE_LOCKS
+       __spin_unlock(&output_lock);
+       enable_irqsave(&irq_state);
+       #else
        spin_unlock_irqsave(&output_lock);
+       #endif
 
        return cnt;
 }
index 39fc306..4cd222e 100644 (file)
@@ -129,10 +129,25 @@ static void pcpui_trace_kmsg_handler(void *event, void *data)
        kfree(func_name);
 }
 
+static void pcpui_trace_locks_handler(void *event, void *data)
+{
+       struct pcpu_trace_event *te = (struct pcpu_trace_event*)event;
+       char *func_name;
+       uintptr_t lock_addr = te->arg1;
+       if (lock_addr > KERN_LOAD_ADDR)
+               func_name = get_fn_name(lock_addr);
+       else
+               func_name = "Dynamic lock";
+       printk("Time %uus, lock %p (%s)\n", te->arg0, lock_addr, func_name);
+       if (lock_addr > KERN_LOAD_ADDR)
+               kfree(func_name);
+}
+
 /* Add specific trace handlers here: */
 trace_handler_t pcpui_tr_handlers[PCPUI_NR_TYPES] = {
                                   0,
                                   pcpui_trace_kmsg_handler,
+                                  pcpui_trace_locks_handler,
                                   };
 
 /* Generic handler for the pcpui ring.  Will switch out to the appropriate