a long semaphore wait and mysqld hangs

[Jui-Nan Lin]

We are running Percona-XtraDB-5.1.45-1.0.6-10.2-Linux-2.6.18-164.15.1.el5-x86_64.
 Recently when we execute a SQL "TRUNCATE" query, the slave server hangs. (the master database server is find.)

It is not an I/O issue since there is no read queries on the slave server.
The slave server only acts as a hot-backup server.

# uname -a
Linux db-counter-1-1 2.6.26-2-amd64 #1 SMP Sun Jun 20 20:16:30 UTC 2010 x86_64 GNU/Linux

# cat mysql.log
InnoDB: Warning: a long semaphore wait:
--Thread 1199630672 has waited at buf/buf0buf.c line 3550 for 241.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1224808784 has waited at buf/buf0buf.c line 3550 for 241.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1182845264 has waited at buf/buf0buf.c line 3550 for 241.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1191237968 has waited at buf/buf0buf.c line 3550 for 241.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1166059856 has waited at buf/buf0buf.c line 3550 for 241.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1216416080 has waited at buf/buf0buf.c line 3550 for 241.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1208023376 has waited at buf/buf0buf.c line 3550 for 241.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1174452560 has waited at buf/buf0buf.c line 3550 for 241.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0

=====================================
100713 15:44:10 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 63 seconds
----------

----------
BACKGROUND THREAD
----------
srv_master_thread loops: 146612 1_second, 65456 sleeps, 14651 10_second, 137 background, 137 flush
srv_master_thread log flush and writes: 80105
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 2607011, signal count 2571643
--Thread 1199630672 has waited at buf/buf0buf.c line 3550 for 254.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
--Thread 1224808784 has waited at buf/buf0buf.c line 3550 for 254.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
--Thread 1182845264 has waited at buf/buf0buf.c line 3550 for 254.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
--Thread 1191237968 has waited at buf/buf0buf.c line 3550 for 254.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
--Thread 1166059856 has waited at buf/buf0buf.c line 3550 for 254.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
--Thread 1216416080 has waited at buf/buf0buf.c line 3550 for 254.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
--Thread 1208023376 has waited at buf/buf0buf.c line 3550 for 254.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
--Thread 1174452560 has waited at buf/buf0buf.c line 3550 for 254.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
--Thread 1258379600 has waited at buf/buf0buf.c line 2254 for 245.00 seconds the semaphore:
S-lock on RW-latch at 0xe03d60 '&page_hash_latch'
a writer (thread id 1259178320) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf/buf0buf.c line 2254
Last time write locked in file buf/buf0lru.c line 367
Mutex spin waits 1250584, rounds 13076870, OS waits 310399
RW-shared spins 2306008, OS waits 2222748; RW-excl spins 138761, OS waits 69252
Spin rounds per wait: 10.46 mutex, 29.09 RW-shared, 18.79 RW-excl
--------
FILE I/O
--------
I/O thread 0 state: waiting for i/o request (insert buffer thread)
I/O thread 1 state: waiting for i/o request (log thread)
I/O thread 2 state: waiting for i/o request (read thread)
I/O thread 3 state: waiting for i/o request (read thread)
I/O thread 4 state: waiting for i/o request (read thread)

I/O thread 5 state: waiting for i/o request (read thread)
I/O thread 6 state: waiting for i/o request (read thread)
I/O thread 7 state: waiting for i/o request (read thread)
I/O thread 8 state: waiting for i/o request (read thread)
I/O thread 9 state: waiting for i/o request (read thread)
I/O thread 10 state: complete io for buf page (write thread) ev set
I/O thread 11 state: complete io for buf page (write thread) ev set
I/O thread 12 state: complete io for buf page (write thread) ev set
I/O thread 13 state: complete io for buf page (write thread) ev set
I/O thread 14 state: complete io for buf page (write thread) ev set
I/O thread 15 state: complete io for buf page (write thread) ev set
I/O thread 16 state: complete io for buf page (write thread) ev set
I/O thread 17 state: complete io for buf page (write thread) ev set
Pending normal aio reads: 0, aio writes: 85,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
827731 OS file reads, 23816650 OS file writes, 638325 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 287, seg size 289,
20049 inserts, 20049 merged recs, 17205 merges
Hash table size 35401589, node heap has 16543 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 8025471663308
Log flushed up to 8025471642505
Last checkpoint at 8025394194788
Max checkpoint age 162361775
Checkpoint age target 157287970
Modified age 76737289
Checkpoint age 77468520
0 pending log writes, 0 pending chkp writes
16518337 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 17616076800; in additional pool allocated 0
Internal hash tables (constant factor + variable factor)
    Adaptive hash index 554257432 (283212712 + 271044720)
    Page hash 17701592
    Dictionary cache 71859488 (70804688 + 1054800)
    File system 160000 (82672 + 77328)
    Lock system 42500824 (42500456 + 368)
    Recovery system 0 (0 + 0)
    Threads 408856 (406936 + 1920)
