title: Measuring mutex contention / interpreting mutrace output
body: <p>I'm trying to measure mutex contention in my program with mutrace, but am stuck as to how to use the report it outputs.</p>
  
  <pre><code>mutrace: Showing statistics for process test (PID: 5924).
  mutrace: 1223 mutexes used.
  
  Mutex #362 (0x0x1a23750) first referenced by:
          /usr/local/lib/libmutrace.so(pthread_mutex_init+0x1b2) [0x7fb6b14129b4]
          ./test() [0x500042]
  
  Mutex #390 (0x0x1a23ac0) first referenced by:
          /usr/local/lib/libmutrace.so(pthread_mutex_init+0x1b2) [0x7fb6b14129b4]
          ./test() [0x500042]
  
  Mutex #965 (0x0x1a3a600) first referenced by:
          /usr/local/lib/libmutrace.so(pthread_mutex_init+0x1b2) [0x7fb6b14129b4]
          ./test() [0x500042]
  
  Mutex #502 (0x0x1abbc90) first referenced by:
          /usr/local/lib/libmutrace.so(pthread_mutex_init+0x1b2) [0x7fb6b14129b4]
          ./test() [0x500042]
  
  Mutex #241 (0x0x7fb6af9019c0) first referenced by:
          /usr/local/lib/libmutrace.so(pthread_mutex_lock+0x116) [0x7fb6b1412da6]
          /lib/libgcc_s.so.1(_Unwind_Find_FDE+0x2a) [0x7fb6af6fe3ea]
          [(nil)]
  
  Mutex #704 (0x0x7fb6afe85020) first referenced by:
          /usr/local/lib/libmutrace.so(pthread_mutex_lock+0x116) [0x7fb6b1412da6]
          /usr/lib/libstdc++.so.6(_ZNSt6localeC1Ev+0x2f) [0x7fb6afbf021f]
  
  Mutex #452 (0x0x1a240b0) first referenced by:
          /usr/local/lib/libmutrace.so(pthread_mutex_init+0x1b2) [0x7fb6b14129b4]
          ./test() [0x500042]
  
  Mutex #981 (0x0x1a3a770) first referenced by:
          /usr/local/lib/libmutrace.so(pthread_mutex_init+0x1b2) [0x7fb6b14129b4]
          ./test() [0x500042]
  
  Mutex #626 (0x0x73daa8) first referenced by:
          /usr/local/lib/libmutrace.so(pthread_mutex_init+0x1b2) [0x7fb6b14129b4]
          ./test(_ZN7threads5mutexC2Eb+0x5e) [0x50675e]
  
  Mutex #801 (0x0x1ab6798) first referenced by:
          /usr/local/lib/libmutrace.so(pthread_mutex_init+0x1b2) [0x7fb6b14129b4]
          ./test(_ZN7threads5mutexC1Eb+0x5e) [0x50643e]
  
  mutrace: Showing 10 mutexes in order of (write) contention count:
  
   Mutex #   Locked  Changed    Cont. cont.Time[ms] tot.Time[ms] avg.Time[ms] Flags
       362   517216   163871    70638       619.184      138.933        0.000 M-.--.
       390   180589    61197    31681      5926.827      463.255        0.003 M-.--.
       965    38679    24052    10646       661.639      718.836        0.019 M-.--.
       502    35394    19012     1540       153.286      134.116        0.004 M-.--.
       241     3481     2715     1378       135.624        1.189        0.000 M-.--.
       704    20902     3879       70         0.594        6.702        0.000 M-.--.
       452      892      158       49        21.401      125.918        0.141 M-.--.
       981     2369     2361       12         0.229       12.984        0.005 M-.--.
       626      598      270        4         0.139        8.417        0.014 Mx.r-.
       801      125        2        1         0.012        0.270        0.002 Mx.r-.
       ...      ...      ...      ...           ...          ...          ... ||||||
                                                                              /|||||
            Object:                                      M = Mutex, W = RWLock /||||
             State:                                  x = dead, ! = inconsistent /|||
               Use:                                  R = used in realtime thread /||
        Mutex Type:                   r = RECURSIVE, e = ERRORCHECK, a = ADAPTIVE /|
    Mutex Protocol:                                       i = INHERIT, p = PROTECT /
       RWLock Kind:  r = PREFER_READER, w = PREFER_WRITER, W = PREFER_WRITER_NONREC 
  
  mutrace: Note that rwlocks are shown as two lines: write locks then read locks.
  
  mutrace: Note that the flags column R is only valid in --track-rt mode!
  
  mutrace: 275 condition variables used.
  
  Condvar #235 (0x0x7fb6a039d5c8) first referenced by:
          /usr/local/lib/libmutrace.so(pthread_cond_init+0x120) [0x7fb6b14134be]
          ./test(_ZN7threads4condC1Ev+0x17) [0x5051b7]
  
  Condvar #153 (0x0x7fb6a8259978) first referenced by:
          /usr/local/lib/libmutrace.so(pthread_cond_init+0x120) [0x7fb6b14134be]
          ./test(_ZN7threads4condC1Ev+0x17) [0x5051b7]
  
  Condvar #42 (0x0x7fb6a03e8188) first referenced by:
          /usr/local/lib/libmutrace.so(pthread_cond_init+0x120) [0x7fb6b14134be]
          ./test(_ZN7threads4condC1Ev+0x17) [0x5051b7]
  
  Condvar #222 (0x0x7fb6a019b7c8) first referenced by:
          /usr/local/lib/libmutrace.so(pthread_cond_init+0x120) [0x7fb6b14134be]
          ./test(_ZN7threads4condC1Ev+0x17) [0x5051b7]
  
  Condvar #118 (0x0x7fb6a0223ca8) first referenced by:
          /usr/local/lib/libmutrace.so(pthread_cond_init+0x120) [0x7fb6b14134be]
          ./test(_ZN7threads4condC1Ev+0x17) [0x5051b7]
  
  Condvar #8 (0x0x7fb6a820d748) first referenced by:
          /usr/local/lib/libmutrace.so(pthread_cond_init+0x120) [0x7fb6b14134be]
          ./test(_ZN7threads4condC1Ev+0x17) [0x5051b7]
  
  Condvar #171 (0x0x7fb69c04d9d8) first referenced by:
          /usr/local/lib/libmutrace.so(pthread_cond_init+0x120) [0x7fb6b14134be]
          ./test(_ZN7threads4condC1Ev+0x17) [0x5051b7]
  
  Condvar #0 (0x0x7fb69c22a2e8) first referenced by:
          /usr/local/lib/libmutrace.so(pthread_cond_init+0x120) [0x7fb6b14134be]
          ./test(_ZN7threads4condC1Ev+0x17) [0x5051b7]
  
  Condvar #75 (0x0x7fb6a81a65f8) first referenced by:
          /usr/local/lib/libmutrace.so(pthread_cond_init+0x120) [0x7fb6b14134be]
          ./test(_ZN7threads4condC1Ev+0x17) [0x5051b7]
  
  Condvar #142 (0x0x7fb6a001c308) first referenced by:
          /usr/local/lib/libmutrace.so(pthread_cond_init+0x120) [0x7fb6b14134be]
          ./test(_ZN7threads4condC1Ev+0x17) [0x5051b7]
  
  mutrace: Showing 10 condition variables in order of wait contention count:
  
    Cond #    Waits  Signals    Cont. tot.Time[ms] cont.Time[ms] avg.Time[ms] Flags
       235      271        0        0     1370.469         0.000        0.000     x.
       153      190        0        0      960.142         0.000        0.000     x.
        42       65        0        0      328.264         0.000        0.000     x.
       222       52        0        0      262.584         0.000        0.000     x.
       118       51        0        0      261.869         0.000        0.000     x.
         8       48        0        0      242.422         0.000        0.000     x.
       171       41        0        0      207.044         0.000        0.000     x.
         0       38        0        0      191.881         0.000        0.000     x.
        75       37        0        0      186.835         0.000        0.000     x.
       142       35        0        0      176.704         0.000        0.000     x.
       ...      ...      ...      ...          ...           ...          ...     ||
                                                                                  /|
             State:                                     x = dead, ! = inconsistent /
               Use:                                     R = used in realtime thread 
  
  mutrace: Note that the flags column R is only valid in --track-rt mode!
  
  mutrace: Total runtime is 3701.228 ms.
  
  mutrace: Results for SMP with 8 processors.
  </code></pre>
  
  <p>It seems I definitely have a mutex contention problem, but I don't know how to correlate this back to my source code. I was hoping for better back traces then this.</p>
  
  <p>The executable has been compiled with -rdynamic as per mutrace's website (and -g -gdb also).</p>
  
  <p>I discovered mutrace here on stackoverflow, so hopefully there's some people with experience!</p>
  
  <p>Thanks.</p>