MySQL Bugs: #45643: Server crash due to gap locking mechanism

Bug #45643	Server crash due to gap locking mechanism
Submitted:	22 Jun 2009 3:20	Modified:	7 Jul 2009 23:04
Reporter:	Joao de Araujo	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: Locking	Severity:	S2 (Serious)
Version:	5.1.35	OS:	Windows (Windows Server 2008)
Assigned to:		CPU Architecture:	Any
Tags:	gap locking, innodb_locks_unsafe_for_binlog

Description:
Server Crash if enabling innodb_locks_unsafe_for_binlog=1 or isolation

I think the gap locking mechanism is crashing my application and mysql server.

The server and application crashes together if I use TRANSACTION_READ_COMMITTED or set explicitly innodb_locks_unsafe_for_binlog=1 in "my.ini"
Otherwise, if I use the isolation level TRANSACTION_READ_UNCOMMITTED and innodb_locks_unsafe_for_binlog=0, the application runs, but receives a deadlock message:

com.mysql.jdbc.exceptions.jdbc4.MySQLTransactionRollbackException: Deadlock found when trying to get lock; try restarting transaction

due to the embedded gap locking mechanism of mysql server

See below the output of the log file.

090621 21:29:27  InnoDB: Started; log sequence number 3 1436578153
090621 21:29:27 [Note] Event Scheduler: Loaded 0 events
090621 21:29:27 [Note] M:\Program Files\MySQL\MySQL Server 5.1\bin\mysqld: ready for connections.
Version: '5.1.35-community'  socket: ''  port: 3306  MySQL Community Server (GPL)
090621 21:30:18  InnoDB: Assertion failure in thread 2396 in file .\row\row0mysql.c line 1534
InnoDB: Failing assertion: index->type & DICT_CLUSTERED
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.1/en/forcing-recovery.html
InnoDB: about forcing recovery.
InnoDB: Thread 2140 stopped in file G:\mysql-5.1.35-winbuild\mysql-community-nt-5.1.35-build\storage\innobase\include\buf0buf.ic line 169
090621 21:30:18 - mysqld got exception 0xc0000005 ;
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.

key_buffer_size=183500800
read_buffer_size=65536
max_used_connections=12
max_threads=100
threads_connected=7
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 211831 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0xe2ac210
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...
006B5906    mysqld.exe!row_unlock_for_mysql()[row0mysql.c:1534]
006BDB18    mysqld.exe!row_search_for_mysql()[row0sel.c:4090]
006AAA30    mysqld.exe!ha_innobase::general_fetch()[ha_innodb.cc:4589]
006AAAED    mysqld.exe!ha_innobase::index_next()[ha_innodb.cc:4624]
00447E0B    mysqld.exe!handler::read_range_next()[handler.cc:4212]
00445F08    mysqld.exe!handler::read_multi_range_next()[handler.cc:4092]
004D7935    mysqld.exe!QUICK_RANGE_SELECT::get_next()[opt_range.cc:8424]
004E9261    mysqld.exe!rr_quick()[records.cc:313]
0053C839    mysqld.exe!mysql_delete()[sql_delete.cc:335]
00556878    mysqld.exe!mysql_execute_command()[sql_parse.cc:3273]
0055A8C3    mysqld.exe!mysql_parse()[sql_parse.cc:5933]
0055B3B3    mysqld.exe!dispatch_command()[sql_parse.cc:1218]
0055C1B7    mysqld.exe!do_command()[sql_parse.cc:861]
005DF511    mysqld.exe!handle_one_connection()[sql_connect.cc:1115]
0064588B    mysqld.exe!pthread_start()[my_winthread.c:85]
0072ADD3    mysqld.exe!_callthreadstart()[thread.c:293]
FCB0E900    
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 108D8890=delete from historicalprices where codSecurity=23 and (datTimestamp between '2009-06-17 00:00:00' and '2009-06-18 23:59:00')
thd->thread_id=17
thd->killed=NOT_KILLED
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.
InnoDB: Thread 3304 stopped in file .\handler\ha_innodb.cc line 5769
InnoDB: Thread 2200 stopped in file .\mem\mem0pool.c line 341
InnoDB: Thread 2392 stopped in file .\os\os0sync.c line 574
InnoDB: Thread 3688 stopped in file .\sync\sync0arr.c line 337
InnoDB: Thread 3276 stopped in file .\sync\sync0arr.c line 337
InnoDB: Log scan progressed past the checkpoint lsn 3 1436578163

How to repeat:
My application gather data from Internet, delete some old records from the table historicalprices with 20 million records and insert at the same time thousands of records in this table. I use around 100 threads in my java application to do this work.

The delete uses a where clause based on the column of type DATETIME that is indexed.

DELETE From HistoricalPrices as hist WHERE codSecurity = ? AND datTimestamp between :startDate AND :finalDate

