Modify ktr(4) to be typesafe
[dragonfly.git] / sys / kern / kern_ktr.c
index 238762e..e4c819c 100644 (file)
@@ -61,9 +61,7 @@
  * OUT OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF
  * SUCH DAMAGE.
  */
-/*
- * $DragonFly: src/sys/kern/kern_ktr.c,v 1.23 2008/02/12 23:33:23 corecode Exp $
- */
+
 /*
  * Kernel tracepoint facility.
  */
@@ -95,6 +93,8 @@
 
 #ifndef KTR_ENTRIES
 #define        KTR_ENTRIES             2048
+#elif (KTR_ENTRIES & KTR_ENTRIES - 1)
+#error KTR_ENTRIES must be a power of two
 #endif
 #define KTR_ENTRIES_MASK       (KTR_ENTRIES - 1)
 
 #endif
 KTR_INFO_MASTER(testlog);
 #if KTR_TESTLOG
-KTR_INFO(KTR_TESTLOG, testlog, test1, 0, "test1", sizeof(void *) * 4);
-KTR_INFO(KTR_TESTLOG, testlog, test2, 1, "test2", sizeof(void *) * 4);
-KTR_INFO(KTR_TESTLOG, testlog, test3, 2, "test3", sizeof(void *) * 4);
-KTR_INFO(KTR_TESTLOG, testlog, test4, 3, "test4", 0);
-KTR_INFO(KTR_TESTLOG, testlog, test5, 4, "test5", 0);
-KTR_INFO(KTR_TESTLOG, testlog, test6, 5, "test6", 0);
+KTR_INFO(KTR_TESTLOG, testlog, test1, 0, "test1 %d %d %d %d", int dummy1, int dummy2, int dummy3, int dummy4);
+KTR_INFO(KTR_TESTLOG, testlog, test2, 1, "test2 %d %d %d %d", int dummy1, int dummy2, int dummy3, int dummy4);
+KTR_INFO(KTR_TESTLOG, testlog, test3, 2, "test3 %d %d %d %d", int dummy1, int dummy2, int dummy3, int dummy4);
+KTR_INFO(KTR_TESTLOG, testlog, test4, 3, "test4");
+KTR_INFO(KTR_TESTLOG, testlog, test5, 4, "test5");
+KTR_INFO(KTR_TESTLOG, testlog, test6, 5, "test6");
 #ifdef SMP
-KTR_INFO(KTR_TESTLOG, testlog, pingpong, 6, "pingpong", 0);
-KTR_INFO(KTR_TESTLOG, testlog, pipeline, 7, "pipeline", 0);
-KTR_INFO(KTR_TESTLOG, testlog, crit_beg, 8, "crit_beg", 0);
-KTR_INFO(KTR_TESTLOG, testlog, crit_end, 9, "crit_end", 0);
-KTR_INFO(KTR_TESTLOG, testlog, spin_beg, 10, "spin_beg", 0);
-KTR_INFO(KTR_TESTLOG, testlog, spin_end, 11, "spin_end", 0);
+KTR_INFO(KTR_TESTLOG, testlog, pingpong, 6, "pingpong");
+KTR_INFO(KTR_TESTLOG, testlog, pipeline, 7, "pipeline");
+KTR_INFO(KTR_TESTLOG, testlog, crit_beg, 8, "crit_beg");
+KTR_INFO(KTR_TESTLOG, testlog, crit_end, 9, "crit_end");
+KTR_INFO(KTR_TESTLOG, testlog, spin_beg, 10, "spin_beg");
+KTR_INFO(KTR_TESTLOG, testlog, spin_end, 11, "spin_end");
 #endif
 #define logtest(name)  KTR_LOG(testlog_ ## name, 0, 0, 0, 0)
 #define logtest_noargs(name)   KTR_LOG(testlog_ ## name)
@@ -131,7 +131,8 @@ MALLOC_DEFINE(M_KTR, "ktr", "ktr buffers");
 SYSCTL_NODE(_debug, OID_AUTO, ktr, CTLFLAG_RW, 0, "ktr");
 
 int            ktr_entries = KTR_ENTRIES;
-SYSCTL_INT(_debug_ktr, OID_AUTO, entries, CTLFLAG_RD, &ktr_entries, 0, "");
+SYSCTL_INT(_debug_ktr, OID_AUTO, entries, CTLFLAG_RD, &ktr_entries, 0,
+    "Size of the event buffer");
 
 int            ktr_version = KTR_VERSION;
 SYSCTL_INT(_debug_ktr, OID_AUTO, version, CTLFLAG_RD, &ktr_version, 0, "");
