/home/fox/release/dtrace/dtrace-20111209.tar.bz2

dtrace4linux · dtrace4linux · commit b45056ae087f · 2012-02-08T21:21:00.000Z
diff --git a/.release b/.release
@@ -1,3 +1,3 @@
-date=Tue Dec  6 23:08:02 GMT 2011
-release=dtrace-20111206
-build=337
+date=Fri Dec  9 20:50:38 GMT 2011
+release=dtrace-20111209
+build=338
diff --git a/Changes b/Changes
@@ -1,3 +1,32 @@
+Fri Dec  9 20:01:25 2011  fox
+
+     621* tools/tail.pl: Tool to do tail -f on any file, but specific
+          char special device files. Defaults to /proc/dtrace/trace.
+
+     620* Archive: 1.0131
+
+     619* dtrace.c: Added some monitoring around the kmem_free in 
+          dtrace_state_destroy. Not needed, but something to watch.
+
+     618* x_call.c: Whilst priming the other cpus for action, attempt
+          to drawin any pending call against ourselves. Reduce the
+	  poll time (ack_wait) a little, to try and gain better performance.
+
+     617* mutex.c: Dont disable interrupts for interrupt level mutexes.
+          (And, by implication, we dont need to restore them). Parameterise
+	  this change.
+	  Every 500m iterations, dump a "taking a long time message". Havent
+	  seen this get hit.
+
+Thu Dec  8 21:44:49 2011  fox
+
+     616* toxic.c: Re-enable more of the functions. We shouldnt have the old
+          problems anymore.
+
+Wed Dec  7 20:57:52 2011  fox
+
+     615* tools/cpustuck.pl: Simple tool to look for stuck cpus.
+
 Sun Dec  4 12:03:45 2011  fox
 
      614* dtrace.c: Tone down the teardown logic to avoid two
diff --git a/archive.sh b/archive.sh
@@ -1,6 +1,6 @@
 NAME=dtrace
 MAJ_VERSION=1
-MIN_VERSION=0130
+MIN_VERSION=0131
 EXCLUDE="*.ko *.o .git"
 EXCLUDE_DIRS="build-"
-#date Sun Dec  4 12:08:49 GMT 2011
+#date Fri Dec  9 20:12:02 GMT 2011
diff --git a/driver/dtrace.c b/driver/dtrace.c
@@ -5941,9 +5941,7 @@ dtrace_probe(dtrace_id_t id, uintptr_t arg0, uintptr_t arg1,
 		while (lock_teardown >= 0) {
 			extern void xcall_slave2(void);
 			xcall_slave2();
-dcnt[0]++;
 			if (cnt++ >= smp_processor_id() * 10/*000*/) {
-dcnt[1]++;
 				break;
 				}
 			}
@@ -10524,7 +10522,32 @@ dtrace_ecb_destroy(dtrace_ecb_t *ecb)
 		lock_teardown = smp_processor_id();
 	}
 
+#if linux
+	/***********************************************/
+	/*   Put  some  timings  around  the free. We  */
+	/*   dont need this, but its interesting when  */
+	/*   monitoring /proc/dtrace/trace.	       */
+	/***********************************************/
+	{static unsigned cnt;
+	static hrtime_t max_t;
+	hrtime_t s = dtrace_gethrtime();
+
+	cnt++;
+
 	kmem_free(ecb, sizeof (dtrace_ecb_t));
+
+	s = dtrace_gethrtime() - s;
+	if (s > max_t) {
+		max_t = s;
+		dtrace_printf("kmem_free t=%s (%d)\n", hrtime_str(s), cnt);
+	} else if ((cnt % 10000) == 0) {
+		dtrace_printf("kmem_free cnt=%d\n", cnt);
+	}
+	}
+
+#else
+	kmem_free(ecb, sizeof (dtrace_ecb_t));
+#endif
 }
 
 static dtrace_ecb_t *
@@ -13654,7 +13677,7 @@ HERE();
 	 * in the second we disable whatever is left over.
 	 */
 
