Date: Fri, 23 Jun 2006 23:57:41 GMT From: Kip Macy <kmacy@FreeBSD.org> To: Perforce Change Reviews <perforce@freebsd.org> Subject: PERFORCE change 99908 for review Message-ID: <200606232357.k5NNvf5j070265@repoman.freebsd.org>
next in thread | raw e-mail | index | archive | help
http://perforce.freebsd.org/chv.cgi?CH=99908 Change 99908 by kmacy@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 }; /*
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?200606232357.k5NNvf5j070265>