Analyze the current lock contention
I've hacked mutrace
and named
to work again together and here are current results:
mutrace: Showing statistics for process named (PID: 1782915).
mutrace: 1802520 mutexes used.
Mutex #1326836 (0x0x55ec3f8dd640) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_init+0xe8) [0x7fc95d0d87a8]
/home/ondrej/Projects/bind9/lib/dns/.libs/libdns-9.19.6-dev.so(dns_sdb_register+0xb7) [0x7fc95ca55f32]
Mutex #1332002 (0x0x55ec3fa3b4e0) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_init+0xe8) [0x7fc95d0d87a8]
/home/ondrej/Projects/bind9/lib/isc/.libs/libisc-9.19.6-dev.so(isc__task_create+0xbd) [0x7fc95cb98aee]
Mutex #1329994 (0x0x55ec3f9cea68) first referenced by:
/usr/local/lib/libmutrace.so(pthread_rwlock_init+0xca) [0x7fc95d0d942a]
/home/ondrej/Projects/bind9/lib/dns/.libs/libdns-9.19.6-dev.so(dns_rbtdb_create+0xfe) [0x7fc95c9e4cfc]
Mutex #1332378 (0x0x55ec3fa5b7a8) first referenced by:
/usr/local/lib/libmutrace.so(pthread_rwlock_init+0xca) [0x7fc95d0d942a]
/home/ondrej/Projects/bind9/lib/dns/.libs/libdns-9.19.6-dev.so(dns_adb_create+0x120) [0x7fc95c951561]
Mutex #1332379 (0x0x55ec3fa5bd30) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_init+0xe8) [0x7fc95d0d87a8]
/home/ondrej/Projects/bind9/lib/isc/.libs/libisc-9.19.6-dev.so(isc__task_create+0xbd) [0x7fc95cb98aee]
Mutex #1327168 (0x0x55ec3f8f9558) first referenced by:
/usr/local/lib/libmutrace.so(pthread_rwlock_init+0xca) [0x7fc95d0d942a]
/home/ondrej/Projects/bind9/lib/dns/.libs/libdns-9.19.6-dev.so(dns_zonemgr_create+0x218) [0x7fc95caa36d6]
Mutex #1325497 (0x0x55ec3f841648) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_init+0xe8) [0x7fc95d0d87a8]
/home/ondrej/Projects/bind9/lib/isc/.libs/libisc-9.19.6-dev.so(+0x438b4) [0x7fc95cb8c8b4]
Mutex #78281 (0x0x7fc95d0d1fa0) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_lock+0x4c) [0x7fc95d0d89bc]
/usr/lib/x86_64-linux-gnu/libuv.so.1(uv_mutex_lock+0x9) [0x7fc95c3aa689]
Mutex #1330013 (0x0x55ec3f9cf2c0) first referenced by:
/usr/local/lib/libmutrace.so(pthread_rwlock_init+0xca) [0x7fc95d0d942a]
/home/ondrej/Projects/bind9/lib/dns/.libs/libdns-9.19.6-dev.so(dns_rbtdb_create+0x497) [0x7fc95c9e5095]
Mutex #1325525 (0x0x55ec3f843f48) first referenced by:
/usr/local/lib/libmutrace.so(pthread_mutex_init+0xe8) [0x7fc95d0d87a8]
/home/ondrej/Projects/bind9/lib/isc/.libs/libisc-9.19.6-dev.so(+0x411fe) [0x7fc95cb8a1fe]
mutrace: Showing 10 mutexes in order of (write) contention count:
Mutex # Changed Locked tot.Time[ms] avg.Time[ms] max.Time[ms] Cont. tot.Cont[ms] avg.Cont[ms] max.Cont[ms] Flags
1326836 959 3544 16.228 0.005 0.055 829 93.809 0.113 2.528 Mx.a-.
1332002 10563 942412 784.830 0.001 0.183 330 0.379 0.001 0.021 Mx.a-.
1329994 7845 141856 7.790 0.000 0.079 185 1.978 0.011 0.130 W!...r
(read) 989396 57.085 0.000 0.169 254 5.736 0.023 0.112 ||||||
1332378 4593 48592 1590.456 0.033 45.106 165 56.996 0.345 7.611 Wx...r
(read) 1 39.878 39.878 39.878 0 0.000 0.000 0.000 ||||||
1332379 23798 36940 37.882 0.001 0.101 108 0.210 0.002 0.081 Mx.a-.
1327168 133 314 24.442 0.078 0.276 96 8.554 0.089 0.534 Wx...r
(read) 2 1.013 0.507 0.760 0 0.000 0.000 0.000 ||||||
1325497 2107 1018717 828.111 0.001 0.207 65 0.115 0.002 0.015 Mx.a-.
78281 19 21 1.274 0.061 0.186 15 2.693 0.180 0.251 M-.--.
1330013 2650 41181 52.259 0.001 0.104 11 0.044 0.004 0.007 Wx...r
(read) 103766 96.121 0.001 0.130 8 0.099 0.012 0.049 ||||||
1325525 26482 30675 31.489 0.001 0.092 11 0.033 0.003 0.010 Mx.a-.
... ... ... ... ... ... ... ... ... ... ||||||
/|||||
Object: M = Mutex, W = RWLock, I = isc_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: 1 condition variables used.
mutrace: No condition variable contended according to filtering parameters.
mutrace: Total runtime is 185346.476 ms.
mutrace: Results for SMP with 8 processors.
mutrace: WARNING: 139919 inconsistent mutex uses detected. Results might not be reliable.
mutrace: Fix your program first!
mutrace: WARNING: 98 internal hash collisions detected. Results might not be as reliable as they could be.
mutrace: Try to increase --hash-size=, which is currently at 400000009.
mutrace: WARNING: 533 internal mutex contention detected. Results might not be reliable as they could be.
mutrace: Try to increase --hash-size=, which is currently at 400000009.