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

Freezes with "has waited at buf0buf.c line 2529 for XXX seconds the semaphore" errors

Bug #1026926 reported by Przemek Peron
76
This bug affects 15 people
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
Fix Released
Critical
Stewart Smith
Percona Server moved to https://jira.percona.com/projects/PS 5.5.27-28.0
5.1
Invalid
Undecided
Unassigned
5.5
Fix Released
Critical
Stewart Smith
Percona Server moved to https://jira.percona.com/projects/PS 5.5.27-28.0

Bug Description

Almost daily my Percona MySQL Server is freezing and I have to kill -9 all processes and restart the server since normal kill or shutdown doesn't work. The server runs 25GB database (mostly InnoDB). It happens usually at night and the only thing that comes to mind is the backup of databases and r1soft cdp backup which I do nightly.

mysqladmin processlist shows many waiting processes and one with "Waiting for table metadata lock" status.

mysqlbug output:
--- CUT ---
Server version 5.5.24-55
Protocol version 10
Connection Localhost via UNIX socket
UNIX socket /var/run/mysqld/mysqld.sock
Uptime: 1 day 7 min 46 sec

Threads: 301 Questions: 9526676 Slow queries: 206 Opens: 2391 Flush tables: 1 Open tables: 1148 Queries per second avg: 109.670
>C compiler: gcc (Debian 4.4.5-8) 4.4.5

>C++ compiler: gcc (Debian 4.4.5-8) 4.4.5

>Environment:
 <machine, os, target, libraries (multiple lines)>
System: Linux xxx.xxx 2.6.32-5-amd64 #1 SMP Sun May 6 04:00:17 UTC 2012 x86_64 GNU/Linux
Some paths: /usr/bin/perl /usr/bin/make /usr/bin/gcc /usr/bin/cc
GCC: Using built-in specs.
Target: x86_64-linux-gnu
Configured with: ../src/configure -v --with-pkgversion='Debian 4.4.5-8' --with-bugurl=file:///usr/share/doc/gcc-4.4/README.Bugs --enable-languages=c,c++,fortran,objc,obj-c++ --prefix=/usr --program-suffix=-4.4 --enable-shared --enable-multiarch --enable-linker-build-id --with-system-zlib --libexecdir=/usr/lib --without-included-gettext --enable-threads=posix --with-gxx-include-dir=/usr/include/c++/4.4 --libdir=/usr/lib --enable-nls --enable-clocale=gnu --enable-libstdcxx-debug --enable-objc-gc --with-arch-32=i586 --with-tune=generic --enable-checking=release --build=x86_64-linux-gnu --host=x86_64-linux-gnu --target=x86_64-linux-gnu
Thread model: posix
gcc version 4.4.5 (Debian 4.4.5-8)
Compilation info (call): CC='/usr/bin/gcc' CFLAGS='-g -O2 -fPIC -Wall -O3 -g -static-libgcc -fno-omit-frame-pointer -DPERCONA_INNODB_VERSION=rel26.0 -fPIC -Wall -O3 -g -static-libgcc -fno-omit-frame-pointer -fno-strict-aliasing -DDBUG_OFF -DMY_PTHREAD_FASTMUTEX=1' CXX='/usr/bin/gcc' CXXFLAGS='-g -O2 -O2 -fno-omit-frame-pointer -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fno-exceptions -DPERCONA_INNODB_VERSION=rel26.0 -fPIC -Wall -Wno-unused-parameter -fno-implicit-templates -fno-exceptions -fno-rtti -O3 -g -static-libgcc -fno-omit-frame-pointer -fno-strict-aliasing -DDBUG_OFF -DMY_PTHREAD_FASTMUTEX=1' LDFLAGS='' ASFLAGS=''
Compilation info (used): CC='/usr/bin/gcc' CFLAGS='-g -O2 -fPIC -Wall -O3 -g -static-libgcc -fno-omit-frame-pointer -DPERCONA_INNODB_VERSION=rel26.0 -fPIC -Wall -O3 -g -static-libgcc -fno-omit-frame-pointer -fno-strict-aliasing -DDBUG_OFF -DMY_PTHREAD_FASTMUTEX=1' CXX='/usr/bin/gcc' CXXFLAGS='-g -O2 -O2 -fno-omit-frame-pointer -g -pipe -Wall -Wp,-D_FORTIFY_SOURCE=2 -fno-exceptions -DPERCONA_INNODB_VERSION=rel26.0 -fPIC -Wall -Wno-unused-parameter -fno-implicit-templates -fno-exceptions -fno-rtti -O3 -g -static-libgcc -fno-omit-frame-pointer -fno-strict-aliasing -DDBUG_OFF -DMY_PTHREAD_FASTMUTEX=1' LDFLAGS='' ASFLAGS=''
LIBC:
lrwxrwxrwx 1 root root 14 Jun 25 09:32 /lib/libc.so.6 -> libc-2.11.3.so
-rwxr-xr-x 1 root root 1437064 Feb 12 20:12 /lib/libc-2.11.3.so
-rw-r--r-- 1 root root 4439052 Feb 12 20:12 /usr/lib/libc.a
-rw-r--r-- 1 root root 247 Feb 12 20:10 /usr/lib/libc.so
--- CUT ---

