Bug #1295820 “slave locks up waiting for commit lock” : Bugs : Percona Server moved to https://jira.percona.com/projects/PS

Revision history for this message

monty solomon (monty+launchpad) wrote on 2014-03-21:

#1

# rpm -qa | grep Percona
Percona-Server-server-56-5.6.16-rel64.1.el6.x86_64
Percona-Server-client-56-5.6.16-rel64.1.el6.x86_64
Percona-Server-devel-56-5.6.16-rel64.1.el6.x86_64
Percona-Server-shared-compat-5.5.35-rel33.0.611.rhel6.x86_64
Percona-Server-shared-56-5.6.16-rel64.1.el6.x86_64

Revision history for this message

monty solomon (monty+launchpad) wrote on 2014-03-21:

#2

Download full text (7.3 KiB)

mysql> SHOW ENGINE INNODB STATUS\G
*************************** 1. row ***************************
Type: InnoDB
Name:
Status:
=====================================
2014-03-21 19:42:53 7f4370d2a700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 12 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 27050 srv_active, 0 srv_shutdown, 22385 srv_idle
srv_master_thread log flush and writes: 49435
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 312899
OS WAIT ARRAY INFO: signal count 312727
Mutex spin waits 252689, rounds 7171447, OS waits 237254
RW-shared spins 72427, rounds 2169907, OS waits 72281
RW-excl spins 2573, rounds 98345, OS waits 3256
Spin rounds per wait: 28.38 mutex, 29.96 RW-shared, 38.22 RW-excl
------------
TRANSACTIONS
------------
Trx id counter 126744264
Purge done for trx's n:o < 126744259 undo n:o < 0 state: running but idle
History list length 1497
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 6563, OS thread handle 0x7f4370d2a700, query id 1034611 localhost root init
SHOW ENGINE INNODB STATUS
---TRANSACTION 126570662, not started
MySQL thread id 3850, OS thread handle 0x7f45082c3700, query id 1029582 10.82.214.16 zenoss init
---TRANSACTION 126744261, ACTIVE 11622 sec
2 lock struct(s), heap size 360, 1 row lock(s), undo log entries 1
MySQL thread id 364, OS thread handle 0x7f45081ff700, query id 1029572 Waiting for commit lock
TABLE LOCK table `singularity12`.`taskHistory` trx id 126744261 lock mode IX
RECORD LOCKS space id 437 page no 2770185 n bits 80 index `PRIMARY` of table `singularity12`.`taskHistory` trx id 126744261 lock_mode X locks rec but not gap
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
1764945 OS file reads, 921802 OS file writes, 71456 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 18, seg size 20, 618 merges
merged operations:
insert 863, delete mark 785, delete 109
discarded operations:
insert 0, delete mark 0, delete 0
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 161270301510
Log flushed up to 161270301510
Pages flu...

mysql> SHOW ENGINE INNODB STATUS\G
*************************** 1. row ***************************
  Type: InnoDB
  Name: 
