Measuring mutex contention / interpreting mutrace output

Question

I'm trying to measure mutex contention in my program with mutrace, but am stuck as to how to use the report it outputs.

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.

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.

The executable has been compiled with -rdynamic as per mutrace's website (and -g -gdb also).

I discovered mutrace here on stackoverflow, so hopefully there's some people with experience!

Thanks.

Short version: Go through each mutex that appears on the output. Think through what that mutex does and how much contention you could reasonable expect. For any mutex that shows more contention than you reasonably expected, decide if that contention is significant and if so, analyze the use of that mutex to see if there's some easy way to minimize the contention. — David Schwartz, Jul 30 '12 at 09:55
Yes, but using such a limited backtrace, how do I determine which mutex is which? Obviously it's using the addresses, but this is not something I have had to do before. How do I go about it? — goji, Jul 30 '12 at 21:39
I'm not sure why you're getting such a limited backtrace. Worst case, you can add code to log the addresses of your mutexes. — David Schwartz, Jul 30 '12 at 22:23

Folkert van Heusden · Answer 1 · 2012-07-31T12:24:37.900

Never worked with mutrace, but address to symbol conversion can be done with: addr2line

e.g.:

addr2line -e sysopview 0x5051b7

In this example "sysopview" is the path to the binary in which the address is supposed to be located and 0x5051b7 is the example address. Addr2line will then emit the name it thinks should map to it. Works with backtraces as well.

Example output:

folkert@belle:~/Projects/entropybroker/trunk$ addr2line -e ./entropy_broker 0x0000000000406968 /home/folkert/Projects/entropybroker/trunk/handle_client.cpp:761

In this example the address 0x406968 maps to file handle_client.cpp line 761.

On Debian this program can be found in the "binutils" package.

score 3 · Accepted Answer · answered Jul 31 '12 at 03:09

I leave the debugging flags on in my realease build, so -g -gdb -rdynamic were all enabled. I figured this would be okay. After switching back to my debug build, the removal of -O2 made the backtraces more useful. Still mangled, but much better.

I've discovered all my mutexes with the highest contention are all being used for synchronisation in the gcrypt lib used by gnutls. Might have to experiment and see if going back to openssl improves it, or maybe cyassl!

Thanks.

Indeed removing optimization (i.e. using -`O0`) makes the stack traces more "verbose" — Shmil The Cat, Aug 12 '21 at 22:38

Measuring mutex contention / interpreting mutrace output

2 Answers2