Error log:
--- CUT ---
InnoDB: Warning: a long semaphore wait:
--Thread 140476551141120 has waited at dict0dict.c line 744 for 241.00 seconds the semaphore:
Mutex at 0x2279ec38 '&dict_sys->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 140476533987072 has waited at buf0buf.c line 2529 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0

=====================================
120720 4:00:47 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 38 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 62511 1_second, 62263 sleeps, 6229 10_second, 251 background, 251 flush
srv_master_thread log flush and writes: 85222
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 35233, signal count 94778
--Thread 140476551141120 has waited at dict0dict.c line 744 for 253.00 seconds the semaphore:
Mutex at 0x2279ec38 '&dict_sys->mutex', lock var 1
waiters flag 1
--Thread 140476533987072 has waited at buf0buf.c line 2529 for 253.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476565554944 has waited at buf0buf.c line 2529 for 252.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476213966592 has waited at buf0buf.c line 2529 for 251.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476548933376 has waited at buf0buf.c line 2529 for 245.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476527363840 has waited at buf0buf.c line 2529 for 244.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476513515264 has waited at buf0buf.c line 2529 for 235.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476533786368 has waited at buf0buf.c line 2529 for 235.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476520339200 has waited at buf0buf.c line 2529 for 225.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476524152576 has waited at buf0buf.c line 2529 for 225.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476300654336 has waited at buf0buf.c line 2529 for 224.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476300453632 has waited at buf0buf.c line 2529 for 222.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476219385600 has waited at buf0buf.c line 2529 for 222.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140497213142784 has waited at buf0buf.c line 2529 for 221.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476216575744 has waited at buf0buf.c line 2529 for 221.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476219987712 has waited at buf0buf.c line 2529 for 218.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476548732672 has waited at buf0buf.c line 2529 for 217.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476218984192 has waited at buf0buf.c line 2529 for 214.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476219184896 has waited at buf0buf.c line 2529 for 213.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476215772928 has waited at buf0buf.c line 2529 for 209.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476218181376 has waited at buf0buf.c line 2529 for 200.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476518532864 has waited at buf0buf.c line 2529 for 84.000 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476520740608 has waited at buf0buf.c line 2529 for 32.000 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476529370880 has waited at buf0buf.c line 2529 for 31.000 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476531377920 has waited at buf0buf.c line 2529 for 25.000 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476536194816 has waited at buf0buf.c line 2529 for 24.000 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476531980032 has waited at buf0buf.c line 2529 for 21.000 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476538402560 has waited at buf0buf.c line 2529 for 17.000 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
--Thread 140476526360320 has waited at buf0buf.c line 2529 for 8.0000 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
Mutex spin waits 291401, rounds 415500, OS waits 4104
RW-shared spins 47145, rounds 769368, OS waits 23733
RW-excl spins 11868, rounds 338903, OS waits 7174
Spin rounds per wait: 1.43 mutex, 16.32 RW-shared, 28.56 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
918443 OS file reads, 2096575 OS file writes, 196710 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 12, seg size 14, 3033 merges
merged operations:
 insert 9053, delete mark 1086, delete 81
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 38249647, node heap has 24414 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 93233771103
Log flushed up to 93233771103
Last checkpoint at 93233771103
Max checkpoint age 6720677
Checkpoint age target 6510656
Modified age 0
Checkpoint age 0
0 pending log writes, 0 pending chkp writes
830472 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 19855835136; in additional pool allocated 0
Internal hash tables (constant factor + variable factor)
    Adaptive hash index 706000368 (305997176 + 400003192)
    Page hash 19125592 (buffer pool 0 only)
    Dictionary cache 77734832 (76501168 + 1233664)
    File system 160112 (82672 + 77440)
    Lock system 47847008 (47812792 + 34216)
    Recovery system 0 (0 + 0)
