LOCK TRACE
table of contents
Please note: the colors are only used for easier reading, they don't have a special meaning.
meta data
durations
errors
double lock/unlock mutexes
still locked mutexes
double lock/unlock r/w-locks
still locked r/w-locks
where are locks used
correlations between locks
The "tid" is the thread identifier of the thread that triggered a measurement.
meta data executable /home/folkert/Projects/lock_tracer/build/test PID 89812 scheduler sched-other host name lappiemctopface core file /tmp/core-main-6-1000-1000-89812-1639996891 trace file dump.dat.89812 # trace records 15251343 (90.91%, 4.10%/s) fork warning false # cores 4 started at 1639996868.032641172 (2021-12-20 11:41:08.32640919) stopped at 1639996890.203887701 (2021-12-20 11:41:30.203887492) took 22.171247s
counts
# mutex try-locks 1 # rwlock try-rdlock 1 # rwlock try-timed-rdlock 1 # rwlock try-wrlock 1 # rwlock try-timed-rwlock 1 failed mutex destroy 0 failed mutex init 0 failed mutex locks 1 failed mutex unlocks 0 failed pthread_clean 0 failed rw destroy 0 failed rw init 0 failed rw read lock 2 failed rw unlock 0 failed rw write lock 3 mutex destroy 0 mutex init 4 mutex locks 7361738 mutex unlocks 7889581 pthread_clean 0 rw destroy 0 rw init 0 rw read lock 4 rw unlock 8 rw write lock 2
2. acquisition durations
How long it took before a mutex (or r/w-lock) was acquired. This takes longer if an other thread is already holding it and doesn't immediately return it.
Also shown is, how long mutex was held on average. 'sd' is the standard deviation.
mutex avg: 0.521us, sd: 23.693us mutex held avg: 3.634us, sd: 1122.081us read lock avg: 0.047us, sd: 0.030us write lock avg: 0.370us, sd: 320.000us
per mutex durations
acquiration duration
pointer average standard deviation 0x00005615a3680040/test (.bss)/??:0/ 536.000us 0.000us 0x00007fedd82001a0/()+0x101a0/??:0/ 384.000us 0.000us 0x00007fedd8204398/()+0x14398/??:0/ 60.491us 4827.144us 0x00007fedd820aa80/()+0x1aa80/??:0/ 98.739us 91.636us 0x00007ffd8455d390/??/??:0/ 417811.423us 559825.385us 0x00007ffd8455d3c0/??/??:0/ 353.000us 0.000us 0x00007ffd8455d3f0/??/??:0/ 72.641us 121.384us 0x00007ffd8455d400/??/??:0/ 65.000us 0.000us 0x00007ffd8455d420/??/??:0/ 27.285us 83.137us
mutex held duration
pointer average standard deviation 0x00005615a3680040/test (.bss)/??:0/ 40251.000us 0.000us 0x00007fedd82001a0/()+0x101a0/??:0/ 112106.000us 0.000us 0x00007fedd8204398/()+0x14398/??:0/ 689.648us 905193.350us 0x00007fedd820aa80/()+0x1aa80/??:0/ 2204.077us 17377.393us 0x00007ffd8455d390/??/??:0/ 2456101.417us 19592147.290us 0x00007ffd8455d3f0/??/??:0/ 61392.560us 583404.706us 0x00007ffd8455d400/??/??:0/ 501368772.000us 0.000us 0x00007ffd8455d420/??/??:0/ 8413.764us 62623.228us
per r/w lock durations
read lock acquiration duration
pointer r/w average standard deviation 0x00007ffd8455d430/??/??:0/ 43.333us 33.639us 0x00007ffd8455d440/??/??:0/ 59.000us 0.000us
write lock acquiration duration
pointer r/w average standard deviation 0x00007ffd8455d440/??/??:0/ 370.000us 320.000us
r/w-lock held duration
pointer r/w> average standard deviation 0x00007ffd8455d440/??/??:0/ r 24727.000us 0.000us w 27939.000us 14916.823us
3. function call errors
pthread_-functions can fail, they then return an errno-alike error code. In this section, all that occured (for the ones checked, like mutex errors etc) are listed.
Count: 4
Resource temporarily unavailable
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.702157136 took 0.065us call trace
0x7fedd84716fd 0x00007fedd84716fd/??/??:0/ 0x7fedd8471c59 0x00007fedd8471c59/??/??:0/ 0x5615a367db8b 0x00005615a367db8b/test_rwlock+0x9b (.text)//home/folkert/Projects/lock_tracer/test.c:147:2/ 0x5615a367d3d8 0x00005615a367d3d8/main+0x18 (.text)//home/folkert/Projects/lock_tracer/test.c:203:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.702180606 took 0.045us call trace
0x7fedd84716fd 0x00007fedd84716fd/??/??:0/ 0x7fedd8471c59 0x00007fedd8471c59/??/??:0/ 0x5615a367db93 0x00005615a367db93/test_rwlock+0xa3 (.text)//home/folkert/Projects/lock_tracer/test.c:149:2/ 0x5615a367d3d8 0x00005615a367d3d8/main+0x18 (.text)//home/folkert/Projects/lock_tracer/test.c:203:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
Device or resource busy
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.702320958 took 0.000us call trace
0x7fedd84716fd 0x00007fedd84716fd/??/??:0/ 0x7fedd8472a4e 0x00007fedd8472a4e/??/??:0/ 0x5615a367dc3b 0x00005615a367dc3b/test_try_lock+0x6b (.text)//home/folkert/Projects/lock_tracer/test.c:165:18/ 0x5615a367d3df 0x00005615a367d3df/main+0x1f (.text)//home/folkert/Projects/lock_tracer/test.c:205:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
Resource deadlock avoided
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.536292605 took 0.558us call trace
0x7fedd8471d62 0x00007fedd8471d62/??/??:0/ 0x7fedd84721c7 0x00007fedd84721c7/??/??:0/ 0x5615a367da6f 0x00005615a367da6f/test_mutex+0x2bf (.text)//home/folkert/Projects/lock_tracer/test.c:120:16/ 0x5615a367d3d1 0x00005615a367d3d1/main+0x11 (.text)//home/folkert/Projects/lock_tracer/test.c:201:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.702080483 took 0.052us call trace
0x7fedd84716fd 0x00007fedd84716fd/??/??:0/ 0x7fedd8471b39 0x00007fedd8471b39/??/??:0/ 0x5615a367db6b 0x00005615a367db6b/test_rwlock+0x7b (.text)//home/folkert/Projects/lock_tracer/test.c:142:2/ 0x5615a367d3d8 0x00005615a367d3d8/main+0x18 (.text)//home/folkert/Projects/lock_tracer/test.c:203:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
Connection timed out
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.702382172 took 12.652us call trace
0x7fedd84716fd 0x00007fedd84716fd/??/??:0/ 0x7fedd8472b38 0x00007fedd8472b38/??/??:0/ 0x5615a367dc59 0x00005615a367dc59/test_try_lock+0x89 (.text)//home/folkert/Projects/lock_tracer/test.c:169:1/ 0x5615a367d3df 0x00005615a367d3df/main+0x1f (.text)//home/folkert/Projects/lock_tracer/test.c:205:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
4. mutex lock/unlock mistakes
Mistakes are: locking a mutex another time by the same thread, unlocking mutexes that are not locked and unlocking of a mutex by some other thread than the one who locked the mutex.
This section contains a list of all the seen mutex/error-type combinations and then for each the mistakes made and then one or more backtraces ("first" and "next") where they occured.
Count: 4
mutex 0x5615a3680040, type "not locked"
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:18.35263837 took 0.000us call trace
0x7fedd8471d62 0x00007fedd8471d62/??/??:0/ 0x7fedd8472733 0x00007fedd8472733/??/??:0/ 0x5615a367d8dd 0x00005615a367d8dd/test_mutex+0x12d (.text)//home/folkert/Projects/lock_tracer/test.c:85:2/ 0x5615a367d3d1 0x00005615a367d3d1/main+0x11 (.text)//home/folkert/Projects/lock_tracer/test.c:201:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
mutex 0x7ffd8455d390, type "already locked"
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.535657752 took 0.000us call trace
0x7fedd8471d62 0x00007fedd8471d62/??/??:0/ 0x7fedd84726bb 0x00007fedd84726bb/??/??:0/ 0x5615a367da2e 0x00005615a367da2e/test_mutex+0x27e (.text)//home/folkert/Projects/lock_tracer/test.c:109:2/ 0x5615a367d3d1 0x00005615a367d3d1/main+0x11 (.text)//home/folkert/Projects/lock_tracer/test.c:201:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.535536519 took 0.283us call trace
0x7fedd8471d62 0x00007fedd8471d62/??/??:0/ 0x7fedd84721c7 0x00007fedd84721c7/??/??:0/ 0x5615a367da1e 0x00005615a367da1e/test_mutex+0x26e (.text)//home/folkert/Projects/lock_tracer/test.c:105:2/ 0x5615a367d3d1 0x00005615a367d3d1/main+0x11 (.text)//home/folkert/Projects/lock_tracer/test.c:201:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.535590139 took 0.143us call trace
0x7fedd8471d62 0x00007fedd8471d62/??/??:0/ 0x7fedd84721c7 0x00007fedd84721c7/??/??:0/ 0x5615a367da26 0x00005615a367da26/test_mutex+0x276 (.text)//home/folkert/Projects/lock_tracer/test.c:107:2/ 0x5615a367d3d1 0x00005615a367d3d1/main+0x11 (.text)//home/folkert/Projects/lock_tracer/test.c:201:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
mutex 0x7ffd8455d390, type "not locked"
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.536025028 took 0.000us call trace
0x7fedd8471d62 0x00007fedd8471d62/??/??:0/ 0x7fedd8472733 0x00007fedd8472733/??/??:0/ 0x5615a367da3e 0x00005615a367da3e/test_mutex+0x28e (.text)//home/folkert/Projects/lock_tracer/test.c:111:2/ 0x5615a367d3d1 0x00005615a367d3d1/main+0x11 (.text)//home/folkert/Projects/lock_tracer/test.c:201:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.536084923 took 0.000us call trace
0x7fedd8471d62 0x00007fedd8471d62/??/??:0/ 0x7fedd8472733 0x00007fedd8472733/??/??:0/ 0x5615a367da46 0x00005615a367da46/test_mutex+0x296 (.text)//home/folkert/Projects/lock_tracer/test.c:112:2/ 0x5615a367d3d1 0x00005615a367d3d1/main+0x11 (.text)//home/folkert/Projects/lock_tracer/test.c:201:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.536127132 took 0.000us call trace
0x7fedd8471d62 0x00007fedd8471d62/??/??:0/ 0x7fedd8472733 0x00007fedd8472733/??/??:0/ 0x5615a367da4e 0x00005615a367da4e/test_mutex+0x29e (.text)//home/folkert/Projects/lock_tracer/test.c:114:2/ 0x5615a367d3d1 0x00005615a367d3d1/main+0x11 (.text)//home/folkert/Projects/lock_tracer/test.c:201:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
mutex 0x7ffd8455d420, type "not locked"
first
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:18.35831552 took 0.000us call trace
0x7fedd8471d62 0x00007fedd8471d62/??/??:0/ 0x7fedd8472733 0x00007fedd8472733/??/??:0/ 0x5615a367d974 0x00005615a367d974/test_mutex+0x1c4 (.text)//home/folkert/Projects/lock_tracer/test.c:99:3/ 0x5615a367d3d1 0x00005615a367d3d1/main+0x11 (.text)//home/folkert/Projects/lock_tracer/test.c:201:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
next
Mistake count: 175947 (total number of backtraces seen; note that the list below is de-duplicated).
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:18.36026859 took 0.000us call trace
0x7fedd8471d62 0x00007fedd8471d62/??/??:0/ 0x7fedd8472733 0x00007fedd8472733/??/??:0/ 0x5615a367d974 0x00005615a367d974/test_mutex+0x1c4 (.text)//home/folkert/Projects/lock_tracer/test.c:99:3/ 0x5615a367d3d1 0x00005615a367d3d1/main+0x11 (.text)//home/folkert/Projects/lock_tracer/test.c:201:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
first
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:18.35794505 took 0.000us call trace
0x7fedd8471d62 0x00007fedd8471d62/??/??:0/ 0x7fedd8472733 0x00007fedd8472733/??/??:0/ 0x5615a367d96c 0x00005615a367d96c/test_mutex+0x1bc (.text)//home/folkert/Projects/lock_tracer/test.c:98:3/ 0x5615a367d3d1 0x00005615a367d3d1/main+0x11 (.text)//home/folkert/Projects/lock_tracer/test.c:201:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
next
Mistake count: 175947 (total number of backtraces seen; note that the list below is de-duplicated).
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:18.35999687 took 0.000us call trace
0x7fedd8471d62 0x00007fedd8471d62/??/??:0/ 0x7fedd8472733 0x00007fedd8472733/??/??:0/ 0x5615a367d96c 0x00005615a367d96c/test_mutex+0x1bc (.text)//home/folkert/Projects/lock_tracer/test.c:98:3/ 0x5615a367d3d1 0x00005615a367d3d1/main+0x11 (.text)//home/folkert/Projects/lock_tracer/test.c:201:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
first
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:18.35880072 took 0.000us call trace
0x7fedd8471d62 0x00007fedd8471d62/??/??:0/ 0x7fedd8472733 0x00007fedd8472733/??/??:0/ 0x5615a367d97c 0x00005615a367d97c/test_mutex+0x1cc (.text)//home/folkert/Projects/lock_tracer/test.c:20:25/ 0x5615a367d3d1 0x00005615a367d3d1/main+0x11 (.text)//home/folkert/Projects/lock_tracer/test.c:201:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
next
Mistake count: 175947 (total number of backtraces seen; note that the list below is de-duplicated).
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:18.36066712 took 0.000us call trace
0x7fedd8471d62 0x00007fedd8471d62/??/??:0/ 0x7fedd8472733 0x00007fedd8472733/??/??:0/ 0x5615a367d97c 0x00005615a367d97c/test_mutex+0x1cc (.text)//home/folkert/Projects/lock_tracer/test.c:20:25/ 0x5615a367d3d1 0x00005615a367d3d1/main+0x11 (.text)//home/folkert/Projects/lock_tracer/test.c:201:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
5. still locked mutexes
A list of the mutexes that were still locked when the program terminated.
Count: 2
mutex 0x7ffd8455d390
The following location did not unlock:
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.536198587 took 0.174us call trace
0x7fedd8471d62 0x00007fedd8471d62/??/??:0/ 0x7fedd84721c7 0x00007fedd84721c7/??/??:0/ 0x5615a367da56 0x00005615a367da56/test_mutex+0x2a6 (.text)//home/folkert/Projects/lock_tracer/test.c:116:2/ 0x5615a367d3d1 0x00005615a367d3d1/main+0x11 (.text)//home/folkert/Projects/lock_tracer/test.c:201:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
mutex 0x7ffd8455d3c0
The following location did not unlock:
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.536252876 took 0.353us call trace
0x7fedd8471d62 0x00007fedd8471d62/??/??:0/ 0x7fedd84721c7 0x00007fedd84721c7/??/??:0/ 0x5615a367da62 0x00005615a367da62/test_mutex+0x2b2 (.text)//home/folkert/Projects/lock_tracer/test.c:117:2/ 0x5615a367d3d1 0x00005615a367d3d1/main+0x11 (.text)//home/folkert/Projects/lock_tracer/test.c:201:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
6. r/w-lock lock/unlock mistakes
Mistakes are: read-locking a r/w-lock another time by the same thread, unlocking r/w-locks that are not locked and unlocking of an r/w-lock by some other thread than the one who locked it.
This section contains a list of all the seen r/w-lock/error-type combinations and then for each the mistakes made and then one or more backtraces ("first" and "next") where they occured.
Count: 2
r/w-lock 0x7ffd8455d430, type "already locked"
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.702294116 took 0.000us call trace
0x7fedd84716fd 0x00007fedd84716fd/??/??:0/ 0x7fedd847289e 0x00007fedd847289e/??/??:0/ 0x5615a367dc33 0x00005615a367dc33/test_try_lock+0x63 (.text)//home/folkert/Projects/lock_tracer/test.c:163:2/ 0x5615a367d3df 0x00005615a367d3df/main+0x1f (.text)//home/folkert/Projects/lock_tracer/test.c:205:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.702342638 took 0.082us call trace
0x7fedd84716fd 0x00007fedd84716fd/??/??:0/ 0x7fedd8472988 0x00007fedd8472988/??/??:0/ 0x5615a367dc4e 0x00005615a367dc4e/test_try_lock+0x7e (.text)//home/folkert/Projects/lock_tracer/test.c:168:2/ 0x5615a367d3df 0x00005615a367d3df/main+0x1f (.text)//home/folkert/Projects/lock_tracer/test.c:205:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
r/w-lock 0x7ffd8455d440, type "not locked"
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.702120240 took 0.000us call trace
0x7fedd84716fd 0x00007fedd84716fd/??/??:0/ 0x7fedd8472bf3 0x00007fedd8472bf3/??/??:0/ 0x5615a367db7b 0x00005615a367db7b/test_rwlock+0x8b (.text)//home/folkert/Projects/lock_tracer/test.c:144:2/ 0x5615a367d3d8 0x00005615a367d3d8/main+0x18 (.text)//home/folkert/Projects/lock_tracer/test.c:203:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.702236748 took 0.000us call trace
0x7fedd84716fd 0x00007fedd84716fd/??/??:0/ 0x7fedd8472bf3 0x00007fedd8472bf3/??/??:0/ 0x5615a367dbab 0x00005615a367dbab/test_rwlock+0xbb (.text)//home/folkert/Projects/lock_tracer/test.c:152:1/ 0x5615a367d3d8 0x00005615a367d3d8/main+0x18 (.text)//home/folkert/Projects/lock_tracer/test.c:203:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.702200333 took 0.000us call trace
0x7fedd84716fd 0x00007fedd84716fd/??/??:0/ 0x7fedd8472bf3 0x00007fedd8472bf3/??/??:0/ 0x5615a367db9b 0x00005615a367db9b/test_rwlock+0xab (.text)//home/folkert/Projects/lock_tracer/test.c:150:2/ 0x5615a367d3d8 0x00005615a367d3d8/main+0x18 (.text)//home/folkert/Projects/lock_tracer/test.c:203:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.702217176 took 0.000us call trace
0x7fedd84716fd 0x00007fedd84716fd/??/??:0/ 0x7fedd8472bf3 0x00007fedd8472bf3/??/??:0/ 0x5615a367dba3 0x00005615a367dba3/test_rwlock+0xb3 (.text)//home/folkert/Projects/lock_tracer/test.c:151:2/ 0x5615a367d3d8 0x00005615a367d3d8/main+0x18 (.text)//home/folkert/Projects/lock_tracer/test.c:203:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.702140682 took 0.000us call trace
0x7fedd84716fd 0x00007fedd84716fd/??/??:0/ 0x7fedd8472bf3 0x00007fedd8472bf3/??/??:0/ 0x5615a367db83 0x00005615a367db83/test_rwlock+0x93 (.text)//home/folkert/Projects/lock_tracer/test.c:146:2/ 0x5615a367d3d8 0x00005615a367d3d8/main+0x18 (.text)//home/folkert/Projects/lock_tracer/test.c:203:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
7. still locked rwlocks
A list of the r/w-locks that were still locked when the program terminated.
Count: 1
rwlock 0x7ffd8455d430
One of the following locations did not unlock:
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.702264110 took 0.048us call trace
0x7fedd84716fd 0x00007fedd84716fd/??/??:0/ 0x7fedd8471c59 0x00007fedd8471c59/??/??:0/ 0x5615a367dc2b 0x00005615a367dc2b/test_try_lock+0x5b (.text)//home/folkert/Projects/lock_tracer/test.c:162:2/ 0x5615a367d3df 0x00005615a367d3df/main+0x1f (.text)//home/folkert/Projects/lock_tracer/test.c:205:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.702294116 took 0.000us call trace
0x7fedd84716fd 0x00007fedd84716fd/??/??:0/ 0x7fedd847289e 0x00007fedd847289e/??/??:0/ 0x5615a367dc33 0x00005615a367dc33/test_try_lock+0x63 (.text)//home/folkert/Projects/lock_tracer/test.c:163:2/ 0x5615a367d3df 0x00005615a367d3df/main+0x1f (.text)//home/folkert/Projects/lock_tracer/test.c:205:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
tid 89812 thread name test-mutex timestamp 2021-12-20 11:41:29.702342638 took 0.082us call trace
0x7fedd84716fd 0x00007fedd84716fd/??/??:0/ 0x7fedd8472988 0x00007fedd8472988/??/??:0/ 0x5615a367dc4e 0x00005615a367dc4e/test_try_lock+0x7e (.text)//home/folkert/Projects/lock_tracer/test.c:168:2/ 0x5615a367d3df 0x00005615a367d3df/main+0x1f (.text)//home/folkert/Projects/lock_tracer/test.c:205:2/ 0x7fedd8248fd0 0x00007fedd8248fd0/__libc_start_call_main+0x80 (.text)/../sysdeps/nptl/libc_start_call_main.h:58:16/ 0x7fedd824907d 0x00007fedd824907d/__libc_start_main@@GLIBC_2.34+0x7d (.text)/../csu/libc-start.c:128:20/ 0x5615a367d455 0x00005615a367d455/_start+0x25 (.text)/??:0/
8. where are locks used
0x00005615a3680040/test (.bss)/??:0/
0x00007fedd8471d62/??/??:0/
0x00007ffd8455d390/??/??:0/
0x00007fedd8471d62/??/??:0/
0x00007ffd8455d3c0/??/??:0/
0x00007fedd8471d62/??/??:0/
0x00007ffd8455d3f0/??/??:0/
0x00007fedd8471d62/??/??:0/
0x00007ffd8455d400/??/??:0/
0x00007fedd8471d62/??/??:0/
0x00007ffd8455d420/??/??:0/
0x00007fedd8471d62/??/??:0/
0x00007ffd8455d430/??/??:0/
0x00007fedd84716fd/??/??:0/
0x00007ffd8455d440/??/??:0/
0x00007fedd84716fd/??/??:0/
9. which locks might be correlated
%3
0x5615a3680040
0x5615a3680040
0x7fedd82001a0
0x7fedd82001a0
0x5615a3680040--0x7fedd82001a0
0x7fedd820aa80
0x7fedd820aa80
0x5615a3680040--0x7fedd820aa80
0x7ffd8455d3c0
0x7ffd8455d3c0
0x5615a3680040--0x7ffd8455d3c0
0x7ffd8455d390
0x7ffd8455d390
0x5615a3680040--0x7ffd8455d390
0x7ffd8455d440
0x7ffd8455d440
0x5615a3680040--0x7ffd8455d440
0x7ffd8455d420
0x7ffd8455d420
0x5615a3680040--0x7ffd8455d420
0x7ffd8455d430
0x7ffd8455d430
0x5615a3680040--0x7ffd8455d430
0x7ffd8455d400
0x7ffd8455d400
0x5615a3680040--0x7ffd8455d400
0x7ffd8455d3f0
0x7ffd8455d3f0
0x5615a3680040--0x7ffd8455d3f0
0x7fedd8204398
0x7fedd8204398
0x5615a3680040--0x7fedd8204398
0x7fedd82001a0--0x7fedd820aa80
0x7fedd82001a0--0x7ffd8455d3c0
0x7fedd82001a0--0x7ffd8455d390
0x7fedd82001a0--0x7ffd8455d440
0x7fedd82001a0--0x7ffd8455d420
0x7fedd82001a0--0x7ffd8455d430
0x7fedd82001a0--0x7ffd8455d400
0x7fedd82001a0--0x7ffd8455d3f0
0x7fedd82001a0--0x7fedd8204398
0x7fedd820aa80--0x7ffd8455d3c0
0x7fedd820aa80--0x7ffd8455d390
0x7fedd820aa80--0x7ffd8455d440
0x7fedd820aa80--0x7ffd8455d420
0x7fedd820aa80--0x7ffd8455d430
0x7fedd820aa80--0x7ffd8455d400
0x7fedd820aa80--0x7ffd8455d3f0
0x7ffd8455d3c0--0x7ffd8455d440
0x7ffd8455d3c0--0x7ffd8455d420
0x7ffd8455d3c0--0x7ffd8455d430
0x7ffd8455d3c0--0x7ffd8455d400
0x7ffd8455d3c0--0x7ffd8455d3f0
0x7ffd8455d390--0x7ffd8455d3c0
0x7ffd8455d390--0x7ffd8455d440
0x7ffd8455d390--0x7ffd8455d420
0x7ffd8455d390--0x7ffd8455d430
0x7ffd8455d390--0x7ffd8455d400
0x7ffd8455d390--0x7ffd8455d3f0
0x7ffd8455d420--0x7ffd8455d440
0x7ffd8455d420--0x7ffd8455d430
0x7ffd8455d430--0x7ffd8455d440
0x7ffd8455d400--0x7ffd8455d440
0x7ffd8455d400--0x7ffd8455d420
0x7ffd8455d400--0x7ffd8455d430
0x7ffd8455d3f0--0x7ffd8455d440
0x7ffd8455d3f0--0x7ffd8455d420
0x7ffd8455d3f0--0x7ffd8455d430
0x7ffd8455d3f0--0x7ffd8455d400
0x7fedd8204398--0x7fedd820aa80
0x7fedd8204398--0x7ffd8455d3c0
0x7fedd8204398--0x7ffd8455d390
0x7fedd8204398--0x7ffd8455d440
0x7fedd8204398--0x7ffd8455d420
0x7fedd8204398--0x7ffd8455d430
0x7fedd8204398--0x7ffd8455d400
0x7fedd8204398--0x7ffd8455d3f0
This locktracer is (C) 2021 by Folkert van Heusden <mail@vanheusden.com>