To reproduce the error:
1) use TRANSACTION_READ_COMMITTED or set explicitly innodb_locks_unsafe_for_binlog=1 in "my.ini"
2) Use the tables below with a program to generate random inserts and deletes concurrently using about 100 threads. 
3) Wait 20-50 seconds. After some inserts and deletes, the application and/or mysql server will crash.

CREATE TABLE  `security` (
  `codSecurity` int(11) NOT NULL AUTO_INCREMENT,
  `codCountry` int(11) DEFAULT NULL,
  `codSecurityType` int(11) NOT NULL,
  `codExchange` int(11) DEFAULT NULL,
  `strSymbolIB` varchar(12) NOT NULL,
  `strSymbolYahoo` varchar(16) DEFAULT NULL,
  `strName` varchar(255) NOT NULL,
  `strCurrency` varchar(3) DEFAULT NULL,
  `strAvailableExchanges` varchar(255) DEFAULT NULL,
  `bolNoHistorical` bit(1) DEFAULT NULL,
  PRIMARY KEY (`codSecurity`),
  KEY `FK3892774044C7FC8` (`codExchange`),
  KEY `FK38927740A479D36A` (`codCountry`),
  KEY `FK38927740BD401396` (`codSecurityType`),
  KEY `idx_SymbolIB` (`strSymbolIB`),
  KEY `idx_security_name` (`strName`),
  CONSTRAINT `FK3892774044C7FC8` FOREIGN KEY (`codExchange`) REFERENCES `exchange` (`codExchange`),
  CONSTRAINT `FK38927740A479D36A` FOREIGN KEY (`codCountry`) REFERENCES `country` (`codCountry`),
  CONSTRAINT `FK38927740BD401396` FOREIGN KEY (`codSecurityType`) REFERENCES `securitytype` (`codSecurityType`)
) ENGINE=InnoDB AUTO_INCREMENT=38130 DEFAULT CHARSET=latin1;

CREATE TABLE  `historicalprices` (
  `codHistoricalPrices` int(11) NOT NULL AUTO_INCREMENT,
  `codSecurity` int(11) NOT NULL,
  `datTimestamp` datetime NOT NULL,
  `numOpen` float DEFAULT NULL,
  `numDayHigh` float DEFAULT NULL,
  `numDayLow` float DEFAULT NULL,
  `numClose` float DEFAULT NULL,
  `numAdjustedOpen` float DEFAULT NULL,
  `numAdjustedDayHigh` float DEFAULT NULL,
  `numAdjustedDayLow` float DEFAULT NULL,
  `numAdjustedClose` float DEFAULT NULL,
  `numVolume` int(11) DEFAULT NULL,
  `bolDayTemp` bit(1) DEFAULT b'0',
  PRIMARY KEY (`codHistoricalPrices`),
  KEY `FKA7BF5594883E5202` (`codSecurity`),
  KEY `idx_timestamp` (`datTimestamp`),
  KEY `idx_numClose` (`numClose`),
  CONSTRAINT `FKA7BF5594883E5202` FOREIGN KEY (`codSecurity`) REFERENCES `security` (`codSecurity`)
) ENGINE=InnoDB AUTO_INCREMENT=19648832 DEFAULT CHARSET=latin1;

Suggested fix:
I tried the solutions below:

FAILED) use TRANSACTION_READ_COMMITTED or set explicitly innodb_locks_unsafe_for_binlog=1 in "my.ini"
PASSED) Delete the indices 'idx_timestamp' and `idx_numClose`

I would not like to delete the indices due to performance issues.

output for the command "show innodb status"

'InnoDB', '', '
=====================================
090621 21:01:17 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 20 seconds
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 77, signal count 73
Mutex spin waits 0, rounds 863, OS waits 10
RW-shared spins 118, OS waits 59; RW-excl spins 7, OS waits 5
------------------------
LATEST DETECTED DEADLOCK
------------------------
090621 20:51:42
*** (1) TRANSACTION:
TRANSACTION 0 3493167, ACTIVE 0 sec, OS thread id 1712 inserting
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 1024, 3 row lock(s), undo log entries 2
MySQL thread id 5, query id 442 localhost 127.0.0.1 mibss update
insert into historicalprices (codSecurity, datTimestamp, numOpen, numDayHigh, numDayLow, numClose, numAdjustedOpen, numAdjustedDayHigh, numAdjustedDayLow, numAdjustedClose, numVolume, bolDayTemp) values (46, '2009-06-17 00:00:00', 4.68, 4.84, 4.4, 4.5, 4.68, 4.84, 4.4, 4.5, 10137400, 0)
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 304043 n bits 200 index `idx_timestamp` of table `mibss`.`historicalprices` trx id 0 3493167 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 8; hex 80001245b6263280; asc    E &2 ;; 1: len 4; hex 812b9ee2; asc  +  ;;