Dictionary memory allocated 1233664
InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Warning: a long semaphore wait:
--Thread 140476551141120 has waited at dict0dict.c line 744 for 272.00 seconds the semaphore:
Mutex at 0x2279ec38 '&dict_sys->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 140476533987072 has waited at buf0buf.c line 2529 for 272.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476565554944 has waited at buf0buf.c line 2529 for 271.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476213966592 has waited at buf0buf.c line 2529 for 270.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476548933376 has waited at buf0buf.c line 2529 for 264.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476527363840 has waited at buf0buf.c line 2529 for 263.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476513515264 has waited at buf0buf.c line 2529 for 254.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476533786368 has waited at buf0buf.c line 2529 for 254.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476520339200 has waited at buf0buf.c line 2529 for 244.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476524152576 has waited at buf0buf.c line 2529 for 244.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476300654336 has waited at buf0buf.c line 2529 for 243.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476300453632 has waited at buf0buf.c line 2529 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476219385600 has waited at buf0buf.c line 2529 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
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 140476551141120 has waited at dict0dict.c line 744 for 303.00 seconds the semaphore:
Mutex at 0x2279ec38 '&dict_sys->mutex', lock var 1
waiters flag 1
InnoDB: Warning: a long semaphore wait:
--Thread 140476533987072 has waited at buf0buf.c line 2529 for 303.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476565554944 has waited at buf0buf.c line 2529 for 302.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476213966592 has waited at buf0buf.c line 2529 for 301.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476548933376 has waited at buf0buf.c line 2529 for 295.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476527363840 has waited at buf0buf.c line 2529 for 294.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476513515264 has waited at buf0buf.c line 2529 for 285.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476533786368 has waited at buf0buf.c line 2529 for 285.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476520339200 has waited at buf0buf.c line 2529 for 275.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476524152576 has waited at buf0buf.c line 2529 for 275.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476300654336 has waited at buf0buf.c line 2529 for 274.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476300453632 has waited at buf0buf.c line 2529 for 272.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476219385600 has waited at buf0buf.c line 2529 for 272.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140497213142784 has waited at buf0buf.c line 2529 for 271.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476216575744 has waited at buf0buf.c line 2529 for 271.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476219987712 has waited at buf0buf.c line 2529 for 268.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476548732672 has waited at buf0buf.c line 2529 for 267.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476218984192 has waited at buf0buf.c line 2529 for 264.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476219184896 has waited at buf0buf.c line 2529 for 263.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476215772928 has waited at buf0buf.c line 2529 for 259.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
InnoDB: Warning: a long semaphore wait:
--Thread 140476218181376 has waited at buf0buf.c line 2529 for 250.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629
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
120720 4:09:41 [Warning] Too many connections
120720 4:23:23 [Warning] Too many connections
120720 4:26:56 [Warning] Too many connections
120720 4:27:07 [Warning] Too many connections
120720 4:27:09 [Warning] Too many connections
120720 4:27:17 [Warning] Too many connections
120720 4:27:18 [Warning] Too many connections
120720 4:27:23 [Warning] Too many connections
120720 4:27:24 [Warning] Too many connections
120720 4:27:25 [Warning] Too many connections
120720 4:27:26 [Warning] Too many connections
120720 4:27:44 [Warning] Too many connections
120720 4:27:48 [Warning] Too many connections
120720 4:27:50 [Warning] Too many connections
120720 4:27:50 [Warning] Too many connections
120720 4:27:52 [Warning] Too many connections
120720 4:27:53 [Warning] Too many connections
120720 4:27:58 [Warning] Too many connections
120720 4:27:58 [Warning] Too many connections
120720 4:28:00 [Warning] Too many connections
120720 4:28:02 [Warning] Too many connections
120720 4:28:02 [Warning] Too many connections
120720 5:06:28 [Warning] Too many connections
120720 5:13:51 [Warning] Too many connections
120720 5:19:12 [Warning] Too many connections

--- CUT ---

my.cnf:
--- CUT ---
[client]
port = 3306
socket = /var/run/mysqld/mysqld.sock

[mysqld_safe]
socket = /var/run/mysqld/mysqld.sock
nice = 0

[mysqld]
user = mysql
pid-file = /var/run/mysqld/mysqld.pid
socket = /var/run/mysqld/mysqld.sock
port = 3306
basedir = /usr
datadir = /var/lib/mysql
tmpdir = /tmp
language = /usr/share/mysql/english
skip-external-locking