-extern unsigned long cnt_xcall1;
+{extern unsigned long cnt_xcall1;
 hrtime_t s = dtrace_gethrtime();
 dtrace_printf("teardown start xcalls=%lu probes=%llu\n", cnt_xcall1, cnt_probes - cnt_free1);
 
@@ -13690,12 +13713,11 @@ dtrace_printf("teardown start xcalls=%lu probes=%llu\n", cnt_xcall1, cnt_probes
 	/*   Dump some stats on how long the teardown  */
 	/*   took.				       */
 	/***********************************************/
-	{
-		hrtime_t e = dtrace_gethrtime() - s;
-		dtrace_printf("teardown done %llu.%09llu xcalls=%lu probes=%llu\n", e / (1000 * 1000 * 1000), e % (1000 * 1000 * 1000), cnt_xcall1,
-			cnt_probes - cnt_free1);
-	}
-
+	s = dtrace_gethrtime() - s;
+	dtrace_printf("teardown done %s xcalls=%lu probes=%llu\n", hrtime_str(s),
+		cnt_xcall1,
+		cnt_probes - cnt_free1);
+}
 
 	/*
 	 * Before we free the buffers, perform one more sync to assure that
diff --git a/driver/instr_linux.c b/driver/instr_linux.c
@@ -112,7 +112,7 @@ instr_is_patched(char *name, uint8_t *addr)
 
 	for (; fbt != NULL; fbt = fbt->insp_hashnext) {
 		if (fbt->insp_patchpoint == addr) {
-			dtrace_printf("fbt:dup patch: %p %s\n", addr, name);
+			dtrace_printf("instr:dup patch: %p %s\n", addr, name);
 			return 1;
 		}
 	}
@@ -475,7 +475,7 @@ instr_provide_function(struct modctl *mp, par_module_t *pmp,
 	char	pred_buf[128];
 
 # define UNHANDLED_FBT() if (do_print || dtrace_unhandled) { \
-		printk("fbt:unhandled instr %s:%p %02x %02x %02x %02x\n", \
+		printk("instr:unhandled instr %s:%p %02x %02x %02x %02x\n", \
 			name, instr, instr[0], instr[1], instr[2], instr[3]); \
 			}
 
diff --git a/driver/mutex.c b/driver/mutex.c
@@ -40,6 +40,8 @@ unsigned long cnt_mtx1;
 unsigned long cnt_mtx2;
 unsigned long cnt_mtx3;
 
+static const int disable_ints;
+
 void
 dmutex_init(mutex_t *mp)
 {
@@ -60,7 +62,7 @@ dmutex_init(mutex_t *mp)
 void
 mutex_enter_common(mutex_t *mp, int dflag)
 {       unsigned long flags;
-	unsigned long cnt;
+	unsigned int  cnt;
 
 	if (!mp->m_initted) {
 		/***********************************************/
@@ -108,7 +110,7 @@ mutex_enter_common(mutex_t *mp, int dflag)
 		return;
 	}
 
-	if (dflag)
+	if (disable_ints && dflag)
 	    flags = dtrace_interrupt_disable();
 	else
 	      flags = dtrace_interrupt_get();
@@ -122,23 +124,16 @@ mutex_enter_common(mutex_t *mp, int dflag)
 		/***********************************************/
 		if ((cnt++ % 100) == 0)
 			xcall_slave2();
+
 		/***********************************************/
-		/*   We  want  to avoid locking the kernel if  */
-		/*   something  is  broken, but if we do exit  */
-		/*   prematurely,  we  will  have  the caller  */
-		/*   race against someone else (eg syscall:::  */
-		/*   and   fbt:::  in  a  continuous  restart  */
-		/*   loop).  For  now,  we  will hang til the  */
-		/*   traffic jam is passed.		       */
+		/*   If  we  start locking up the kernel, let  */
+		/*   user  know  something  bad is happening.  */
+		/*   Probably  pointless  if mutex is working  */
+		/*   correctly.				       */
 		/***********************************************/
-		if (cnt++ == 1500 * 1000 * 1000) {
+		if ((cnt++ % (500 * 1000 * 1000)) == 0) {
 			dtrace_printf("mutex_enter: taking a long time to grab lock mtx3=%llu\n", cnt_mtx3);
-			xcall_slave2();
 			cnt_mtx3++;
-//			break;
-/*			dtrace_interrupt_enable(flags);
-			dtrace_linux_panic("mutex");
-			break;*/
 		}
 	}
 //preempt_disable();