@@ -140,7 +141,8 @@ static int  ktr_stacktrace = 1;
 SYSCTL_INT(_debug_ktr, OID_AUTO, stacktrace, CTLFLAG_RD, &ktr_stacktrace, 0, "");
 
 static int     ktr_resynchronize = 0;
-SYSCTL_INT(_debug_ktr, OID_AUTO, resynchronize, CTLFLAG_RW, &ktr_resynchronize, 0, "");
+SYSCTL_INT(_debug_ktr, OID_AUTO, resynchronize, CTLFLAG_RW,
+    &ktr_resynchronize, 0, "Resynchronize TSC 10 times a second");
 
 #if KTR_TESTLOG
 static int     ktr_testlogcnt = 0;
@@ -167,8 +169,6 @@ __cachealign struct ktr_cpu ktr_cpu[MAXCPU] = {
 };
 
 #ifdef SMP
-static int     ktr_sync_state = 0;
-static int     ktr_sync_count;
 static int64_t ktr_sync_tsc;
 #endif
 struct callout ktr_resync_callout;
@@ -176,7 +176,8 @@ struct callout      ktr_resync_callout;
 #ifdef KTR_VERBOSE
 int    ktr_verbose = KTR_VERBOSE;
 TUNABLE_INT("debug.ktr.verbose", &ktr_verbose);
-SYSCTL_INT(_debug_ktr, OID_AUTO, verbose, CTLFLAG_RW, &ktr_verbose, 0, "");
+SYSCTL_INT(_debug_ktr, OID_AUTO, verbose, CTLFLAG_RW, &ktr_verbose, 0,
+    "Log events to the console as well");
 #endif
 
 static void ktr_resync_callback(void *dummy __unused);
@@ -194,7 +195,7 @@ ktr_sysinit(void *dummy)
                kcpu->ktr_buf = kmalloc(KTR_ENTRIES * sizeof(struct ktr_entry),
                                        M_KTR, M_WAITOK | M_ZERO);
        }
-       callout_init(&ktr_resync_callout);
+       callout_init_mp(&ktr_resync_callout);
        callout_reset(&ktr_resync_callout, hz / 10, ktr_resync_callback, NULL);
 }
 SYSINIT(ktr_sysinit, SI_BOOT2_KLD, SI_ORDER_ANY, ktr_sysinit, NULL);
@@ -229,7 +230,10 @@ static
 void 
 ktr_resync_callback(void *dummy __unused)
 {
+       struct lwkt_cpusync cs;
+#if KTR_TESTLOG
        int count;
+#endif
 
        KKASSERT(mycpu->gd_cpuid == 0);
 
@@ -300,72 +304,43 @@ ktr_resync_callback(void *dummy __unused)
        if ((cpu_feature & CPUID_TSC) == 0)
                return;
 
-       /*
-        * Send the synchronizing IPI and wait for all cpus to get into
-        * their spin loop.  We must process incoming IPIs while waiting
-        * to avoid a deadlock.
-        */
        crit_enter();
-       ktr_sync_count = 0;
-       ktr_sync_state = 1;
-       ktr_sync_tsc = rdtsc();
-       count = lwkt_send_ipiq_mask(mycpu->gd_other_cpus & smp_active_mask,
-                                   (ipifunc1_t)ktr_resync_remote, NULL);
-       while (ktr_sync_count != count)
-               lwkt_process_ipiq();
-
-       /*
-        * Continuously update the TSC for cpu 0 while waiting for all other
-        * cpus to finish stage 2.
-        */
-       cpu_disable_intr();
+       lwkt_cpusync_init(&cs, smp_active_mask, ktr_resync_remote,
+                         (void *)(intptr_t)mycpu->gd_cpuid);
+       lwkt_cpusync_interlock(&cs);
        ktr_sync_tsc = rdtsc();
-       cpu_sfence();
-       ktr_sync_state = 2;
-       cpu_sfence();
-       while (ktr_sync_count != 0) {
-               ktr_sync_tsc = rdtsc();
-               cpu_lfence();
-               cpu_nop();
-       }
-       cpu_enable_intr();
+       lwkt_cpusync_deinterlock(&cs);
        crit_exit();
-       ktr_sync_state = 0;
 done:
        callout_reset(&ktr_resync_callout, hz / 10, ktr_resync_callback, NULL);
 }
 
 /*
- * The remote-end of the KTR synchronization protocol runs on all cpus except
- * cpu 0.  Since this is an IPI function, it is entered with the current
- * thread in a critical section.
+ * The remote-end of the KTR synchronization protocol runs on all cpus.
+ * The one we run on the controlling cpu updates its tsc continuously
+ * until the others have finished syncing (theoretically), but we don't
+ * loop forever.
+ *
+ * This is a bit ad-hoc but we need to avoid livelocking inside an IPI
+ * callback.  rdtsc() is a synchronizing instruction (I think).
  */
 static void