key_buffer = 32M
thread_stack = 192K
thread_cache_size = 8
innodb_file_per_table = 1
innodb_buffer_pool_size = 18G
innodb_additional_mem_pool_size = 20M
innodb_flush_log_at_trx_commit=2
innodb_log_buffer_size = 64M
innodb_flush_method = O_DIRECT
transaction-isolation = READ-COMMITTED
innodb_thread_concurrency = 18
table_open_cache = 8000
sort_buffer_size = 32M
join_buffer_size = 16M
tmp_table_size = 512M
max_heap_table_size = 512M
max_connections = 300
max_allowed_packet = 64M

query_cache_limit = 1M
query_cache_size = 128M

expire_logs_days = 10
max_binlog_size = 100M

[mysqldump]
quick
quote-names
max_allowed_packet = 16M

[mysql]

[isamchk]
key_buffer = 16M

!includedir /etc/mysql/conf.d/
--- CUT ---

Related branches

lp:~stewart/percona-server/5.5.27-plus-bugfixes
On hold for merging into lp:percona-server/5.5
Alexey Kopytov (community): Needs Information
Laurynas Biveinis (community): Needs Information
Diff: 55 lines (+15/-6)
1 file modified
Percona-Server/storage/innobase/buf/buf0lru.c (+15/-6)
Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

This looks like a bug in non-lazy drop of table -- lock ordering is not preserved leading to deadlock (I presume you have tables being dropped around the time? ).

Does adding innodb_lazy_drop_table=ON (it is also dynamic, so no need to restart server) help?

Regarding the lock wait itself (in non lazy situation):

--Thread 140476533987072 has waited at buf0buf.c line 2529 for 303.00 seconds the semaphore:
S-lock on RW-latch at 0x416f048 '&buf_pool->page_hash_latch'
a writer (thread id 140476533987072) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file buf0buf.c line 2529
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-debs/label_exp/debian6-64/target/Percona-Server-5.5.24-rel26.0/storage/innobase/buf/buf0lru.c line 629

Both the waiter and the thread waited upon are same - 140476533987072. The reason being drop table path (buf0lru.c:629) also has buf0buf.c:2529 in it -- the root being buf_LRU_remove_all_pages for both.

In other words,

at buf0buf.c:2529 in buf_page_get_gen:

  rw_lock_s_lock(&buf_pool->page_hash_latch); --> it is already holding X-latch here, which it acquired at buf0lru.c:629

In btr_search_drop_page_hash_when_freed, they are already accounting for this kind of lock ordering but they are checking only for block->lock I believe.

"""
 /* If the caller has a latch on the page, then the caller must
 have a x-latch on the page and it must have already dropped
 the hash index for the page. Because of the x-latch that we
 are possibly holding, we cannot s-latch the page, but must
 (recursively) x-latch it, even though we are only reading. */
"""

Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