@@ -187,7 +182,7 @@ if (f++ == 70) {
 
 	cnt_mtx2++;
 	mutex_enter_common(mp, FALSE);
-	if (irqs_disabled()) {
+	if (disable_ints && irqs_disabled()) {
 		dtrace_printf("%p: mutex_enter with irqs disabled fl:%lx level:%d cpu:%d\n",
 		    mp, mp->m_flags, mp->m_level, mp->m_cpu);
 		dtrace_printf("orig: init=%d fl:%lx cpu:%d\n", imp.m_initted, imp.m_flags, imp.m_cpu);
@@ -210,7 +205,8 @@ dmutex_exit(mutex_t *mp)
 	*/
 
 	mp->m_count = 0;
-	dtrace_interrupt_enable(fl);
+	if (disable_ints)
+		dtrace_interrupt_enable(fl);
 //preempt_enable_no_resched();
 }
 
diff --git a/driver/printf.c b/driver/printf.c
@@ -198,7 +198,11 @@ static hrtime_t	hrt0;
 	dtrace_printf_int(smp_processor_id());
 	ADDCH(' ');
 	dtrace_printf_int(get_current()->pid);
-	ADDCH(':');
+	if (irqs_disabled()) {
+		ADDCH('-');
+	} else {
+		ADDCH(':');
+	}
 
 	while ((ch = *fmt++) != '\0') {
 		if (ch != '%') {
diff --git a/driver/toxic.c b/driver/toxic.c
@@ -56,12 +56,12 @@ char toxic_probe_tbl[] = {
 	"__kprobes_text_start"
 	"__mod_timer "
 	"__show_registers "
-	"__mutex_init "
-	"__mutex_lock_interruptible_slowpath "
-	"__mutex_lock_killable_slowpath "
-	"__mutex_lock_slowpath "
-	"__mutex_trylock_slowpath "
-	"__mutex_unlock_slowpath "
+//	"__mutex_init "
+//	"__mutex_lock_interruptible_slowpath "
+//	"__mutex_lock_killable_slowpath "
+//	"__mutex_lock_slowpath "
+//	"__mutex_trylock_slowpath "
+//	"__mutex_unlock_slowpath "
 #if LINUX_VERSION_CODE < KERNEL_VERSION(2, 6, 19)
 	"__tasklet_hi_schedule "
 	"__tasklet_schedule "
@@ -95,8 +95,8 @@ char toxic_probe_tbl[] = {
 	"kmem_cache_free "
 	"level3_kernel_pgt " // this is a data element in the code segment
 	"level2_kernel_pgt " // this is a data element in the code segment
-	"mutex_lock "
-	"mutex_unlock "
+//	"mutex_lock "
+//	"mutex_unlock "
 	"native_get_debugreg "
 	"on_each_cpu " 		// Needed by dtrace_xcall
 	"oops_exit "
diff --git a/driver/x_call.c b/driver/x_call.c
@@ -28,7 +28,7 @@
 
 
 extern void dtrace_sync_func(void);
-int 	in_xcall;
+int 	in_xcall = -1;
 char	nmi_masks[NCPU];
 
 /**********************************************************************/
@@ -294,36 +294,19 @@ void
 dtrace_xcall1(processorid_t cpu, dtrace_xcall_t func, void *arg)
 {
 
-	/***********************************************/
-	/*   We  dont disable interrupts whilst doing  */
-	/*   an xcall. We may have two cpus trying to  */
-	/*   do  this at the same time, so we need to  */
-	/*   run in a lockless mode.		       */
-	/*   					       */
-	/*   We  do run with preempt_disable to avoid  */
-	/*   any  chance  of rescheduling the calling  */
-	/*   process  whilst we wait for long periods  */
-	/*   of  time.  (Note  that  disable  is  not  */
-	/*   nested;  does  this  matter  if  we have  */
-	/*   multiple  cpus  coming  in  at  the same  */
-	/*   time?				       */
-	/***********************************************/
-//	preempt_disable();
-
 	/***********************************************/
 	/*   Just  track re-entrancy events - we will  */
 	/*   be lockless in dtrace_xcall2.	       */
 	/***********************************************/
-	if (in_xcall) {
+	if (in_xcall >= 0 && (cnt_xcall0 < 500 || (cnt_xcall0 % 50) == 0)) {
+		dtrace_printf("x_call: re-entrant call in progress (%d) other=%d.\n", cnt_xcall0, in_xcall); 
 		cnt_xcall0++; 
-		if (cnt_xcall0 < 10 || (cnt_xcall0 % 50) == 0)
-			dtrace_printf("x_call: re-entrant call in progress (%d).\n", cnt_xcall0); 
-//dump_all_stacks();
 	}
-	in_xcall = 1;
+	in_xcall = smp_processor_id();
+//int flags = dtrace_interrupt_disable();
 	dtrace_xcall2(cpu, func, arg);
-	in_xcall = 0;
-//	preempt_enable();
+//dtrace_interrupt_enable(flags);
+	in_xcall = -1;
 }
 void
 dtrace_xcall2(processorid_t cpu, dtrace_xcall_t func, void *arg)
@@ -434,6 +417,7 @@ typedef struct cpumask cpumask_t;
 				dtrace_printf("[%d] cpu%d in wrong state (state=%d)\n",
 					smp_processor_id(), c, xc->xc_state);
 			}
+//			xcall_slave2();
 			if (cnt == 100 * 1000 * 1000) {
 				dtrace_printf("[%d] cpu%d - busting lock\n",
 					smp_processor_id(), c);
@@ -485,7 +469,6 @@ typedef struct cpumask cpumask_t;
 	/*   us whilst we are calling them.	       */
 	/***********************************************/
 	while (cpus_todo > 0) {
-//static int first = 1;
 		for (c = 0; c < nr_cpus && cpus_todo > 0; c++) {
 			xcall_slave2();
 			if (c == cpu_id || (cpu & (1 << c)) == 0)
@@ -495,17 +478,12 @@ typedef struct cpumask cpumask_t;
 			/*   Wait  a  little  while  for  this cpu to  */
 			/*   respond before going on to the next one.  */
 			/***********************************************/
-			if (ack_wait(c, 1000)) {
+			if (ack_wait(c, 100)) {
 				cpus_todo--;
 				cpu &= ~(1 << c);
 			}
 		}
-/*if (cpus_todo > 0 && first) { 
-cnt_xcall8++;
-void dump_all_stacks(void); first = FALSE; dtrace_printf("xcall deadlock:\n"); }
-*/
 	}
-
 //	smp_mb();
 
 	xcall_levels[cpu_id]--;
diff --git a/tools/cpustuck.pl b/tools/cpustuck.pl
diff --git a/utils/get-vmlinux.pl b/utils/get-vmlinux.pl

Original file line number	Diff line number	Diff line change
`@@ -112,7 +112,7 @@ instr_is_patched(char name, uint8_t addr)`
`112`	`112`
`113`	`113`	`for (; fbt != NULL; fbt = fbt->insp_hashnext) {`
`114`	`114`	`if (fbt->insp_patchpoint == addr) {`
`115`		`- dtrace_printf("fbt:dup patch: %p %s\n", addr, name);`
	`115`	`+ dtrace_printf("instr:dup patch: %p %s\n", addr, name);`
`116`	`116`	`return 1;`
`117`	`117`	`}`
`118`	`118`	`}`
`@@ -475,7 +475,7 @@ instr_provide_function(struct modctl mp, par_module_t pmp,`
`475`	`475`	`char pred_buf[128];`
`476`	`476`
`477`	`477`	`# define UNHANDLED_FBT() if (do_print \|\| dtrace_unhandled) { \`
`478`		`- printk("fbt:unhandled instr %s:%p %02x %02x %02x %02x\n", \`
	`478`	`+ printk("instr:unhandled instr %s:%p %02x %02x %02x %02x\n", \`
`479`	`479`	`name, instr, instr[0], instr[1], instr[2], instr[3]); \`
`480`	`480`	`}`
`481`	`481`