-ktr_resync_remote(void *dummy __unused)
+ktr_resync_remote(void *arg)
 {
-       volatile int64_t tsc1 = ktr_sync_tsc;
-       volatile int64_t tsc2;
+       globaldata_t gd = mycpu;
+       int64_t delta;
+       int i;
 
-       /*
-        * Inform the master that we have entered our hard loop.
-        */
-       KKASSERT(ktr_sync_state == 1);
-       atomic_add_int(&ktr_sync_count, 1);
-       while (ktr_sync_state == 1) {
-               lwkt_process_ipiq();
+       if (gd->gd_cpuid == (int)(intptr_t)arg) {
+               for (i = 0; i < 2000; ++i)
+                       ktr_sync_tsc = rdtsc();
+       } else {
+               delta = rdtsc() - ktr_sync_tsc;
+               if (tsc_offsets[gd->gd_cpuid] == 0)
+                       tsc_offsets[gd->gd_cpuid] = delta;
+               tsc_offsets[gd->gd_cpuid] =
+                       (tsc_offsets[gd->gd_cpuid] * 7 + delta) / 8;
        }
-
-       /*
-        * Now the master is in a hard loop, synchronize the TSC and
-        * we are done.
-        */
-       cpu_disable_intr();
-       KKASSERT(ktr_sync_state == 2);
-       tsc2 = ktr_sync_tsc;
-       if (tsc2 > tsc1)
-               tsc_offsets[mycpu->gd_cpuid] = rdtsc() - tsc2;
-       atomic_subtract_int(&ktr_sync_count, 1);
-       cpu_enable_intr();
 }
 
 #if KTR_TESTLOG
@@ -432,12 +407,11 @@ ktr_resync_callback(void *dummy __unused)
 #endif
 
 /*
- * KTR_WRITE_ENTRY - Primary entry point for kernel trace logging
+ * Setup the next empty slot and return it to the caller to store the data
+ * directly.
  */
-
-static __inline
-void
-ktr_write_entry(struct ktr_info *info, const char *file, int line, __va_list va)
+struct ktr_entry *
+ktr_begin_write_entry(struct ktr_info *info, const char *file, int line)
 {
        struct ktr_cpu_core *kcpu;
        struct ktr_entry *entry;
@@ -446,7 +420,7 @@ ktr_write_entry(struct ktr_info *info, const char *file, int line, __va_list va)
        cpu = mycpu->gd_cpuid;
        kcpu = &ktr_cpu[cpu].core;
        if (kcpu->ktr_buf == NULL)
-               return;
+               return NULL;
 
        crit_enter();
        entry = kcpu->ktr_buf + (kcpu->ktr_idx & KTR_ENTRIES_MASK);
@@ -467,36 +441,26 @@ ktr_write_entry(struct ktr_info *info, const char *file, int line, __va_list va)
        entry->ktr_file = file;
        entry->ktr_line = line;
        crit_exit();
-       if (info->kf_data_size > KTR_BUFSIZE)
-               bcopy(va, entry->ktr_data, KTR_BUFSIZE);
-       else if (info->kf_data_size)
-               bcopy(va, entry->ktr_data, info->kf_data_size);
+       return entry;
+}
+
+int
+ktr_finish_write_entry(struct ktr_info *info, struct ktr_entry *entry)
+{
        if (ktr_stacktrace)
                cpu_ktr_caller(entry);
 #ifdef KTR_VERBOSE
        if (ktr_verbose && info->kf_format) {
 #ifdef SMP
-               kprintf("cpu%d ", cpu);
+               kprintf("cpu%d ", mycpu->gd_cpuid);
 #endif
                if (ktr_verbose > 1) {
                        kprintf("%s.%d\t", entry->ktr_file, entry->ktr_line);
                }
-               kvprintf(info->kf_format, va);
-               kprintf("\n");
+               return !0;
        }
 #endif
-}
-
-void
-ktr_log(struct ktr_info *info, const char *file, int line, ...)
-{
-       __va_list va;
-
-       if (panicstr == NULL) {
-               __va_start(va, line);
-               ktr_write_entry(info, file, line, va);
-               __va_end(va);
-       }
+       return 0;
 }
 
 #ifdef DDB