Mysql blocked on insert

[Benjamin Boudoir]

Hi,

Since the upgrade from 5.5.25 to 5.5.27 on our slave (Debian Squeeze), mysql sometime freeze on small insert. All our DB uses InnoDB.

When we kill the querie, nothing's happen (it just marked as "killed") and a "show engine innodb status" not returning anything (might ^c to recover the shell).

Example insert (after the kill) :
| 8 | system user | | db | Killed | 6474 | update | INSERT INTO `table` (id_1,id_2) VALUES ('126555','8478392') | 0 | 0 | 1 |

The update is 24h old and this bug already append 3 times.

We have the folling informations in the hostname.log :
=====================================
120829 10:55:51 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 68 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 539 1_second, 539 sleeps, 53 10_second, 0 background, 0 flush
srv_master_thread log flush and writes: 548
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 1087, signal count 1143
--Thread 139724007020288 has waited at buf0buf.c line 3667 for 251.00 seconds the semaphore:
Mutex at 0x3e4f368 '&buf_pool->mutex', lock var 1
waiters flag 1
--Thread 139718685546240 has waited at buf0lru.c line 1102 for 251.00 seconds the semaphore:
Mutex at 0x3e4f368 '&buf_pool->mutex', lock var 1
waiters flag 1
--Thread 139718693938944 has waited at buf0flu.c line 1887 for 251.00 seconds the semaphore:
Mutex at 0x3e4f368 '&buf_pool->mutex', lock var 1
waiters flag 1
Mutex spin waits 4717, rounds 41043, OS waits 904
RW-shared spins 322, rounds 3988, OS waits 94
RW-excl spins 152, rounds 3366, OS waits 72
Spin rounds per wait: 8.70 mutex, 12.39 RW-shared, 22.14 RW-excl
--------
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
36186 OS file reads, 176589 OS file writes, 157588 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 24, free list len 135, seg size 160, 1319 merges
merged operations:
 insert 4688, delete mark 582, delete 170
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 8850461, node heap has 810 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 1590504073898
Log flushed up to 1590504073898
Last checkpoint at 1590456151274
Max checkpoint age 67236619
Checkpoint age target 65135475
Modified age 47786593
Checkpoint age 47922624
0 pending log writes, 0 pending chkp writes
155275 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 4412407808; in additional pool allocated 0
Internal hash tables (constant factor + variable factor)
    Adaptive hash index 84078944 (70803688 + 13275256)
    Page hash 4426024 (buffer pool 0 only)
    Dictionary cache 22729692 (17702416 + 5027276)
    File system 442152 (82672 + 359480)
    Lock system 10626080 (10625704 + 376)
    Recovery system 0 (0 + 0)
Dictionary memory allocated 5027276
InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Warning: a long semaphore wait:
--Thread 139724007020288 has waited at buf0buf.c line 3667 for 272.00 seconds the semaphore:
Mutex at 0x3e4f368 '&buf_pool->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 139718685546240 has waited at buf0lru.c line 1102 for 272.00 seconds the semaphore:
Mutex at 0x3e4f368 '&buf_pool->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 139718693938944 has waited at buf0flu.c line 1887 for 272.00 seconds the semaphore:
Mutex at 0x3e4f368 '&buf_pool->mutex', lock var 1
waiters flag 1
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0
InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Warning: a long semaphore wait:
--Thread 139724007020288 has waited at buf0buf.c line 3667 for 303.00 seconds the semaphore:
Mutex at 0x3e4f368 '&buf_pool->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 139718685546240 has waited at buf0lru.c line 1102 for 303.00 seconds the semaphore:
Mutex at 0x3e4f368 '&buf_pool->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 139718693938944 has waited at buf0flu.c line 1887 for 303.00 seconds the semaphore:
Mutex at 0x3e4f368 '&buf_pool->mutex', lock var 1
waiters flag 1
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0
InnoDB: ###### Diagnostic info printed to the standard error stream

Regards,

[Raghavendra D Prabhu (raghavendra-prabhu)]

Marking this as a duplicate of https://bugs.launchpad.net/percona-server/+bug/1040735. You can track further activity and/or provide comments there.