Just checked the upstream code, looks like PS added RW-lock on buf_pool->page_hash_latch, both in buf_LRU_remove_all_pages and buf_page_get_gen (upstream doesn't have for those). This may have been introduced when btr_search_drop_page_hash_when_freed was added to newly added function buf_LRU_remove_all_pages which wasn't there earlier. (may have been part of 5.5.23 upstream DROP TABLE code)

Revision history for this message
Przemek Peron (huan-j) wrote :

> I presume you have tables being dropped around the time?

There was "TRUNCATE TABLE" query running when the server freezed.

> Does adding innodb_lazy_drop_table=ON (it is also dynamic,
> so no need to restart server) help?

I've just added it and will let know if it works.

Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

'Truncate table' shares codepath with drop table. So it fits the behaviour you are seeing.

Revision history for this message
Przemek Peron (huan-j) wrote :

It has been 4 days since I've added "innodb_lazy_drop_table=ON" and till now the problem didn't reappear.

Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

Seems more are getting hit by same issue - http://forum.percona.com/index.php?t=msg&goto=9016&#msg_9016

Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

This should fix it:

==============================================

--- ./storage/innobase/buf/buf0lru.c 2012-08-03 22:41:36.867258585 +0530
+++ /tmp/buf0lru.c 2012-08-03 22:41:21.140590741 +0530
@@ -694,7 +694,7 @@
    ulint page_no;
    ulint zip_size;

- buf_pool_mutex_exit(buf_pool);
+ rw_lock_x_unlock(&buf_pool->page_hash_latch);

    zip_size = buf_page_get_zip_size(bpage);
    page_no = buf_page_get_page_no(bpage);

==============================================

I think buf_pool_mutex_exit may have been introduced in an erroneous merge since buf_pool_mutex_enter above in the same function is commented out (since we don't use buffer pool mutex here).

Revision history for this message
Raghavendra D Prabhu (raghavendra-prabhu) wrote :

Looks like it is right in revno: 0.16401.224 but somewhere in the merge it got lost. (also missing a mutex_exit(&LRU_list_mutex);)

Laurynas Biveinis (laurynas-biveinis)
tags: added: contribution
Revision history for this message
Alexey Kopytov (akopytov) wrote :

It's a critical regression introduced by incorrectly merging the upstream fix for http://bugs.mysql.com/bug.php?id=61188

tags: added: triaged
tags: added: regression
removed: triaged
Revision history for this message
Dima (l-dima) wrote :
Download full text (10.6 KiB)

I have just upgraded to percona 5.5.27-28 and hit what appears to be this deadlock. I do have drop table going on right around this issue. The trace is sightly different though.

InnoDB: Warning: a long semaphore wait:
--Thread 139645203990272 has waited at row0ins.c line 1557 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x1089700 '&dict_operation_lock'
a writer (thread id 139645204256512) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0undo.c line 315
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-rpms/label_exp/centos6-64/target/BUILD/Percona-Server-5.5.27-rel28.0/Percona-Server-5.5.27-rel28.0/storage/innobase/row/row0mysql.c line 3270
InnoDB: Warning: a long semaphore wait:
--Thread 139645203724032 has waited at row0undo.c line 315 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x1089700 '&dict_operation_lock'
a writer (thread id 139645204256512) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0undo.c line 315
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-rpms/label_exp/centos6-64/target/BUILD/Percona-Server-5.5.27-rel28.0/Percona-Server-5.5.27-rel28.0/storage/innobase/row/row0mysql.c line 3270
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0

=====================================
120826 2:58:09 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 66 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 39222 1_second, 39129 sleeps, 3907 10_second, 150 background, 150 flush
srv_master_thread log flush and writes: 40048
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 29054, signal count 45202
--Thread 139645203990272 has waited at row0ins.c line 1557 for 254.00 seconds the semaphore:
S-lock on RW-latch at 0x1089700 '&dict_operation_lock'
a writer (thread id 139645204256512) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0undo.c line 315
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-rpms/label_exp/centos6-64/target/BUILD/Percona-Server-5.5.27-rel28.0/Percona-Server-5.5.27-rel28.0/storage/innobase/row/row0mysql.c line 3270
--Thread 139645203724032 has waited at row0undo.c line 315 for 254.00 seconds the semaphore:
S-lock on RW-latch at 0x1089700 '&dict_operation_lock'
a writer (thread id 139645204256512) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0undo.c line 315
Last time write locked in file /home/jenkins/workspace/percona-server-5.5-rpms/label_exp/centos6-64/target/BUILD/Percona-Server-5.5.27-rel28.0/Percona-Server-5.5.27-rel28.0/storage/innobase/row/row0mysql.c line 3270
--Thread 139645204256512 has waited at buf0buf.c line 3667 for 253.00 seconds the semaphore:
Mutex at 0x2dd3048 '&buf_pool->mutex', lock var 1
waiters flag 1
--Thread 139645191735040 has waited at buf0buf.c line 3667 for...

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

Dima -

Could you provide the full GDB stacktraces at the time of deadlock? You'd need to install Percona Server debug symbols and GDB if not already installed and then do
gdb -ex "set pagination 0" -ex "thread apply all bt" --batch -p $(pidof mysqld)

Revision history for this message
Dima (l-dima) wrote :

I will if it happens again. However, I did enable lazy_table_drop and it was not happening two nights in a row. Since it is a production server I am not going to mess with it and disable lazy drop to reproduce the issue, sorry.

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

Sure, thanks, please update us if you get any crashes with the lazy drop table enabled.

Revision history for this message
Dima (l-dima) wrote :
Download full text (43.1 KiB)

It happened again on a slave of the original production server during replication. I forgot to set lazy drop there. I was able to capture the stack trace as well as the new error log below.

Hope it helps. I am going to set lazy load on the slave as well now.

Version: '5.5.27-28.0-log' socket: '/var/lib/mysql/mysql.sock' port: 3306 Percona Server (GPL), Release rel28.0, Revision 291
InnoDB: Warning: a long semaphore wait:
--Thread 140567060027136 has waited at buf0flu.c line 1887 for 241.00 seconds the semaphore:
Mutex at 0x3e1f128 '&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

=====================================
120828 6:24:34 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 33 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 134 1_second, 133 sleeps, 13 10_second, 12 background, 10 flush
srv_master_thread log flush and writes: 319
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 2098, signal count 2086
--Thread 140567060027136 has waited at buf0flu.c line 1887 for 245.00 seconds the semaphore:
Mutex at 0x3e1f128 '&buf_pool->mutex', lock var 1
waiters flag 1
--Thread 140569517369088 has waited at buf0lru.c line 1102 for 244.00 seconds the semaphore:
Mutex at 0x3e1f128 '&buf_pool->mutex', lock var 1
waiters flag 1
Mutex spin waits 2236, rounds 39111, OS waits 1222
RW-shared spins 80, rounds 1689, OS waits 53
RW-excl spins 8, rounds 24866, OS waits 818
Spin rounds per wait: 17.49 mutex, 21.11 RW-shared, 3108.25 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
10772 OS file reads, 61296 OS file writes, 4293 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 23, free list len 83602, seg size 83626, 2759 merges
merged operations:
 insert 5051, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 4425293, node heap has 50 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 252929934147
Log flushed up to 252929934147
Last checkpoint at 252926047000
Max ch...

Revision history for this message
Pavel Hladík (pavel-hladik) wrote :

Hi, It happend to me on CentOS 6.3 and Percona 5.5.27-rel28.0.291.rhel6, so I guess it is not fixed. I tried innodb_lazy_drop_table se to 1 and it seems that helped me.

Revision history for this message
Vern Burton (vern-1) wrote :
Download full text (6.0 KiB)

I can also verify this on

[root@server:~]# yum list installed | grep percona
Percona-Server-client-55.x86_64 5.5.27-rel28.0.291.rhel6 @percona
Percona-Server-devel-55.x86_64 5.5.27-rel28.0.291.rhel6 @percona
Percona-Server-server-55.x86_64 5.5.27-rel28.0.291.rhel6 @percona
Percona-Server-shared-55.x86_64 5.5.27-rel28.0.291.rhel6 @percona
Percona-Server-test-55.x86_64 5.5.27-rel28.0.291.rhel6 @percona
percona-release.x86_64 0.0-1 installed
[root@server:~]# cat /etc/redhat-release
CentOS release 6.3 (Final)

=====================================
120829 2:04:35 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 49 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 39026 1_second, 39026 sleeps, 3901 10_second, 16 backgr ound, 16 flush
srv_master_thread log flush and writes: 41415
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 10132, signal count 16893
--Thread 139685146564352 has waited at buf0buf.c line 3667 for 251.00 seconds th e semaphore:
Mutex at 0x2dba8f8 '&buf_pool->mutex', lock var 1
waiters flag 1
--Thread 139685157054208 has waited at buf0flu.c line 1887 for 245.00 seconds th e semaphore:
Mutex at 0x2dba8f8 '&buf_pool->mutex', lock var 1
waiters flag 1
--Thread 139684885821184 has waited at buf0lru.c line 1102 for 237.00 seconds th e semaphore:
Mutex at 0x2dba8f8 '&buf_pool->mutex', lock var 1
waiters flag 1
Mutex spin waits 15906, rounds 125370, OS waits 3319
RW-shared spins 5150, rounds 122649, OS waits 4016
RW-excl spins 3970, rounds 94541, OS waits 2753
Spin rounds per wait: 7.88 mutex, 23.82 RW-shared, 23.81 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
8013 OS file reads, 567592 OS file writes, 119812 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 27, seg size 29, 0 merges
merged operations:
 insert 0, delete mark 0, delete 0...

Read more...

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

Vern -

The deadlock you experienced seems to be bug 1040735, please follow it there for an eventual resolution.

Thanks.

Revision history for this message
Dima (l-dima) wrote :

Laurynas,

What about my issue in #14? Is that same as bug 1040735 as well?

BTW, since enabling lazy drop on the slave it is running smooth so far as well.

Thanks,
Dima.

Revision history for this message
Laurynas Biveinis (laurynas-biveinis) wrote :

Dima -

Yes., the stacktraces of #14 match bug 1040735.

Revision history for this message
Shahriyar Rzayev (rzayev-sehriyar) wrote :

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-345

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Duplicates of this bug

Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.