pt-sift doesnot seem to calculate the right mutexes

Reported by Kenny Gryp on 2011-09-30
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Toolkit
Undecided
Unassigned

Bug Description

pt-sift displays something like this:

--innodb--
    txns: 84xLOCK WAIT (405s) 163xACTIVE (9892s) 36xnot (0s)
    0 queries inside InnoDB, 0 queries in queue
    Main thread: making checkpoint, pending reads 1, writes 0, flush 0
    Log: lsn = 36623175066868, chkp = 36622450173415, chkp age = 724893453
    Threads are waiting at:
     32 trx0trx.c line 790
      7 trx0trx.c line 1767
      3 trx0trx.c line 1179
      2 trx0trx.c line 223
      2 row0sel.c line 3075
      2 row0ins.c line 2008
      2 lock0lock.c line 5120
      1 trx0trx.c line 2137
      1 trx0trx.c line 2114
      1 trx0purge.c line 391
      1 row0sel.c line 4801
      1 lock0lock.c line 5350
      1 btr0pcur.c line 426
      1 btr0cur.c line 546
    Threads are waiting on:
      2 X-lock on RW-latch at 0x2aaaaefc91b8 '&block->lock'
      2 S-lock on RW-latch at 0x2aaaaefc91b8 '&block->lock'
      1 S-lock on RW-latch at 0x2aaaee043638 '&block->lock'

while inndobstatus1 and innodbstatus2 contains a lot of &kernel_mutex semaphore waits:
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 13055816227, signal count 3164232053
--Thread 1264777536 has waited at btr0cur.c line 546 for 0.0000 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x2ab72a741a08 '&new_index->lock'
a writer (thread id 1264777536) has reserved it in mode wait exclusive
number of readers 5, waiters flag 0, lock_word: fffffffffffffffb
Last time read locked in file btr0cur.c line 553
Last time write locked in file /home/buildbot/slaves/percona-server-51-12/CentOS-5-x86-RPM_CentOS_5_x86_64/work/BUILD/Percona-Server-5.5.14-rel20.5/Percona-Server-5.5.14-rel20.5/storage/innobase/btr/btr0cur.c line 546
--Thread 1315363136 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1268771136 has waited at row0ins.c line 2008 for 0.0000 seconds the semaphore:
X-lock on RW-latch at 0x2aaaaefc91b8 '&block->lock'
a writer (thread id 1288206656) has reserved it in mode exclusive
number of readers 0, waiters flag 0, lock_word: 0
Last time read locked in file row0sel.c line 3075
Last time write locked in file /home/buildbot/slaves/percona-server-51-12/CentOS-5-x86-RPM_CentOS_5_x86_64/work/BUILD/Percona-Server-5.5.14-rel20.5/Percona-Server-5.5.14-rel20.5/storage/innobase/row/row0ins.c line 2008
--Thread 1272232256 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1346513216 has waited at lock0lock.c line 5120 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1348110656 has waited at row0ins.c line 2008 for 0.0000 seconds the semaphore:
X-lock on RW-latch at 0x2aaaaefc91b8 '&block->lock'
a writer (thread id 1288206656) has reserved it in mode exclusive
number of readers 0, waiters flag 0, lock_word: 0
Last time read locked in file row0sel.c line 3075
Last time write locked in file /home/buildbot/slaves/percona-server-51-12/CentOS-5-x86-RPM_CentOS_5_x86_64/work/BUILD/Percona-Server-5.5.14-rel20.5/Percona-Server-5.5.14-rel20.5/storage/innobase/row/row0ins.c line 2008
--Thread 1351838016 has waited at trx0trx.c line 1767 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1345182016 has waited at trx0trx.c line 2114 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1326278976 has waited at trx0purge.c line 391 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1281816896 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1285544256 has waited at trx0trx.c line 1767 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1348376896 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1333467456 has waited at trx0trx.c line 2137 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1316960576 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1327343936 has waited at row0sel.c line 4801 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1345714496 has waited at trx0trx.c line 1767 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1334266176 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1280751936 has waited at row0sel.c line 3075 for 0.0000 seconds the semaphore:
S-lock on RW-latch at 0x2aaaaefc91b8 '&block->lock'
a writer (thread id 1288206656) has reserved it in mode exclusive
number of readers 0, waiters flag 0, lock_word: 0
Last time read locked in file row0sel.c line 3075
Last time write locked in file /home/buildbot/slaves/percona-server-51-12/CentOS-5-x86-RPM_CentOS_5_x86_64/work/BUILD/Percona-Server-5.5.14-rel20.5/Percona-Server-5.5.14-rel20.5/storage/innobase/row/row0ins.c line 2008
--Thread 1298323776 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1343052096 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1269303616 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1306310976 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1293265216 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1310038336 has waited at lock0lock.c line 5120 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1341987136 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1306044736 has waited at trx0trx.c line 223 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1272498496 has waited at row0sel.c line 3075 for 0.0000 seconds the semaphore:
S-lock on RW-latch at 0x2aaaaefc91b8 '&block->lock'
a writer (thread id 1288206656) has reserved it in mode exclusive
number of readers 0, waiters flag 0, lock_word: 0
Last time read locked in file row0sel.c line 3075
Last time write locked in file /home/buildbot/slaves/percona-server-51-12/CentOS-5-x86-RPM_CentOS_5_x86_64/work/BUILD/Percona-Server-5.5.14-rel20.5/Percona-Server-5.5.14-rel20.5/storage/innobase/row/row0ins.c line 2008
--Thread 1297791296 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1339857216 has waited at trx0trx.c line 223 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1341188416 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1311369536 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1305512256 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1344915776 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1273297216 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1349441856 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1300719936 has waited at trx0trx.c line 1179 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1324415296 has waited at trx0trx.c line 1767 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1328675136 has waited at trx0trx.c line 1179 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1340123456 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1291934016 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1303648576 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1332668736 has waited at trx0trx.c line 1767 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1318025536 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1297525056 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1277024576 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1295661376 has waited at trx0trx.c line 1767 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1330006336 has waited at trx0trx.c line 1767 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1278089536 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1348909376 has waited at lock0lock.c line 5350 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1307375936 has waited at btr0pcur.c line 426 for 0.0000 seconds the semaphore:
S-lock on RW-latch at 0x2aaaee043638 '&block->lock'
a writer (thread id 1346513216) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0sel.c line 3075
Last time write locked in file /home/buildbot/slaves/percona-server-51-12/CentOS-5-x86-RPM_CentOS_5_x86_64/work/BUILD/Percona-Server-5.5.14-rel20.5/Percona-Server-5.5.14-rel20.5/storage/innobase/row/row0ins.c line 2008
--Thread 1349175616 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1295395136 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1268504896 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1338526016 has waited at trx0trx.c line 1179 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1337461056 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1330272576 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
--Thread 1294596416 has waited at trx0trx.c line 790 for 0.0000 seconds the semaphore:
Mutex at 0x1905aa18 '&kernel_mutex', lock var 1
waiters flag 0
Mutex spin waits 16210335455, rounds 431570432038, OS waits 10966433915
RW-shared spins 1483243861, rounds 37761580946, OS waits 1040814371
RW-excl spins 239209004, rounds 29473436626, OS waits 888212940
Spin rounds per wait: 26.62 mutex, 25.46 RW-shared, 123.21 RW-excl

tags: added: pt-sift wrong-output
Changed in percona-toolkit:
status: New → Confirmed
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers