Measuring mutex contention / interpreting mutrace output
https://stackoverflow.com/questions/11718997
-
23-06-2021 - |
italiano
english
français
española
中国
日本の
العربية
Deutsch
한국어
Português
RussianQuestion
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.
Solution 2
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.
OTHER TIPS
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.
