Track total contention time for mutexes and rwlocks

This adds the ability to track the total amount of time for which each mutex
or rwlock is contended. Effectively, this is the amount of time which is
spent blocked inside pthread_mutex_lock() and friends — we don't count time
spent inside these functions if the mutex isn't busy, however (i.e. if
pthread_mutex_trylock() doesn't return EBUSY).

It is possible for the total contention time for a given mutex to exceed the
total locked time. This can happen if the OS doesn't re-schedule a thread
which is blocked on a mutex until some time after the thread which was
holding the mutex unlocks it.

This commit replaces the “max.Time[ms]” summary column with a new
“cont.Time[ms]” column which lists the total contention time for each mutex.
I believe this is more important/useful than the maximum locked time.

1 files changed, 69 insertions, 27 deletions

diff --git a/mutrace.c b/mutrace.c
index e1176aa..8d5648c 100644
--- a/mutrace.c
+++ b/mutrace.c
@@ -84,6 +84,10 @@ struct mutex_info {
         uint64_t nsec_locked_total;
         uint64_t nsec_locked_max;
 
+        uint64_t nsec_contended_total; /* mutexes only */
+        uint64_t nsec_read_contended_total; /* rwlocks only */
+        uint64_t nsec_write_contended_total; /* rwlocks only */
+
         uint64_t nsec_timestamp;
         struct stacktrace_info stacktrace;
 
@@ -537,14 +541,14 @@ static bool mutex_info_stat(struct mutex_info *mi) {
                 return false;
 
         fprintf(stderr,
-                "%8u %8u %8u %8u %12.3f %12.3f %12.3f %c%c%c%c%c%c\n",
+                "%8u %8u %8u %8u %13.3f %12.3f %12.3f %c%c%c%c%c%c\n",
                 mi->id,
                 mi->n_locked,
                 mi->n_owner_changed,
                 mi->n_contended,
+                (double) mi->nsec_contended_total / 1000000.0,
                 (double) mi->nsec_locked_total / 1000000.0,
                 (double) mi->nsec_locked_total / mi->n_locked / 1000000.0,
-                (double) mi->nsec_locked_max / 1000000.0,
                 mi->mutex ? 'M' : 'W',
                 mi->broken ? '!' : (mi->dead ? 'x' : '-'),
                 track_rt ? (mi->realtime ? 'R' : '-') : '.',
@@ -613,7 +617,7 @@ static void show_summary_internal(void) {
                         "\n"
                         "mutrace: Showing %u most contended mutexes:\n"
                         "\n"
-                        " Mutex #   Locked  Changed    Cont. tot.Time[ms] avg.Time[ms] max.Time[ms]  Flags\n",
+                        " Mutex #   Locked  Changed    Cont. cont.Time[ms] tot.Time[ms] avg.Time[ms] Flags\n",
                         m);
 
                 for (i = 0, m = 0; i < n && (show_n_max <= 0 || m < show_n_max); i++)
@@ -622,19 +626,19 @@ static void show_summary_internal(void) {
 
                 if (i < n)
                         fprintf(stderr,
-                                "     ...      ...      ...      ...          ...          ...          ... ||||||\n");
+                                "     ...      ...      ...      ...           ...          ...          ... ||||||\n");
                 else
                         fprintf(stderr,
-                                "                                                                           ||||||\n");
+                                "                                                                            ||||||\n");
 
                 fprintf(stderr,
-                        "                                                                           /|||||\n"
-                        "          Object:                                     M = Mutex, W = RWLock /||||\n"
-                        "           State:                                 x = dead, ! = inconsistent /|||\n"
-                        "             Use:                                 R = used in realtime thread /||\n"
-                        "      Mutex Type:                  r = RECURSIVE, e = ERRORCHECK, a = ADAPTIVE /|\n"
-                        "  Mutex Protocol:                                      i = INHERIT, p = PROTECT /\n"
-                        "     RWLock Kind: r = PREFER_READER, w = PREFER_WRITER, W = PREFER_WRITER_NONREC \n");
+                        "                                                                            /|||||\n"
+                        "          Object:                                      M = Mutex, W = RWLock /||||\n"
+                        "           State:                                  x = dead, ! = inconsistent /|||\n"
+                        "             Use:                                  R = used in realtime thread /||\n"
+                        "      Mutex Type:                   r = RECURSIVE, e = ERRORCHECK, a = ADAPTIVE /|\n"
+                        "  Mutex Protocol:                                       i = INHERIT, p = PROTECT /\n"
+                        "     RWLock Kind:  r = PREFER_READER, w = PREFER_WRITER, W = PREFER_WRITER_NONREC \n");
 
                 if (!track_rt)
                         fprintf(stderr,
@@ -992,7 +996,7 @@ int pthread_mutex_destroy(pthread_mutex_t *mutex) {
         return real_pthread_mutex_destroy(mutex);
 }
 
-static void mutex_lock(pthread_mutex_t *mutex, bool busy) {
+static void mutex_lock(pthread_mutex_t *mutex, bool busy, uint64_t nsec_contended) {
         struct mutex_info *mi;
         pid_t tid;
 
@@ -1013,8 +1017,10 @@ static void mutex_lock(pthread_mutex_t *mutex, bool busy) {
         mi->n_lock_level++;
         mi->n_locked++;
 
-        if (busy)
+        if (busy) {
                 mi->n_contended++;
+                mi->nsec_contended_total += nsec_contended;
+        }
 
         tid = _gettid();
         if (mi->last_owner != tid) {
@@ -1036,6 +1042,7 @@ static void mutex_lock(pthread_mutex_t *mutex, bool busy) {
 int pthread_mutex_lock(pthread_mutex_t *mutex) {
         int r;
         bool busy;
+        uint64_t wait_time = 0;
 
         if (UNLIKELY(!initialized && recursive)) {
                 /* During the initialization phase we might be called
@@ -1056,19 +1063,24 @@ int pthread_mutex_lock(pthread_mutex_t *mutex) {
                 return r;
 
         if (UNLIKELY((busy = (r == EBUSY)))) {
+                uint64_t start_time = nsec_now();
+
                 r = real_pthread_mutex_lock(mutex);
 
+                wait_time = nsec_now() - start_time;
+
                 if (UNLIKELY(r != 0))
                         return r;
         }
 
-        mutex_lock(mutex, busy);
+        mutex_lock(mutex, busy, wait_time);
         return r;
 }
 
 int pthread_mutex_timedlock(pthread_mutex_t *mutex, const struct timespec *abstime) {
         int r;
         bool busy;
+        uint64_t wait_time = 0;
 
         if (UNLIKELY(!initialized && recursive)) {
                 assert(!threads_existing);
@@ -1082,15 +1094,19 @@ int pthread_mutex_timedlock(pthread_mutex_t *mutex, const struct timespec *absti
                 return r;
 
         if (UNLIKELY((busy = (r == EBUSY)))) {
+                uint64_t start_time = nsec_now();
+
                 r = real_pthread_mutex_timedlock(mutex, abstime);
 
+                wait_time = nsec_now() - start_time;
+
                 if (UNLIKELY(r == ETIMEDOUT))
                         busy = true;
                 else if (UNLIKELY(r != 0))
                         return r;
         }
 
-        mutex_lock(mutex, busy);
+        mutex_lock(mutex, busy, wait_time);
         return r;
 }
 
@@ -1108,7 +1124,7 @@ int pthread_mutex_trylock(pthread_mutex_t *mutex) {
         if (UNLIKELY(r != 0))
                 return r;
 
-        mutex_lock(mutex, false);
+        mutex_lock(mutex, false, 0);
         return r;
 }
 
@@ -1168,7 +1184,7 @@ int pthread_cond_wait(pthread_cond_t *cond, pthread_mutex_t *mutex) {
 
         /* Unfortunately we cannot distuingish mutex contention and
          * the condition not being signalled here. */
-        mutex_lock(mutex, false);
+        mutex_lock(mutex, false, 0);
 
         return r;
 }
@@ -1182,7 +1198,7 @@ int pthread_cond_timedwait(pthread_cond_t *cond, pthread_mutex_t *mutex, const s
 
         mutex_unlock(mutex);
         r = real_pthread_cond_timedwait(cond, mutex, abstime);
-        mutex_lock(mutex, false);
+        mutex_lock(mutex, false, 0);
 
         return r;
 }
@@ -1370,7 +1386,7 @@ int pthread_rwlock_destroy(pthread_rwlock_t *rwlock) {
         return real_pthread_rwlock_destroy(rwlock);
 }
 
-static void rwlock_lock(pthread_rwlock_t *rwlock, bool for_write, bool busy) {
+static void rwlock_lock(pthread_rwlock_t *rwlock, bool for_write, bool busy, uint64_t nsec_contended) {
         struct mutex_info *mi;
         pid_t tid;
 
@@ -1391,9 +1407,15 @@ static void rwlock_lock(pthread_rwlock_t *rwlock, bool for_write, bool busy) {
         mi->n_lock_level++;
         mi->n_locked++;
 
-        if (busy)
+        if (busy) {
                 mi->n_contended++;
 
+                if (for_write)
+                        mi->nsec_write_contended_total += nsec_contended;
+                else
+                        mi->nsec_read_contended_total += nsec_contended;
+        }
+
         tid = _gettid();
         if (mi->last_owner != tid) {
                 if (mi->last_owner != 0)
@@ -1414,6 +1436,7 @@ static void rwlock_lock(pthread_rwlock_t *rwlock, bool for_write, bool busy) {
 int pthread_rwlock_rdlock(pthread_rwlock_t *rwlock) {
         int r;
         bool busy;
+        uint64_t wait_time = 0;
 
         if (UNLIKELY(!initialized && recursive)) {
                 assert(!threads_existing);
@@ -1427,15 +1450,19 @@ int pthread_rwlock_rdlock(pthread_rwlock_t *rwlock) {
                 return r;
 
         if (UNLIKELY((busy = (r == EBUSY)))) {
+                uint64_t start_time = nsec_now();
+
                 r = real_pthread_rwlock_rdlock(rwlock);
 
+                wait_time = nsec_now() - start_time;
+
                 if (UNLIKELY(r == ETIMEDOUT))
                         busy = true;
                 else if (UNLIKELY(r != 0))
                         return r;
         }
 
-        rwlock_lock(rwlock, false, busy);
+        rwlock_lock(rwlock, false, busy, wait_time);
         return r;
 }
 
@@ -1453,13 +1480,14 @@ int pthread_rwlock_tryrdlock(pthread_rwlock_t *rwlock) {
         if (UNLIKELY(r != EBUSY && r != 0))
                 return r;
 
-        rwlock_lock(rwlock, false, false);
+        rwlock_lock(rwlock, false, false, 0);
         return r;
 }
 
 int pthread_rwlock_timedrdlock(pthread_rwlock_t *rwlock, const struct timespec *abstime) {
         int r;
         bool busy;
+        uint64_t wait_time = 0;
 
         if (UNLIKELY(!initialized && recursive)) {
                 assert(!threads_existing);
@@ -1473,21 +1501,26 @@ int pthread_rwlock_timedrdlock(pthread_rwlock_t *rwlock, const struct timespec *
                 return r;
 
         if (UNLIKELY((busy = (r == EBUSY)))) {
+                uint64_t start_time = nsec_now();
+
                 r = real_pthread_rwlock_timedrdlock(rwlock, abstime);
 
+                wait_time = nsec_now() - start_time;
+
                 if (UNLIKELY(r == ETIMEDOUT))
                         busy = true;
                 else if (UNLIKELY(r != 0))
                         return r;
         }
 
-        rwlock_lock(rwlock, false, busy);
+        rwlock_lock(rwlock, false, busy, wait_time);
         return r;
 }
 
 int pthread_rwlock_wrlock(pthread_rwlock_t *rwlock) {
         int r;
         bool busy;
+        uint64_t wait_time = 0;
 
         if (UNLIKELY(!initialized && recursive)) {
                 assert(!threads_existing);
@@ -1501,15 +1534,19 @@ int pthread_rwlock_wrlock(pthread_rwlock_t *rwlock) {
                 return r;
 
         if (UNLIKELY((busy = (r == EBUSY)))) {
+                uint64_t start_time = nsec_now();
+
                 r = real_pthread_rwlock_wrlock(rwlock);
 
+                wait_time = nsec_now() - start_time;
+
                 if (UNLIKELY(r == ETIMEDOUT))
                         busy = true;
                 else if (UNLIKELY(r != 0))
                         return r;
         }
 
-        rwlock_lock(rwlock, true, busy);
+        rwlock_lock(rwlock, true, busy, wait_time);
         return r;
 }
 
@@ -1527,13 +1564,14 @@ int pthread_rwlock_trywrlock(pthread_rwlock_t *rwlock) {
         if (UNLIKELY(r != EBUSY && r != 0))
                 return r;
 
-        rwlock_lock(rwlock, true, false);
+        rwlock_lock(rwlock, true, false, 0);
         return r;
 }
 
 int pthread_rwlock_timedwrlock(pthread_rwlock_t *rwlock, const struct timespec *abstime) {
         int r;
         bool busy;
+        uint64_t wait_time = 0;
 
         if (UNLIKELY(!initialized && recursive)) {
                 assert(!threads_existing);
@@ -1547,15 +1585,19 @@ int pthread_rwlock_timedwrlock(pthread_rwlock_t *rwlock, const struct timespec *
                 return r;
 
         if (UNLIKELY((busy = (r == EBUSY)))) {
+                uint64_t start_time = nsec_now();
+
                 r = real_pthread_rwlock_timedwrlock(rwlock, abstime);
 
+                wait_time = nsec_now() - start_time;
+
                 if (UNLIKELY(r == ETIMEDOUT))
                         busy = true;
                 else if (UNLIKELY(r != 0))
                         return r;
         }
 
-        rwlock_lock(rwlock, true, busy);
+        rwlock_lock(rwlock, true, busy, wait_time);
         return r;
 }