InnoDB Warning: a long semaphore wait; cause MySQL crash

Bug #1576128 reported by rocky
256
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Percona Server moved to https://jira.percona.com/projects/PS
New
Undecided
Unassigned

Bug Description

help me!
mysql version is Ver 14.14 Distrib 5.6.25-73.0;
MySQL is crash , when i execure replace into .

table schema is :
 CREATE TABLE `hkv_4` (
  `rkey` varchar(60) COLLATE utf8_unicode_ci NOT NULL DEFAULT '',
  `field` varchar(60) COLLATE utf8_unicode_ci NOT NULL DEFAULT '',
  `val` varchar(60) COLLATE utf8_unicode_ci DEFAULT NULL,
  `lastTime` bigint(15) DEFAULT NULL,
  PRIMARY KEY (`rkey`,`field`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 COLLATE=utf8_unicode_ci;

mysql error log:
InnoDB: Warning: a long semaphore wait:
--Thread 139901152716544 has waited at btr0cur.cc line 280 for 241.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x7f3d7a4521c0 '&block->lock'
a writer (thread id 139901152716544) has reserved it in mode wait exclusive
number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
Last time read locked in file buf0flu.cc line 1078
Last time write locked in file /mnt/workspace/percona-server-5.6-redhat-binary/label_exp/centos6-64/rpmbuild/BUILD/percona-server-5.6.25-73.0/storage/innobase/row/row0ins.cc line 2357
InnoDB: Warning: a long semaphore wait:
--Thread 139901245896448 has waited at btr0cur.cc line 586 for 241.00 seconds the semaphore:
S-lock on RW-latch at 0x7f3ca041a548 '&new_index->lock'
a writer (thread id 139901152716544) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file btr0cur.cc line 586
Last time write locked in file /mnt/workspace/percona-server-5.6-redhat-binary/label_exp/centos6-64/rpmbuild/BUILD/percona-server-5.6.25-73.0/storage/innobase/btr/btr0cur.cc line 577
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:
InnoDB: Pending preads 0, pwrites 0

=====================================
2016-04-27 18:12:17 7f3d4e5a8700 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 37 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 11410505 srv_active, 0 srv_shutdown, 1266627 srv_idle
srv_master_thread log flush and writes: 12677132
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 67715015
--Thread 139901152716544 has waited at btr0cur.cc line 280 for 250.00 seconds the semaphore:
X-lock (wait_ex) on RW-latch at 0x7f3d7a4521c0 '&block->lock'
a writer (thread id 139901152716544) has reserved it in mode wait exclusive
number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
Last time read locked in file buf0flu.cc line 1078
Last time write locked in file /mnt/workspace/percona-server-5.6-redhat-binary/label_exp/centos6-64/rpmbuild/BUILD/percona-server-5.6.25-73.0/storage/innobase/row/row0ins.cc line 2357
--Thread 139901245896448 has waited at btr0cur.cc line 586 for 250.00 seconds the semaphore:
S-lock on RW-latch at 0x7f3ca041a548 '&new_index->lock'
a writer (thread id 139901152716544) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file btr0cur.cc line 586
Last time write locked in file /mnt/workspace/percona-server-5.6-redhat-binary/label_exp/centos6-64/rpmbuild/BUILD/percona-server-5.6.25-73.0/storage/innobase/btr/btr0cur.cc line 577
--Thread 139901156177664 has waited at btr0cur.cc line 586 for 249.00 seconds the semaphore:
S-lock on RW-latch at 0x7f3ca041a548 '&new_index->lock'
a writer (thread id 139901152716544) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file btr0cur.cc line 586
Last time write locked in file /mnt/workspace/percona-server-5.6-redhat-binary/label_exp/centos6-64/rpmbuild/BUILD/percona-server-5.6.25-73.0/storage/innobase/btr/btr0cur.cc line 577
--Thread 139901248558848 has waited at btr0cur.cc line 586 for 249.00 seconds the semaphore:
S-lock on RW-latch at 0x7f3ca041a548 '&new_index->lock'
a writer (thread id 139901152716544) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file btr0cur.cc line 586
Last time write locked in file /mnt/workspace/percona-server-5.6-redhat-binary/label_exp/centos6-64/rpmbuild/BUILD/percona-server-5.6.25-73.0/storage/innobase/btr/btr0cur.cc line 577
--Thread 139901153515264 has waited at btr0cur.cc line 586 for 248.00 seconds the semaphore:
S-lock on RW-latch at 0x7f3ca041a548 '&new_index->lock'
a writer (thread id 139901152716544) has reserved it in mode exclusive
....
....
....
S-lock on RW-latch at 0x7f3ca041a548 '&new_index->lock'
a writer (thread id 139901152716544) has reserved it in mode exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file btr0cur.cc line 586
Last time write locked in file /mnt/workspace/percona-server-5.6-redhat-binary/label_exp/centos6-64/rpmbuild/BUILD/percona-server-5.6.25-73.0/storage/innobase/btr/btr0cur.cc line 577
OS WAIT ARRAY INFO: signal count 67922663
Mutex spin waits 708588413, rounds 2971275947, OS waits 65761595
RW-shared spins 1948770, rounds 51684416, OS waits 1674418
RW-excl spins 1501321, rounds 10211245, OS waits 182161
Spin rounds per wait: 4.19 mutex, 26.52 RW-shared, 6.80 RW-excl
------------
TRANSACTIONS
------------
Trx id counter 6712744670
Purge done for trx's n:o < 6712744669 undo n:o < 0 state: running but idle
History list length 2621
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 6712744244, not started estimating records in index range
mysql tables in use 1, locked 0
MySQL thread id 802566, OS thread handle 0x7f3d45dc5700, query id 7133892326 10.83.220.58 guestGeo statistics
select * from guestgeo_6.hkv_4 where rkey = 'user:1000030966418:location' order by lasttime desc
---TRANSACTION 6712743213, not started estimating records in index range
mysql tables in use 1, locked 0
MySQL thread id 802565, OS thread handle 0x7f3d4c55c700, query id 7133891209 10.83.220.117 guestGeo statistics
select * from guestgeo_6.hkv_4 where rkey = 'user:1000036697107:location' order by lasttime desc
---TRANSACTION 6712744339, not started estimating records in index range
mysql tables in use 1, locked 0
MySQL thread id 802562, OS thread handle 0x7f3d46973700, query id 7133892415 10.83.220.117 guestGeo statistics
select * from guestgeo_6.hkv_4 where rkey = 'user:1000030907626:location' order by lasttime desc
---TRANSACTION 6712738025, not started estimating records in index range
mysql tables in use 1, locked 0
MySQL thread id 802559, OS thread handle 0x7f3d4c048700, query id 7133885806 10.83.220.117 guestGeo statistics
select * from guestgeo_6.hkv_4 where rkey = 'user:1000034655341:location' order by lasttime desc
---TRANSACTION 6712737007, not started estimating records in index range
mysql tables in use 1, locked 0
MySQL thread id 802556, OS thread handle 0x7f3d469f5700, query id 7133884773 10.83.220.117 guestGeo statistics
select * from guestgeo_6.hkv_4 where rkey = 'user:1000005809773:location' order by lasttime desc
.....
.....
.....
---TRANSACTION 6712744669, ACTIVE 191 sec inserting
mysql tables in use 1, locked 1
1 lock struct(s), heap size 360, 0 row lock(s)
MySQL thread id 802546, OS thread handle 0x7f3d4604f700, query id 7133892726 10.83.220.58 guestGeo update
replace into guestgeo_6.hkv_4(rkey, field, val, lasttime) values('user:1000022363946:location', 'time', _binary'1970-01-18 05:02:31', 1461751746301)
---TRANSACTION 6712744648, ACTIVE 191 sec inserting
mysql tables in use 1, locked 1
1 lock struct(s), heap size 360, 0 row lock(s)
MySQL thread id 802544, OS thread handle 0x7f3d46a77700, query id 7133892704 10.83.220.58 guestGeo update
replace into guestgeo_6.hkv_4(rkey, field, val, lasttime) values('user:1000036796705:location', 'slng', _binary'118.463946', 1461751746246)
---TRANSACTION 6712743299, ACTIVE 193 sec inserting
mysql tables in use 1, locked 1
1 lock struct(s), heap size 360, 0 row lock(s)
MySQL thread id 802563, OS thread handle 0x7f3d467ed700, query id 7133891297 10.83.220.117 guestGeo update
replace into guestgeo_6.hkv_4(rkey, field, val, lasttime) values('user:1000023073970:location', 'slng', _binary'118.5718789704', 1461751744984)
---TRANSACTION 6712743154, ACTIVE 193 sec inserting
mysql tables in use 1, locked 1
1 lock struct(s), heap size 360, 0 row lock(s)
MySQL thread id 802541, OS thread handle 0x7f3d46257700, query id 7133891147 10.83.220.58 guestGeo update
replace into guestgeo_6.hkv_4(rkey, field, val, lasttime) values('user:1000022363946:location', 'slng', _binary'120.781518', 1461751744714)
---TRANSACTION 6712741711, ACTIVE 195 sec inserting

----------------------------
END OF INNODB MONITOR OUTPUT
============================
InnoDB: ###### Diagnostic info printed to the standard error stream
InnoDB: Error: semaphore wait has lasted > 600 seconds
InnoDB: We intentionally crash the server, because it appears to be hung.
2016-04-27 18:24:01 7f3d4efa9700 InnoDB: Assertion failure in thread 139901294778112 in file srv0srv.cc line 2128
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
10:24:01 UTC - mysqld got signal 6 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed,
something is definitely wrong and this may fail.
Please help us make Percona Server better by reporting any
bugs at http://bugs.percona.com/

key_buffer_size=33554432
read_buffer_size=131072
max_used_connections=114
max_threads=2002
thread_count=112
connection_count=112
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 829190 K bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
...
...
...

rocky (rockyjobmail)
summary: - nnoDB: Warning: a long semaphore wait: MySQL crash
+ InnoDB Warning: a long semaphore wait; cause MySQL crash
description: updated
rocky (rockyjobmail)
Changed in percona-server:
status: New → Confirmed
status: Confirmed → New
status: New → Confirmed
status: Confirmed → New
rocky (rockyjobmail)
Changed in percona-server:
status: New → Confirmed
information type: Public → Public Security
Changed in percona-server:
status: Confirmed → New
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-3423

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

Other bug subscribers

Remote bug watches

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