X-Git-Url: https://gitweb.dragonflybsd.org/dragonfly.git/blobdiff_plain/d4a34d073e9d7b921ee3d9370f5f31d834026702..5bf48697e4f53509dec31ef5b2474f8744bd8712:/sys/kern/kern_ktr.c

diff --git a/sys/kern/kern_ktr.c b/sys/kern/kern_ktr.c
index 238762e584..e4c819c92b 100644
--- a/sys/kern/kern_ktr.c
+++ b/sys/kern/kern_ktr.c
@@ -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)
 
@@ -108,19 +108,19 @@
 #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