Status: 
=====================================
2014-03-21 19:42:53 7f4370d2a700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 12 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 27050 srv_active, 0 srv_shutdown, 22385 srv_idle
srv_master_thread log flush and writes: 49435
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 312899
OS WAIT ARRAY INFO: signal count 312727
Mutex spin waits 252689, rounds 7171447, OS waits 237254
RW-shared spins 72427, rounds 2169907, OS waits 72281
RW-excl spins 2573, rounds 98345, OS waits 3256
Spin rounds per wait: 28.38 mutex, 29.96 RW-shared, 38.22 RW-excl
------------
TRANSACTIONS
------------
Trx id counter 126744264
Purge done for trx's n:o < 126744259 undo n:o < 0 state: running but idle
History list length 1497
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 6563, OS thread handle 0x7f4370d2a700, query id 1034611 localhost root init
SHOW ENGINE INNODB STATUS
---TRANSACTION 126570662, not started
MySQL thread id 3850, OS thread handle 0x7f45082c3700, query id 1029582 10.82.214.16 zenoss init
---TRANSACTION 126744261, ACTIVE 11622 sec
2 lock struct(s), heap size 360, 1 row lock(s), undo log entries 1
MySQL thread id 364, OS thread handle 0x7f45081ff700, query id 1029572 Waiting for commit lock
TABLE LOCK table `singularity12`.`taskHistory` trx id 126744261 lock mode IX
RECORD LOCKS space id 437 page no 2770185 n bits 80 index `PRIMARY` of table `singularity12`.`taskHistory` trx id 126744261 lock_mode X locks rec but not gap
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
I/O thread 1 state: waiting for completed aio requests (log thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
I/O thread 9 state: waiting for completed aio requests (write thread)
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
1764945 OS file reads, 921802 OS file writes, 71456 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 18, seg size 20, 618 merges
merged operations:
 insert 863, delete mark 785, delete 109
discarded operations:
 insert 0, delete mark 0, delete 0
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 161270301510
Log flushed up to   161270301510
Pages flushed up to 161270301510
Last checkpoint at  161270301510
Max checkpoint age    216721613
Checkpoint age target 209949063
Modified age          0
Checkpoint age        0
0 pending log writes, 0 pending chkp writes
427259 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 5494538240; in additional pool allocated 0
Total memory allocated by read views 200
Internal hash tables (constant factor + variable factor)
    Adaptive hash index 85052720 	(84999368 + 53352)
    Page hash           2657176 (buffer pool 0 only)
    Dictionary cache    21761113 	(21251248 + 509865)
    File system         869272 	(812272 + 57000)
    Lock system         13283056 	(13281976 + 1080)
    Recovery system     0 	(0 + 0)
Dictionary memory allocated 509865
Buffer pool size        327678
Buffer pool size, bytes 5368676352
Free buffers            2048
Database pages          485640
Old database pages      179261
Modified db pages       0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 14158, not young 11124407
0.00 youngs/s, 0.00 non-youngs/s
Pages read 1764609, created 46014, written 476099
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 485640, unzip_LRU len: 48567
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
----------------------
INDIVIDUAL BUFFER POOL INFO
----------------------
---BUFFER POOL 0
Buffer pool size        163839
Buffer pool size, bytes 2684338176
Free buffers            1024
Database pages          242327
Old database pages      89458
Modified db pages       0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 6918, not young 5568203
0.00 youngs/s, 0.00 non-youngs/s
Pages read 889613, created 22644, written 240091
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 242327, unzip_LRU len: 24234
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
---BUFFER POOL 1
Buffer pool size        163839
Buffer pool size, bytes 2684338176
Free buffers            1024
Database pages          243313
Old database pages      89803
Modified db pages       0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 7240, not young 5556204
0.00 youngs/s, 0.00 non-youngs/s
Pages read 874996, created 23370, written 236008
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 243313, unzip_LRU len: 24333
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
1 RW transactions active inside InnoDB
0 RO transactions active inside InnoDB
1 out of 1000 descriptors used
Main thread process no. 2637, id 139927743821568, state: sleeping
Number of rows inserted 172277, updated 223446, deleted 7307, read 10497229
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
------------
TRANSACTIONS
------------
Trx id counter 126744264
Purge done for trx's n:o < 126744259 undo n:o < 0 state: running but idle
History list length 1497
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0, not started
MySQL thread id 6563, OS thread handle 0x7f4370d2a700, query id 1034611 localhost root init
SHOW ENGINE INNODB STATUS
---TRANSACTION 126570662, not started
MySQL thread id 3850, OS thread handle 0x7f45082c3700, query id 1029582 10.82.214.16 zenoss init
---TRANSACTION 126744261, ACTIVE 11622 sec
2 lock struct(s), heap size 360, 1 row lock(s), undo log entries 1
MySQL thread id 364, OS thread handle 0x7f45081ff700, query id 1029572 Waiting for commit lock
TABLE LOCK table `singularity12`.`taskHistory` trx id 126744261 lock mode IX
RECORD LOCKS space id 437 page no 2770185 n bits 80 index `PRIMARY` of table `singularity12`.`taskHistory` trx id 126744261 lock_mode X locks rec but not gap
----------------------------
END OF INNODB MONITOR OUTPUT
============================

Revision history for this message

Valerii Kravchuk (valerii-kravchuk) wrote on 2014-03-25:

#3

Please, send the entire output of SHOW PROCESSLIST when this happens. I wonder if this can be something like http://bugs.mysql.com/bug.php?id=70307

Changed in percona-server:
status:	New → Incomplete

Revision history for this message

monty solomon (monty+launchpad) wrote on 2014-07-31:

#4

It may be related to that upstream issue.

Revision history for this message

Valerii Kravchuk (valerii-kravchuk) wrote on 2014-07-31:

#5

May be related or is related I wonder (hence my request for SHOW PROCESSLIST)? If it is the same bug, we do have a Verified upstream bug and can just wait for the fix or check if we can fix this earlier than Oracle.

If we are NOT sure, we may have a new bug and still have to work on a repeatable test case.

Revision history for this message

monty solomon (monty+launchpad) wrote on 2014-08-01:

#6

I have not seen the problem recur since I opened this bug.

When I see it again I will capture the PROCESSLIST.

Revision history for this message

monty solomon (monty+launchpad) wrote on 2014-11-02:

#7

Bug 1386363 may be related to this one.

Valerii Kravchuk (valerii-kravchuk) on 2014-11-02

Changed in percona-server:
status:	Incomplete → New

Revision history for this message

Nilnandan Joshi (nilnandan-joshi) wrote on 2014-11-03:

#8

Considering duplicate of this https://bugs.launchpad.net/percona-server/+bug/1386363
As both "commit lock" and "show slave status hang" issues are confirmed there. (Check comment #9 on above bug)

Percona Server moved to https://jira.percona.com/projects/PS

slave locks up waiting for commit lock

Bug Description

Other bug subscribers

Remote bug watches