Adds a KMSG tracer
authorBarret Rhoden <brho@cs.berkeley.edu>
Sat, 27 Jul 2013 00:14:35 +0000 (17:14 -0700)
committerBarret Rhoden <brho@cs.berkeley.edu>
Sat, 27 Jul 2013 00:17:38 +0000 (17:17 -0700)
This traces all kernel messages and MCP proc_yields (which affect the
local context much like a KMSG).  It's a non-overwrite, so you'll need
to reset the ring to get up-to-date results.

Default is off.

Kconfig
kern/include/smp.h
kern/src/process.c
kern/src/smp.c
kern/src/trap.c

diff --git a/Kconfig b/Kconfig
index e45d031..7501cec 100644 (file)
--- a/Kconfig
+++ b/Kconfig
@@ -94,6 +94,15 @@ endmenu
 
 menu "Kernel Debugging"
 
 
 menu "Kernel Debugging"
 
+config TRACE_KMSGS
+       bool "KMSG Tracing"
+       default n
+       help
+               Turns on KMSG tracing, using the per-cpu ring buffer (holds about 256
+               events).  You can access this from the monitor via "trace pcpui".  Turn
+               this off for a slight performance improvement on every KMSG (and every
+               MCP proc_yield).
+
 config SPINLOCK_DEBUG
        bool "Spinlock debugging"
        default n
 config SPINLOCK_DEBUG
        bool "Spinlock debugging"
        default n
index 2da6fe9..7414184 100644 (file)
@@ -101,7 +101,25 @@ struct pcpu_trace_event {
  * use your own macro, and provide a handler.  Add your handler to
  * pcpui_tr_handlers in smp.c. */
 #define PCPUI_TR_TYPE_NULL             0
  * use your own macro, and provide a handler.  Add your handler to
  * pcpui_tr_handlers in smp.c. */
 #define PCPUI_TR_TYPE_NULL             0
-#define PCPUI_NR_TYPES                 1
+#define PCPUI_TR_TYPE_KMSG             1
+#define PCPUI_NR_TYPES                 2
+
+#ifdef CONFIG_TRACE_KMSGS
+
+# define pcpui_trace_kmsg(pcpui, pc)                                           \
+{                                                                              \
+       struct pcpu_trace_event *e = get_trace_slot_racy(&pcpui->traces);          \
+       if (e) {                                                                   \
+               e->type = PCPUI_TR_TYPE_KMSG;                                          \
+               e->arg1 = pc;                                                          \
+       }                                                                          \
+}
+
+#else
+
+# define pcpui_trace_kmsg(pcpui, pc)
+
+#endif /* CONFIG_TRACE_KMSGS */
 
 /* 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). */
 
 /* 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). */
index 9985e44..a12ee01 100644 (file)
@@ -1098,6 +1098,8 @@ void proc_yield(struct proc *SAFE p, bool being_nice)
                TAILQ_INSERT_TAIL(&p->online_vcs, vc, list); /* could go HEAD */
                goto out_failed;
        }
                TAILQ_INSERT_TAIL(&p->online_vcs, vc, list); /* could go HEAD */
                goto out_failed;
        }
+       /* Not really a kmsg, but it acts like one w.r.t. proc mgmt */
+       pcpui_trace_kmsg(pcpui, (uintptr_t)proc_yield);
        /* We won the race with event sending, we can safely yield */
        TAILQ_INSERT_HEAD(&p->inactive_vcs, vc, list);
        /* Note this protects stuff userspace should look at, which doesn't
        /* We won the race with event sending, we can safely yield */
        TAILQ_INSERT_HEAD(&p->inactive_vcs, vc, list);
        /* Note this protects stuff userspace should look at, which doesn't
index 2560e5c..7b49b4e 100644 (file)
@@ -116,9 +116,21 @@ void smp_percpu_init(void)
 
 /* PCPUI Trace Rings: */
 
 
 /* PCPUI Trace Rings: */
 
+static void pcpui_trace_kmsg_handler(void *event, void *data)
+{
+       struct pcpu_trace_event *te = (struct pcpu_trace_event*)event;
+       char *func_name;
+       uintptr_t addr;
+       addr = te->arg1;
+       func_name = get_fn_name(addr);
+       printk("\tKMSG %p: %s\n", addr, func_name);
+       kfree(func_name);
+}
+
 /* Add specific trace handlers here: */
 trace_handler_t pcpui_tr_handlers[PCPUI_NR_TYPES] = {
                                   0,
 /* Add specific trace handlers here: */
 trace_handler_t pcpui_tr_handlers[PCPUI_NR_TYPES] = {
                                   0,
+                                  pcpui_trace_kmsg_handler,
                                   };
 
 /* Generic handler for the pcpui ring.  Will switch out to the appropriate
                                   };
 
 /* Generic handler for the pcpui ring.  Will switch out to the appropriate
index 01bd896..c0eef53 100644 (file)
@@ -76,6 +76,7 @@ void handle_kmsg_ipi(struct hw_trapframe *hw_tf, void *data)
        /* The lock serves as a cmb to force a re-read of the head of the list */
        spin_lock(&pcpui->immed_amsg_lock);
        STAILQ_FOREACH_SAFE(kmsg_i, &pcpui->immed_amsgs, link, temp) {
        /* The lock serves as a cmb to force a re-read of the head of the list */
        spin_lock(&pcpui->immed_amsg_lock);
        STAILQ_FOREACH_SAFE(kmsg_i, &pcpui->immed_amsgs, link, temp) {
+               pcpui_trace_kmsg(pcpui, (uintptr_t)kmsg_i->pc);
                kmsg_i->pc(kmsg_i->srcid, kmsg_i->arg0, kmsg_i->arg1, kmsg_i->arg2);
                STAILQ_REMOVE(&pcpui->immed_amsgs, kmsg_i, kernel_message, link);
                kmem_cache_free(kernel_msg_cache, (void*)kmsg_i);
                kmsg_i->pc(kmsg_i->srcid, kmsg_i->arg0, kmsg_i->arg1, kmsg_i->arg2);
                STAILQ_REMOVE(&pcpui->immed_amsgs, kmsg_i, kernel_message, link);
                kmem_cache_free(kernel_msg_cache, (void*)kmsg_i);
@@ -125,6 +126,7 @@ void process_routine_kmsg(void)
                kmem_cache_free(kernel_msg_cache, (void*)kmsg);
                assert(msg_cp.dstid == pcoreid);        /* caught a brutal bug with this */
                set_rkmsg(pcpui);                                       /* we're now in early RKM ctx */
                kmem_cache_free(kernel_msg_cache, (void*)kmsg);
                assert(msg_cp.dstid == pcoreid);        /* caught a brutal bug with this */
                set_rkmsg(pcpui);                                       /* we're now in early RKM ctx */
+               pcpui_trace_kmsg(pcpui, (uintptr_t)msg_cp.pc);
                msg_cp.pc(msg_cp.srcid, msg_cp.arg0, msg_cp.arg1, msg_cp.arg2);
                /* If we aren't still in early RKM, it is because the KMSG blocked
                 * (thus leaving early RKM, finishing in default context) and then
                msg_cp.pc(msg_cp.srcid, msg_cp.arg0, msg_cp.arg1, msg_cp.arg2);
                /* If we aren't still in early RKM, it is because the KMSG blocked
                 * (thus leaving early RKM, finishing in default context) and then