Dictionary memory allocated 1054800

InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Warning: a long semaphore wait:
--Thread 1199630672 has waited at buf/buf0buf.c line 3550 for 272.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1224808784 has waited at buf/buf0buf.c line 3550 for 272.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1182845264 has waited at buf/buf0buf.c line 3550 for 272.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1191237968 has waited at buf/buf0buf.c line 3550 for 272.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1166059856 has waited at buf/buf0buf.c line 3550 for 272.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1216416080 has waited at buf/buf0buf.c line 3550 for 272.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1208023376 has waited at buf/buf0buf.c line 3550 for 272.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1174452560 has waited at buf/buf0buf.c line 3550 for 272.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1258379600 has waited at buf/buf0buf.c line 2254 for 263.00 seconds the semaphore:
S-lock on RW-latch at 0xe03d60 '&page_hash_latch'
a writer (thread id 1259178320) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf/buf0buf.c line 2254
Last time write locked in file buf/buf0lru.c line 367
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 1199630672 has waited at buf/buf0buf.c line 3550 for 303.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1224808784 has waited at buf/buf0buf.c line 3550 for 303.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1

waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1182845264 has waited at buf/buf0buf.c line 3550 for 303.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1191237968 has waited at buf/buf0buf.c line 3550 for 303.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1166059856 has waited at buf/buf0buf.c line 3550 for 303.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1216416080 has waited at buf/buf0buf.c line 3550 for 303.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1208023376 has waited at buf/buf0buf.c line 3550 for 303.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1174452560 has waited at buf/buf0buf.c line 3550 for 303.00 seconds the semaphore:
Mutex at 0xe03ce0 '&LRU_list_mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 1258379600 has waited at buf/buf0buf.c line 2254 for 294.00 seconds the semaphore:
S-lock on RW-latch at 0xe03d60 '&page_hash_latch'
a writer (thread id 1259178320) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf/buf0buf.c line 2254
Last time write locked in file buf/buf0lru.c line 367
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
Buffer pool size 1048575
Buffer pool size, bytes 17179852800
Free buffers 11333
Database pages 1399565
Old database pages 516655
Modified db pages 19039
Pending reads 0
Pending writes: LRU 0, flush list 76, single page 0
Pages made young 573000, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 831836, created 689488, written 12627095
0.00 reads/s, 0.00 creates/s, 0.02 writes/s
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s
LRU len: 1399565, unzip_LRU len: 156792

I/O sum[18446744073709551615]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread process no. 19005, id 1233201488, state: flushing buffer pool pages
Number of rows inserted 108640019, updated 13837773, deleted 0, read 118501312
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
------------
TRANSACTIONS
------------
Trx id counter 653EFD599
Purge done for trx's n:o < 653EFD581 undo n:o < 0
History list length 72
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 653EFD598, ACTIVE 992 sec, process no 19005, OS thread id 1259178320 truncating table
mysql tables in use 1, locked 1
MySQL thread id 2, query id 46582557 init
TRUNCATE TABLE `blogarticle_history_daily`
----------------------------
END OF INNODB MONITOR OUTPUT
============================

[Stewart Smith (stewart)]

All development of XtraDB has moved under the Percona Server project - https://launchpad.net/percona-server - If this bug can be reproduced against current Percona Server, please file this bug against percona-server (you can simply do so by using the "Also affects project" link above).

Thanks,
Stewart Smith
Director of Server Development
Percona.