*** (2) TRANSACTION:
TRANSACTION 0 3493164, ACTIVE 0 sec, OS thread id 3848 fetching rows, thread declared inside InnoDB 318
mysql tables in use 1, locked 1
120 lock struct(s), heap size 11584, 16423 row lock(s), undo log entries 2
MySQL thread id 6, query id 431 localhost 127.0.0.1 mibss updating
delete from historicalprices where codSecurity=49 and (datTimestamp between '2009-06-17 00:00:00' and '2009-06-18 23:59:00')
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 0 page no 304043 n bits 200 index `idx_timestamp` of table `mibss`.`historicalprices` trx id 0 3493164 lock_mode X
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

 ...cut

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 0 page no 304044 n bits 192 index `idx_timestamp` of table `mibss`.`historicalprices` trx id 0 3493164 lock_mode X waiting
Record lock, heap no 116 PHYSICAL RECORD: n_fields 2; compact format; info bits 0
 0: len 8; hex 80001245b6263280; asc    E &2 ;; 1: len 4; hex 812bd12c; asc  + ,;;

*** WE ROLL BACK TRANSACTION (1)
------------
TRANSACTIONS
------------
Trx id counter 0 3493173
Purge done for trx's n:o < 0 3493172 undo n:o < 0 0
History list length 20
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 0 0, not started, OS thread id 3928
MySQL thread id 15, query id 553 localhost 127.0.0.1 root
show innodb status
--------
FILE I/O
--------
I/O thread 0 state: wait Windows aio (insert buffer thread)
I/O thread 1 state: wait Windows aio (log thread)
I/O thread 2 state: wait Windows aio (read thread)
I/O thread 3 state: wait Windows aio (write thread)
Pending normal aio reads: 0, aio writes: 0,
 ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
Pending flushes (fsync) log: 0; buffer pool: 0
1355 OS file reads, 96 OS file writes, 37 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 705, seg size 707,
0 inserts, 0 merged recs, 0 merges
Hash table size 1407101, node heap has 95 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number 3 1436578153
Log flushed up to   3 1436578153
Last checkpoint at  3 1436578153
0 pending log writes, 0 pending chkp writes
36 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total memory allocated 386714664; in additional pool allocated 1606784
Dictionary memory allocated 80296
Buffer pool size   21696
Free buffers       20256
Database pages     1345
Modified db pages  0
Pending reads 0
Pending writes: LRU 0, flush list 0, single page 0
Pages read 1345, created 0, written 62
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
1 read views open inside InnoDB
Main thread id 2356, state: waiting for server activity
Number of rows inserted 13, updated 5, deleted 20, read 44077
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================
'

I think this is a duplicate of bug #45357 (crash part). Feel free to report another bug about the deadlock with READ UNCOMMITTED isolation level, if you really think it is a bug.

I think it is also related to this http://bugs.mysql.com/bug.php?id=43766

Pushed into mysql-trunk 5.5.6-m3 (revid:alik@sun.com-20100731131027-1n61gseejyxsqk5d) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (merge vers: 5.1.49) (pib:18)

Pushed into mysql-trunk 5.5.6-m3 (revid:alik@sun.com-20100731131027-1n61gseejyxsqk5d) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (merge vers: 5.1.49) (pib:18)

Pushed into mysql-trunk 5.5.6-m3 (revid:alik@sun.com-20100731131027-1n61gseejyxsqk5d) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (merge vers: 5.1.49) (pib:18)

Pushed into mysql-trunk 5.5.6-m3 (revid:alik@sun.com-20100731131027-1n61gseejyxsqk5d) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (merge vers: 5.1.49) (pib:18)

Pushed into mysql-trunk 5.5.6-m3 (revid:alik@sun.com-20100731131027-1n61gseejyxsqk5d) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (merge vers: 5.1.49) (pib:18)

Pushed into mysql-trunk 5.5.6-m3 (revid:alik@sun.com-20100731131027-1n61gseejyxsqk5d) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (merge vers: 5.1.49) (pib:18)

Pushed into mysql-trunk 5.5.6-m3 (revid:alik@sun.com-20100731131027-1n61gseejyxsqk5d) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (merge vers: 5.1.49) (pib:18)

Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804080001-bny5271e65xo34ig) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (merge vers: 5.1.49) (pib:18)

Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804080001-bny5271e65xo34ig) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (merge vers: 5.1.49) (pib:18)

Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804080001-bny5271e65xo34ig) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (merge vers: 5.1.49) (pib:18)

Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804080001-bny5271e65xo34ig) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (merge vers: 5.1.49) (pib:18)

Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804080001-bny5271e65xo34ig) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (merge vers: 5.1.49) (pib:18)

Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804080001-bny5271e65xo34ig) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (merge vers: 5.1.49) (pib:18)

Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804081533-c1d3rbipo9e8rt1s) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (merge vers: 5.1.49) (pib:18)

Pushed into mysql-trunk 5.6.1-m4 (revid:alik@ibmvm-20100804081533-c1d3rbipo9e8rt1s) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (merge vers: 5.1.49) (pib:20)

Pushed into mysql-next-mr (revid:alik@ibmvm-20100804081630-ntapn8bf9pko9vj3) (version source revid:marko.makela@oracle.com-20100621094008-o9fa153s3f09merw) (pib:20)