Bug #70611 Mutex cause Thread waited at srv0srv.c line 1703 for xx seconds the semaphore
Submitted: 12 Oct 2013 9:05 Modified: 29 Dec 2013 10:29
Reporter: sharkbobo shark Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S3 (Non-critical)
Version:5.5.33 OS:Linux (Red Hat Enterprise Linux Server release 5.5)
Assigned to: CPU Architecture:Any
Tags: InnoDB Mutex semaphore

[12 Oct 2013 9:05] sharkbobo shark
Description:
We used InnoDB Engine。Our Order and other tables Set Partition/Day。And We have Many TimerTask Jobs to Insert,update these tables。Our appliation insert datas into homologous  Table Partition by createTime(system current time)

Our Appliation is work on OLTP Mode。(a E-Commerce company  )

client program : J2EE (java connectors version is 5.5.12) 
OS version:Red Hat Enterprise Linux Server release 5.5
Server : 96G mem, 24 Cpus。300G RAID。
Mysql(InnoDB) version: 5.5.33

We met many times Mysql crashed and always occured in early Mornming( 0 AM) recently,sometimes occured in 11 AM or other time。

All Thread Lock infomationes Contains"  Mutex at 0x134d3e8 created file srv0srv.c line 1024, lock var 1"
------------------------------------------------------------------------------------------

Detail Err-info like as below:
--Thread 1530194240 has waited at srv0srv.c line 1703 for 447.00 seconds the semaphore:
Mutex at 0x134d3e8 created file srv0srv.c line 1024, lock var 1
waiters flag 1
--Thread 1519012160 has waited at srv0srv.c line 1703 for 447.00 seconds the semaphore:
Mutex at 0x134d3e8 created file srv0srv.c line 1024, lock var 1
waiters flag 1
Mutex spin waits 18263551666, rounds 380247505145, OS waits 4527306165
RW-shared spins 46147485, rounds 478171921, OS waits 12656216
RW-excl spins 25622633, rounds 665118905, OS waits 13920069
Spin rounds per wait: 20.82 mutex, 10.36 RW-shared, 25.96 RW-excl
FAIL TO OBTAIN KERNEL MUTEX, SKIP LOCK INFO PRINTING
.............................
--------
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)
.................................

Pending normal aio reads: 0 [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 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
8242562 OS file reads, 46299403 OS file writes, 2810312 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 507501, seg size 507503, 173354 merges
merged operations:
 insert 13287, delete mark 57245744, delete 14016224
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 99608347, node heap has 75417 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 19036496876841
Log flushed up to   19036496862530
Last checkpoint at  19035950826294
0 pending log writes, 0 pending chkp writes
239069 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 51511296000; in additional pool allocated 0
Dictionary memory allocated 6146995
Buffer pool size   3071999
Free buffers       1
Database pages     2996056
Old database pages 1105945
Modified db pages  155123
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 15821453, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 8232146, created 1680840, written 45153875
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: 2996056, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
48 queries inside InnoDB, 78 queries in queue
30 read views open inside InnoDB
Main thread process no. 23408, id 1494518080, state: flushing log
Number of rows inserted 112405194, updated 68775775, deleted 126773712, read 28818307409
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
...........

-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 507501, seg size 507503, 173354 merges
merged operations:
 insert 13287, delete mark 57245744, delete 14016224
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 99608347, node heap has 75417 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 19036496876841
Log flushed up to   19036496862530
Last checkpoint at  19035950826294
0 pending log writes, 0 pending chkp writes
239069 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 51511296000; in additional pool allocated 0
Dictionary memory allocated 6146995
Buffer pool size   3071999
Free buffers       1
Database pages     2996056
Old database pages 1105945
Modified db pages  155123
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 15821453, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 8232146, created 1680840, written 45153875
0.00 reads/s, 0.00 creates/s, 0.00 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, Random read ahead 0.00/s
LRU len: 2996056, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
48 queries inside InnoDB, 78 queries in queue
30 read views open inside InnoDB
Main thread process no. 23408, id 1494518080, state: flushing log
Number of rows inserted 112405194, updated 68775775, deleted 126773712, read 28818307409
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

How to repeat:
Now We don't konw how to repeat this problem。but we trace the DB Server IO and CPU load,and analyze our workload,these were not high load。but this problem always apprianced at 0 AM。

Our Table Partition per Day。this will be the reason?
[12 Oct 2013 9:07] sharkbobo shark
completed InnoDB status Infomation

Attachment: mysql.err (application/octet-stream, text), 154.51 KiB.

[12 Oct 2013 9:07] sharkbobo shark
core file

Attachment: mysql_pstack.log (application/octet-stream, text), 382.42 KiB.

[12 Oct 2013 9:13] sharkbobo shark
2 days ago error infomation

Attachment: mysql-err-1.txt (text/plain), 2.10 MiB.

[29 Nov 2013 10:29] Sveta Smirnova
Thank you for the report.

I can not repeat described behavior with generic test on partitioned table. Please check if you don't have regular job running at 0.00
[30 Dec 2013 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".