Date: Fri, 12 Jun 2015 10:01:25 +0000 (UTC) From: Andriy Gapon <avg@FreeBSD.org> To: src-committers@freebsd.org, svn-src-all@freebsd.org, svn-src-head@freebsd.org Subject: svn commit: r284297 - in head: cddl/contrib/opensolaris/cmd/lockstat sys/kern sys/sys Message-ID: <201506121001.t5CA1PTm089721@svn.freebsd.org>
next in thread | raw e-mail | index | archive | help
Author: avg Date: Fri Jun 12 10:01:24 2015 New Revision: 284297 URL: https://svnweb.freebsd.org/changeset/base/284297 Log: several lockstat improvements 0. For spin events report time spent spinning, not a loop count. While loop count is much easier and cheaper to obtain it is hard to reason about the reported numbers, espcially for adaptive locks where both spinning and sleeping can happen. So, it's better to compare apples and apples. 1. Teach lockstat about FreeBSD rw locks. This is done in part by changing the corresponding probes and in part by changing what probes lockstat should expect. 2. Teach lockstat that rw locks are adaptive and can spin on FreeBSD. 3. Report lock acquisition events for successful rw try-lock operations. 4. Teach lockstat about FreeBSD sx locks. Reporting of events for those locks completely mirrors rw locks. 5. Report spin and block events before acquisition event. This is behavior documented for the upstream, so it makes sense to stick to it. Note that because of FreeBSD adaptive lock implementations both the spin and block events may be reported for the same acquisition while the upstream reports only one of them. Differential Revision: https://reviews.freebsd.org/D2727 Reviewed by: markj MFC after: 17 days Relnotes: yes Sponsored by: ClusterHQ Modified: head/cddl/contrib/opensolaris/cmd/lockstat/lockstat.c head/sys/kern/kern_mutex.c head/sys/kern/kern_rwlock.c head/sys/kern/kern_sx.c head/sys/sys/lockstat.h Modified: head/cddl/contrib/opensolaris/cmd/lockstat/lockstat.c ============================================================================== --- head/cddl/contrib/opensolaris/cmd/lockstat/lockstat.c Fri Jun 12 07:50:34 2015 (r284296) +++ head/cddl/contrib/opensolaris/cmd/lockstat/lockstat.c Fri Jun 12 10:01:24 2015 (r284297) @@ -157,14 +157,22 @@ static ls_event_info_t g_event_info[LS_M "lockstat:::rw-block", "arg2 != 0 && arg3 == 1" }, { 'C', "Lock", "R/W reader blocked by write wanted", "nsec", "lockstat:::rw-block", "arg2 != 0 && arg3 == 0 && arg4" }, - { 'C', "Lock", "Unknown event (type 8)", "units" }, - { 'C', "Lock", "Unknown event (type 9)", "units" }, - { 'C', "Lock", "Unknown event (type 10)", "units" }, - { 'C', "Lock", "Unknown event (type 11)", "units" }, - { 'C', "Lock", "Unknown event (type 12)", "units" }, - { 'C', "Lock", "Unknown event (type 13)", "units" }, - { 'C', "Lock", "Unknown event (type 14)", "units" }, - { 'C', "Lock", "Unknown event (type 15)", "units" }, + { 'C', "Lock", "R/W writer spin on writer", "nsec", + "lockstat:::rw-spin", "arg2 == 0 && arg3 == 1" }, + { 'C', "Lock", "R/W writer spin on readers", "nsec", + "lockstat:::rw-spin", "arg2 == 0 && arg3 == 0 && arg4" }, + { 'C', "Lock", "R/W reader spin on writer", "nsec", + "lockstat:::rw-spin", "arg2 != 0 && arg3 == 1" }, + { 'C', "Lock", "R/W reader spin on write wanted", "nsec", + "lockstat:::rw-spin", "arg2 != 0 && arg3 == 0 && arg4" }, + { 'C', "Lock", "SX exclusive block", "nsec", + "lockstat:::sx-block", "arg2 == 0" }, + { 'C', "Lock", "SX shared block", "nsec", + "lockstat:::sx-block", "arg2 != 0" }, + { 'C', "Lock", "SX exclusive spin", "nsec", + "lockstat:::sx-spin", "arg2 == 0" }, + { 'C', "Lock", "SX shared spin", "nsec", + "lockstat:::sx-spin", "arg2 != 0" }, { 'C', "Lock", "Unknown event (type 16)", "units" }, { 'C', "Lock", "Unknown event (type 17)", "units" }, { 'C', "Lock", "Unknown event (type 18)", "units" }, @@ -188,13 +196,17 @@ static ls_event_info_t g_event_info[LS_M "lockstat:::spin-release", NULL, "lockstat:::spin-acquire" }, { 'H', "Lock", "R/W writer hold", "nsec", - "lockstat:::rw-release", "arg1 == 0", - "lockstat:::rw-acquire" }, + "lockstat::rw_wunlock:rw-release", NULL, + "lockstat::rw_wlock:rw-acquire" }, { 'H', "Lock", "R/W reader hold", "nsec", - "lockstat:::rw-release", "arg1 != 0", - "lockstat:::rw-acquire" }, - { 'H', "Lock", "Unknown event (type 36)", "units" }, - { 'H', "Lock", "Unknown event (type 37)", "units" }, + "lockstat::rw_runlock:rw-release", NULL, + "lockstat::rw_rlock:rw-acquire" }, + { 'H', "Lock", "SX shared hold", "nsec", + "lockstat::sx_sunlock:sx-release", NULL, + "lockstat::sx_slock:sx-acquire" }, + { 'H', "Lock", "SX exclusive hold", "nsec", + "lockstat::sx_xunlock:sx-release", NULL, + "lockstat::sx_xlock:sx-acquire" }, { 'H', "Lock", "Unknown event (type 38)", "units" }, { 'H', "Lock", "Unknown event (type 39)", "units" }, { 'H', "Lock", "Unknown event (type 40)", "units" }, Modified: head/sys/kern/kern_mutex.c ============================================================================== --- head/sys/kern/kern_mutex.c Fri Jun 12 07:50:34 2015 (r284296) +++ head/sys/kern/kern_mutex.c Fri Jun 12 10:01:24 2015 (r284297) @@ -384,6 +384,7 @@ __mtx_lock_sleep(volatile uintptr_t *c, uint64_t spin_cnt = 0; uint64_t sleep_cnt = 0; int64_t sleep_time = 0; + int64_t all_time = 0; #endif if (SCHEDULER_STOPPED()) @@ -414,6 +415,9 @@ __mtx_lock_sleep(volatile uintptr_t *c, CTR4(KTR_LOCK, "_mtx_lock_sleep: %s contested (lock=%p) at %s:%d", m->lock_object.lo_name, (void *)m->mtx_lock, file, line); +#ifdef KDTRACE_HOOKS + all_time -= lockstat_nsecs(); +#endif while (!_mtx_obtain_lock(m, tid)) { #ifdef KDTRACE_HOOKS @@ -517,6 +521,9 @@ __mtx_lock_sleep(volatile uintptr_t *c, sleep_cnt++; #endif } +#ifdef KDTRACE_HOOKS + all_time += lockstat_nsecs(); +#endif #ifdef KTR if (cont_logged) { CTR4(KTR_CONTENTION, @@ -534,7 +541,7 @@ __mtx_lock_sleep(volatile uintptr_t *c, * Only record the loops spinning and not sleeping. */ if (spin_cnt > sleep_cnt) - LOCKSTAT_RECORD1(LS_MTX_LOCK_SPIN, m, (spin_cnt - sleep_cnt)); + LOCKSTAT_RECORD1(LS_MTX_LOCK_SPIN, m, (all_time - sleep_time)); #endif } @@ -574,6 +581,9 @@ _mtx_lock_spin_cookie(volatile uintptr_t int contested = 0; uint64_t waittime = 0; #endif +#ifdef KDTRACE_HOOKS + int64_t spin_time = 0; +#endif if (SCHEDULER_STOPPED()) return; @@ -589,6 +599,9 @@ _mtx_lock_spin_cookie(volatile uintptr_t PMC_SOFT_CALL( , , lock, failed); #endif lock_profile_obtain_lock_failed(&m->lock_object, &contested, &waittime); +#ifdef KDTRACE_HOOKS + spin_time -= lockstat_nsecs(); +#endif while (!_mtx_obtain_lock(m, tid)) { /* Give interrupts a chance while we spin. */ @@ -606,6 +619,9 @@ _mtx_lock_spin_cookie(volatile uintptr_t } spinlock_enter(); } +#ifdef KDTRACE_HOOKS + spin_time += lockstat_nsecs(); +#endif if (LOCK_LOG_TEST(&m->lock_object, opts)) CTR1(KTR_LOCK, "_mtx_lock_spin: %p spin done", m); @@ -614,7 +630,7 @@ _mtx_lock_spin_cookie(volatile uintptr_t LOCKSTAT_PROFILE_OBTAIN_LOCK_SUCCESS(LS_MTX_SPIN_LOCK_ACQUIRE, m, contested, waittime, (file), (line)); - LOCKSTAT_RECORD1(LS_MTX_SPIN_LOCK_SPIN, m, i); + LOCKSTAT_RECORD1(LS_MTX_SPIN_LOCK_SPIN, m, spin_time); } #endif /* SMP */ @@ -629,7 +645,7 @@ thread_lock_flags_(struct thread *td, in uint64_t waittime = 0; #endif #ifdef KDTRACE_HOOKS - uint64_t spin_cnt = 0; + int64_t spin_time = 0; #endif i = 0; @@ -638,6 +654,9 @@ thread_lock_flags_(struct thread *td, in if (SCHEDULER_STOPPED()) return; +#ifdef KDTRACE_HOOKS + spin_time -= lockstat_nsecs(); +#endif for (;;) { retry: spinlock_enter(); @@ -654,9 +673,6 @@ retry: WITNESS_CHECKORDER(&m->lock_object, opts | LOP_NEWORDER | LOP_EXCLUSIVE, file, line, NULL); while (!_mtx_obtain_lock(m, tid)) { -#ifdef KDTRACE_HOOKS - spin_cnt++; -#endif if (m->mtx_lock == tid) { m->mtx_recurse++; break; @@ -685,17 +701,17 @@ retry: if (m == td->td_lock) break; __mtx_unlock_spin(m); /* does spinlock_exit() */ + } #ifdef KDTRACE_HOOKS - spin_cnt++; + spin_time += lockstat_nsecs(); #endif - } if (m->mtx_recurse == 0) LOCKSTAT_PROFILE_OBTAIN_LOCK_SUCCESS(LS_MTX_SPIN_LOCK_ACQUIRE, m, contested, waittime, (file), (line)); LOCK_LOG_LOCK("LOCK", &m->lock_object, opts, m->mtx_recurse, file, line); WITNESS_LOCK(&m->lock_object, opts | LOP_EXCLUSIVE, file, line); - LOCKSTAT_RECORD1(LS_THREAD_LOCK_SPIN, m, spin_cnt); + LOCKSTAT_RECORD1(LS_THREAD_LOCK_SPIN, m, spin_time); } struct mtx * Modified: head/sys/kern/kern_rwlock.c ============================================================================== --- head/sys/kern/kern_rwlock.c Fri Jun 12 07:50:34 2015 (r284296) +++ head/sys/kern/kern_rwlock.c Fri Jun 12 10:01:24 2015 (r284297) @@ -300,6 +300,9 @@ __rw_try_wlock(volatile uintptr_t *c, co if (rval) { WITNESS_LOCK(&rw->lock_object, LOP_EXCLUSIVE | LOP_TRYLOCK, file, line); + if (!rw_recursed(rw)) + LOCKSTAT_PROFILE_OBTAIN_LOCK_SUCCESS(LS_RW_WLOCK_ACQUIRE, + rw, 0, 0, file, line); curthread->td_locks++; } return (rval); @@ -352,9 +355,11 @@ __rw_rlock(volatile uintptr_t *c, const #endif uintptr_t v; #ifdef KDTRACE_HOOKS + uintptr_t state; uint64_t spin_cnt = 0; uint64_t sleep_cnt = 0; int64_t sleep_time = 0; + int64_t all_time = 0; #endif if (SCHEDULER_STOPPED()) @@ -372,6 +377,10 @@ __rw_rlock(volatile uintptr_t *c, const rw->lock_object.lo_name, file, line)); WITNESS_CHECKORDER(&rw->lock_object, LOP_NEWORDER, file, line, NULL); +#ifdef KDTRACE_HOOKS + all_time -= lockstat_nsecs(); + state = rw->rw_lock; +#endif for (;;) { #ifdef KDTRACE_HOOKS spin_cnt++; @@ -534,7 +543,19 @@ __rw_rlock(volatile uintptr_t *c, const CTR2(KTR_LOCK, "%s: %p resuming from turnstile", __func__, rw); } +#ifdef KDTRACE_HOOKS + all_time += lockstat_nsecs(); + if (sleep_time) + LOCKSTAT_RECORD4(LS_RW_RLOCK_BLOCK, rw, sleep_time, + LOCKSTAT_READER, (state & RW_LOCK_READ) == 0, + (state & RW_LOCK_READ) == 0 ? 0 : RW_READERS(state)); + /* Record only the loops spinning and not sleeping. */ + if (spin_cnt > sleep_cnt) + LOCKSTAT_RECORD4(LS_RW_RLOCK_SPIN, rw, all_time - sleep_time, + LOCKSTAT_READER, (state & RW_LOCK_READ) == 0, + (state & RW_LOCK_READ) == 0 ? 0 : RW_READERS(state)); +#endif /* * TODO: acquire "owner of record" here. Here be turnstile dragons * however. turnstiles don't like owners changing between calls to @@ -546,16 +567,6 @@ __rw_rlock(volatile uintptr_t *c, const WITNESS_LOCK(&rw->lock_object, 0, file, line); curthread->td_locks++; curthread->td_rw_rlocks++; -#ifdef KDTRACE_HOOKS - if (sleep_time) - LOCKSTAT_RECORD1(LS_RW_RLOCK_BLOCK, rw, sleep_time); - - /* - * Record only the loops spinning and not sleeping. - */ - if (spin_cnt > sleep_cnt) - LOCKSTAT_RECORD1(LS_RW_RLOCK_SPIN, rw, (spin_cnt - sleep_cnt)); -#endif } int @@ -583,6 +594,8 @@ __rw_try_rlock(volatile uintptr_t *c, co LOCK_LOG_TRY("RLOCK", &rw->lock_object, 0, 1, file, line); WITNESS_LOCK(&rw->lock_object, LOP_TRYLOCK, file, line); + LOCKSTAT_PROFILE_OBTAIN_LOCK_SUCCESS(LS_RW_RLOCK_ACQUIRE, + rw, 0, 0, file, line); curthread->td_locks++; curthread->td_rw_rlocks++; return (1); @@ -727,9 +740,11 @@ __rw_wlock_hard(volatile uintptr_t *c, u int contested = 0; #endif #ifdef KDTRACE_HOOKS + uintptr_t state; uint64_t spin_cnt = 0; uint64_t sleep_cnt = 0; int64_t sleep_time = 0; + int64_t all_time = 0; #endif if (SCHEDULER_STOPPED()) @@ -751,6 +766,10 @@ __rw_wlock_hard(volatile uintptr_t *c, u CTR5(KTR_LOCK, "%s: %s contested (lock=%p) at %s:%d", __func__, rw->lock_object.lo_name, (void *)rw->rw_lock, file, line); +#ifdef KDTRACE_HOOKS + all_time -= lockstat_nsecs(); + state = rw->rw_lock; +#endif while (!_rw_write_lock(rw, tid)) { #ifdef KDTRACE_HOOKS spin_cnt++; @@ -888,18 +907,21 @@ __rw_wlock_hard(volatile uintptr_t *c, u spintries = 0; #endif } - LOCKSTAT_PROFILE_OBTAIN_LOCK_SUCCESS(LS_RW_WLOCK_ACQUIRE, rw, contested, - waittime, file, line); #ifdef KDTRACE_HOOKS + all_time += lockstat_nsecs(); if (sleep_time) - LOCKSTAT_RECORD1(LS_RW_WLOCK_BLOCK, rw, sleep_time); + LOCKSTAT_RECORD4(LS_RW_WLOCK_BLOCK, rw, sleep_time, + LOCKSTAT_WRITER, (state & RW_LOCK_READ) == 0, + (state & RW_LOCK_READ) == 0 ? 0 : RW_READERS(state)); - /* - * Record only the loops spinning and not sleeping. - */ + /* Record only the loops spinning and not sleeping. */ if (spin_cnt > sleep_cnt) - LOCKSTAT_RECORD1(LS_RW_WLOCK_SPIN, rw, (spin_cnt - sleep_cnt)); + LOCKSTAT_RECORD4(LS_RW_WLOCK_SPIN, rw, all_time - sleep_time, + LOCKSTAT_READER, (state & RW_LOCK_READ) == 0, + (state & RW_LOCK_READ) == 0 ? 0 : RW_READERS(state)); #endif + LOCKSTAT_PROFILE_OBTAIN_LOCK_SUCCESS(LS_RW_WLOCK_ACQUIRE, rw, contested, + waittime, file, line); } /* Modified: head/sys/kern/kern_sx.c ============================================================================== --- head/sys/kern/kern_sx.c Fri Jun 12 07:50:34 2015 (r284296) +++ head/sys/kern/kern_sx.c Fri Jun 12 10:01:24 2015 (r284297) @@ -288,6 +288,8 @@ sx_try_slock_(struct sx *sx, const char if (atomic_cmpset_acq_ptr(&sx->sx_lock, x, x + SX_ONE_SHARER)) { LOCK_LOG_TRY("SLOCK", &sx->lock_object, 0, 1, file, line); WITNESS_LOCK(&sx->lock_object, LOP_TRYLOCK, file, line); + LOCKSTAT_PROFILE_OBTAIN_LOCK_SUCCESS(LS_SX_SLOCK_ACQUIRE, + sx, 0, 0, file, line); curthread->td_locks++; return (1); } @@ -348,6 +350,9 @@ sx_try_xlock_(struct sx *sx, const char if (rval) { WITNESS_LOCK(&sx->lock_object, LOP_EXCLUSIVE | LOP_TRYLOCK, file, line); + if (!sx_recursed(sx)) + LOCKSTAT_PROFILE_OBTAIN_LOCK_SUCCESS(LS_SX_XLOCK_ACQUIRE, + sx, 0, 0, file, line); curthread->td_locks++; } @@ -509,9 +514,11 @@ _sx_xlock_hard(struct sx *sx, uintptr_t #endif int error = 0; #ifdef KDTRACE_HOOKS + uintptr_t state; uint64_t spin_cnt = 0; uint64_t sleep_cnt = 0; int64_t sleep_time = 0; + int64_t all_time = 0; #endif if (SCHEDULER_STOPPED()) @@ -533,6 +540,10 @@ _sx_xlock_hard(struct sx *sx, uintptr_t CTR5(KTR_LOCK, "%s: %s contested (lock=%p) at %s:%d", __func__, sx->lock_object.lo_name, (void *)sx->sx_lock, file, line); +#ifdef KDTRACE_HOOKS + all_time -= lockstat_nsecs(); + state = sx->sx_lock; +#endif while (!atomic_cmpset_acq_ptr(&sx->sx_lock, SX_LOCK_UNLOCKED, tid)) { #ifdef KDTRACE_HOOKS spin_cnt++; @@ -705,17 +716,21 @@ _sx_xlock_hard(struct sx *sx, uintptr_t CTR2(KTR_LOCK, "%s: %p resuming from sleep queue", __func__, sx); } - - GIANT_RESTORE(); - if (!error) - LOCKSTAT_PROFILE_OBTAIN_LOCK_SUCCESS(LS_SX_XLOCK_ACQUIRE, sx, - contested, waittime, file, line); #ifdef KDTRACE_HOOKS + all_time += lockstat_nsecs(); if (sleep_time) - LOCKSTAT_RECORD1(LS_SX_XLOCK_BLOCK, sx, sleep_time); + LOCKSTAT_RECORD4(LS_SX_XLOCK_BLOCK, sx, sleep_time, + LOCKSTAT_WRITER, (state & SX_LOCK_SHARED) == 0, + (state & SX_LOCK_SHARED) == 0 ? 0 : SX_SHARERS(state)); if (spin_cnt > sleep_cnt) - LOCKSTAT_RECORD1(LS_SX_XLOCK_SPIN, sx, (spin_cnt - sleep_cnt)); + LOCKSTAT_RECORD4(LS_SX_XLOCK_SPIN, sx, all_time - sleep_time, + LOCKSTAT_WRITER, (state & SX_LOCK_SHARED) == 0, + (state & SX_LOCK_SHARED) == 0 ? 0 : SX_SHARERS(state)); #endif + if (!error) + LOCKSTAT_PROFILE_OBTAIN_LOCK_SUCCESS(LS_SX_XLOCK_ACQUIRE, sx, + contested, waittime, file, line); + GIANT_RESTORE(); return (error); } @@ -801,14 +816,21 @@ _sx_slock_hard(struct sx *sx, int opts, uintptr_t x; int error = 0; #ifdef KDTRACE_HOOKS + uintptr_t state; uint64_t spin_cnt = 0; uint64_t sleep_cnt = 0; int64_t sleep_time = 0; + int64_t all_time = 0; #endif if (SCHEDULER_STOPPED()) return (0); +#ifdef KDTRACE_HOOKS + state = sx->sx_lock; + all_time -= lockstat_nsecs(); +#endif + /* * As with rwlocks, we don't make any attempt to try to block * shared locks once there is an exclusive waiter. @@ -958,15 +980,20 @@ _sx_slock_hard(struct sx *sx, int opts, CTR2(KTR_LOCK, "%s: %p resuming from sleep queue", __func__, sx); } - if (error == 0) - LOCKSTAT_PROFILE_OBTAIN_LOCK_SUCCESS(LS_SX_SLOCK_ACQUIRE, sx, - contested, waittime, file, line); #ifdef KDTRACE_HOOKS + all_time += lockstat_nsecs(); if (sleep_time) - LOCKSTAT_RECORD1(LS_SX_XLOCK_BLOCK, sx, sleep_time); + LOCKSTAT_RECORD4(LS_SX_SLOCK_BLOCK, sx, sleep_time, + LOCKSTAT_READER, (state & SX_LOCK_SHARED) == 0, + (state & SX_LOCK_SHARED) == 0 ? 0 : SX_SHARERS(state)); if (spin_cnt > sleep_cnt) - LOCKSTAT_RECORD1(LS_SX_XLOCK_SPIN, sx, (spin_cnt - sleep_cnt)); + LOCKSTAT_RECORD4(LS_SX_SLOCK_SPIN, sx, all_time - sleep_time, + LOCKSTAT_READER, (state & SX_LOCK_SHARED) == 0, + (state & SX_LOCK_SHARED) == 0 ? 0 : SX_SHARERS(state)); #endif + if (error == 0) + LOCKSTAT_PROFILE_OBTAIN_LOCK_SUCCESS(LS_SX_SLOCK_ACQUIRE, sx, + contested, waittime, file, line); GIANT_RESTORE(); return (error); } Modified: head/sys/sys/lockstat.h ============================================================================== --- head/sys/sys/lockstat.h Fri Jun 12 07:50:34 2015 (r284296) +++ head/sys/sys/lockstat.h Fri Jun 12 10:01:24 2015 (r284297) @@ -198,6 +198,9 @@ extern uint64_t lockstat_nsecs(void); (*lockstat_probe_func)(id, (uintptr_t)(lp), 0, 0, 0, 0); \ } while (0) +#define LOCKSTAT_WRITER 0 +#define LOCKSTAT_READER 1 + #else /* !KDTRACE_HOOKS */ #define LOCKSTAT_RECORD(probe, lp, arg1)
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?201506121001.t5CA1PTm089721>