PERFORCE change 99908 for review

[Kip Macy]

http://perforce.freebsd.org/chv.cgi?CH=99908

Change 99908 by kmacy at kmacy_storage:sun4v_work_sleepq on 2006/06/23 23:56:41

	track wait time for mutex acquisition

Affected files ...

.. //depot/projects/kmacy_sun4v/src/sys/kern/kern_mutex.c#14 edit
.. //depot/projects/kmacy_sun4v/src/sys/sun4v/include/pcpu.h#17 edit
.. //depot/projects/kmacy_sun4v/src/sys/sys/_lock.h#4 edit
.. //depot/projects/kmacy_sun4v/src/sys/sys/lock_profile.h#2 edit
.. //depot/projects/kmacy_sun4v/src/sys/sys/proc.h#8 edit

Differences ...

==== //depot/projects/kmacy_sun4v/src/sys/kern/kern_mutex.c#14 (text+ko) ====

@@ -207,20 +207,23 @@
 
 retry_sbufops:
 	sb = sbuf_new(NULL, NULL, MPROF_SBUF_SIZE * multiplier, SBUF_FIXEDLEN);
-	sbuf_printf(sb, "\n%6s %12s %11s %5s %12s %12s %s\n",
-	    "max", "total", "count", "avg", "cnt_hold", "cnt_lock", "name");
+	sbuf_printf(sb, "\n%6s %12s %12s %11s %5s %5s %12s %12s %s\n",
+	    "max", "total", "wait_total", "count", "avg", "wait_avg", "cnt_hold", "cnt_lock", "name");
 	for (i = 0; i < MPROF_HASH_SIZE; ++i) {
 		if (mprof_buf[i].name == NULL)
 			continue;
 		for (p = mprof_buf[i].file;
 			p != NULL && strncmp(p, "../", 3) == 0; p += 3)
  				/* nothing */ ;
-		sbuf_printf(sb, "%6ju %12ju %11ju %5ju %12ju %12ju %s:%d (%s)\n",
+		sbuf_printf(sb, "%6ju %12ju %12ju %11ju %5ju %5ju %12ju %12ju %s:%d (%s)\n",
 		    mprof_buf[i].cnt_max / 1000,
 		    mprof_buf[i].cnt_tot / 1000,
+		    mprof_buf[i].cnt_wait / 1000,
 		    mprof_buf[i].cnt_cur,
 		    mprof_buf[i].cnt_cur == 0 ? (uintmax_t)0 :
 			mprof_buf[i].cnt_tot / (mprof_buf[i].cnt_cur * 1000),
+		    mprof_buf[i].cnt_cur == 0 ? (uintmax_t)0 :
+			mprof_buf[i].cnt_wait / (mprof_buf[i].cnt_cur * 1000),
 		    mprof_buf[i].cnt_contest_holding,
 		    mprof_buf[i].cnt_contest_locking,
 		    p, mprof_buf[i].line, mprof_buf[i].name);

==== //depot/projects/kmacy_sun4v/src/sys/sun4v/include/pcpu.h#17 (text+ko) ====

@@ -41,9 +41,8 @@
 struct pmap;
 #if defined(WITNESS)
 #define SUN4V_PAD 7
-
 #elif defined(MUTEX_PROFILING)
-#define SUN4V_PAD 4
+#define SUN4V_PAD 3
 #else
 #define SUN4V_PAD 0
 #endif

==== //depot/projects/kmacy_sun4v/src/sys/sys/_lock.h#4 (text+ko) ====

@@ -37,6 +37,7 @@
          * MUTEX_PROFILING is in opt_global.h
          */
         u_int64_t               lpo_acqtime;
+        u_int64_t               lpo_waittime;
         const char              *lpo_filename;
         u_int                   lpo_namehash;
         int                     lpo_lineno;

==== //depot/projects/kmacy_sun4v/src/sys/sys/lock_profile.h#2 (text+ko) ====

@@ -16,6 +16,7 @@
 	int		line;
 	uintmax_t	cnt_max;
 	uintmax_t	cnt_tot;
+	uintmax_t       cnt_wait;
 	uintmax_t	cnt_cur;
 	uintmax_t	cnt_contest_holding;
 	uintmax_t	cnt_contest_locking;
@@ -45,6 +46,7 @@
 	struct lock_profile_object *l = &lo->lo_profile_obj;
 
 	l->lpo_acqtime = 0;
+	l->lpo_waittime = 0;
 	l->lpo_filename = NULL;
 	l->lpo_lineno = 0;
 	l->lpo_contest_holding = 0;
@@ -88,6 +90,8 @@
 	if (mutex_prof_enable) {
 		*contested = 1;
 		atomic_add_int(&l->lpo_contest_holding, 1);
+		if (curthread->td_waittime == 0)
+			curthread->td_waittime = rd(tick);
 	}
 }
 
@@ -100,6 +104,12 @@
 		l->lpo_filename = file;
 		l->lpo_lineno = line;
 		l->lpo_acqtime = rd(tick); /* substitute for more general TSC read */
+		if (curthread->td_waittime) {
+			struct thread *td = curthread;
+			if (l->lpo_acqtime > td->td_waittime)  
+				l->lpo_waittime = l->lpo_acqtime - td->td_waittime;
+			td->td_waittime = 0;
+		}
 	}
 }
 
@@ -110,14 +120,16 @@
 	if (l->lpo_acqtime) {
 		const char *unknown = "(unknown)";
 		struct mutex_prof *mpp;
-		u_int64_t acqtime, now;
+		u_int64_t acqtime, now, waittime;
 		u_int hash;
 		const char *p = l->lpo_filename;
 		int collision = 0;
 
 		now = rd(tick);
 		acqtime = l->lpo_acqtime;
+		waittime = l->lpo_waittime;
 		l->lpo_acqtime = 0;
+		l->lpo_waittime = 0;
 		if (now <= acqtime)
 			return;
 		if (p == NULL || *p == '\0')
@@ -162,6 +174,7 @@
 		if (now - acqtime > mpp->cnt_max)
 			mpp->cnt_max = now - acqtime;
 		mpp->cnt_tot += now - acqtime;
+		mpp->cnt_wait += waittime;
 		mpp->cnt_cur++;
 		/*
 		 * There's a small race, really we should cmpxchg

==== //depot/projects/kmacy_sun4v/src/sys/sys/proc.h#8 (text+ko) ====

@@ -256,6 +256,9 @@
 	struct mdthread td_md;		/* (k) Any machine-dependent fields. */
 	struct td_sched	*td_sched;	/* (*) Scheduler-specific data. */
 	struct kaudit_record	*td_ar;	/* (k) Active audit record, if any. */
+#ifdef MUTEX_PROFILING
+	uint64_t        td_waittime;    /* time in ns that thread started waiting for lock */
+#endif
 };
 
 /*