MySQL Bugs: #40113: Embedded SELECT inside UPDATE or DELETE can timeout without error

Bug #40113	Embedded SELECT inside UPDATE or DELETE can timeout without error
Submitted:	17 Oct 2008 15:51	Modified:	7 Aug 2009 0:52
Reporter:	Bob Hansen	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Locking	Severity:	S2 (Serious)
Version:	5.0, 5.1, 6.0 bzr	OS:	Any (Linux, Win XP SP2 32bit)
Assigned to:	Georgi Kodinov	CPU Architecture:	Any
Tags:	Embedded Select Timeout Error Fail Secretly Silent Update Delete, regression

Description:
There is definitely a problem here, so please read this carefully.

Define Tables:
Meals (StudentID bigint)
Primary key StudentID
Engine=InnoDB

Students (StudentNum integer, StudentID bigint, Name char(30))
Primary key StudentNum
Engine=InnoDB

Consider that a row in Students is locked in a transaction via
SELECT * FROM Students WHERE StudentNum='3';
and that each unique StudentNum in Students has a corresponding unique StudentID (in the same row).

Now consider the following 4 statements being executed by a different connection.

1. SELECT StudentID FROM Meals WHERE StudentID=(SELECT StudentID FROM Students WHERE StudentNum='3') FOR UPDATE;

2. INSERT INTO Meals (StudentID) VALUES (SELECT StudentID FROM Students WHERE StudentNum='3');

3. UPDATE Meals SET StudentID='12345' WHERE StudentID=(SELECT StudentID FROM Students WHERE StudentNum='3');

4. DELETE FROM Meals WHERE StudentID=(SELECT StudentID FROM Students WHERE StudentNum='3');

Problems:
A. #2 times out due to Students being locked. This could be accurate although I disagree with it. We are doing an embedded select to translate the StudentNum into a StudentID (not for update) and shouldn't be locking anything. #1 should also lock because it is SELECT..FOR UPDATE but it does not timeout, it succeeds.

B. Both the UPDATE and DELETE hang for two seconds, then "succeed". That is, when they are executed, we wait for approximately 120 ticks (2 seconds) before we get a result back. Take note that LOCK_WAIT_TIMEOUT on the server is set to 1 second. We get an SQL result back of SQL_SUCCESS but no values were UPDATE'd or DELETE'd. This is definitely an error. If it was unable to change a value due to a lock, then it should fail with a Timeout error. Although, again, I argue that it shouldn't be trying to lock Students at all.

How to repeat:
-Create the two tables.
-Insert a row into each table, with a common StudentID between them.
-Lock the row in Students in a transaction.
-Execute the 4 statements as listed.

This can also be reproduced with the MySQL Command Line Client. (see attached file) PurchLunch is similar to Meals.

Suggested fix:
The UPDATE and DELETE are almost certainly broken. They succeed but don't change anything, so that is definitely wrong.

The SELECT...FOR UPDATE and INSERT in my opinion should both or neither be locking but I'm not certain. Given the situation I would suggest checking these as well to make sure they are doing as they are expected.

Succeed but timeout and no data changed.

Attachment: delete and insert lock too.JPG (image/jpeg, text), 114.52 KiB.

Another comment on the attached file.

Execution order:
1. Top window
2. Bottom window
3. Refresh Query Browser in the middle..no changes were made.

Thank you for the report.

I can not repeat described behavior with test data. Additionally version 5.0.45 is old. Please try with current version 5.0.67 and if problem still exists provide output of SHOW WARNINGS run immediately after UPDATE and DELETE statement and try to create repeatable test case. At least provide outpupt of SHOW CREATE TABLE for real tables and real queries.

I upgraded server to 5.0.67 and am still having the problem. Here is the console output with SHOW WARNINGS.

FIRST, I locked the record in MySQL Command LIne Client #1.

mysql> start transaction;
Query OK, 0 rows affected (0.00 sec)

mysql> select jmcrecordnumber from 0809_students where jmcrecordnumber='7' for u
pdate;
+-----------------+
| jmcrecordnumber |
+-----------------+
|               7 |
+-----------------+
1 row in set (0.00 sec)

mysql> show warnings;
Empty set (0.02 sec)

THEN, I try to modify data in the second table using the MySQL Command Line Client #2.

mysql> insert into 0809_purchbreakfast (sturefnum) values ((select sturefnum fro
m 0809_students where jmcrecordnumber='7'));
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction
mysql> show warnings;
+-------+------+--------------------------------------------------------+
| Level | Code | Message                                                |
+-------+------+--------------------------------------------------------+
| Error | 1205 | Lock wait timeout exceeded; try restarting transaction |
| Error | 1048 | Column 'StuRefNum' cannot be null                      |
| Error | 1105 | Unknown error                                          |
+-------+------+--------------------------------------------------------+
3 rows in set (0.00 sec)

mysql> update 0809_purchbreakfast set sturefnum='7000000' where sturefnum=(selec
t sturefnum from 0809_students where jmcrecordnumber='7');
Query OK, 0 rows affected, 1 warning (2.83 sec)

mysql> show warnings;
+-------+------+--------------------------------------------------------+
| Level | Code | Message                                                |
+-------+------+--------------------------------------------------------+
| Error | 1205 | Lock wait timeout exceeded; try restarting transaction |
+-------+------+--------------------------------------------------------+
1 row in set (0.00 sec)

mysql> delete from 0809_purchbreakfast where sturefnum=(select sturefnum from 08
09_students where jmcrecordnumber='7');
Query OK, 0 rows affected, 1 warning (2.14 sec)

mysql> show warnings;
+-------+------+--------------------------------------------------------+
| Level | Code | Message                                                |
+-------+------+--------------------------------------------------------+
| Error | 1205 | Lock wait timeout exceeded; try restarting transaction |
+-------+------+--------------------------------------------------------+
1 row in set (0.00 sec)

Here's table syntax and initial records. Note that the intention here is that there is 1 unique StuRefNum and 1 unique JmcRecordNumber for each student.

CREATE TABLE `0809_PurchBreakfast` (
  `StuRefNum` bigint(20) NOT NULL default '0',
  `DayIndex` smallint(6) NOT NULL default '0',
  PRIMARY KEY  (`StuRefNum`,`DayIndex`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

INSERT INTO `0809_PurchBreakfast` (`StuRefNum`,`DayIndex`) VALUES 
 (1070109,99);
/*!40000 ALTER TABLE `0809_PurchBreakfast` ENABLE KEYS */;

CREATE TABLE `0809_Students` (
  `JMCRecordNumber` bigint(20) NOT NULL default '0',
  `StuRefNum` bigint(20) default NULL,
  `LastName` char(18) default NULL,
  `FirstName` char(12) default NULL,
  PRIMARY KEY  (`JMCRecordNumber`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

/*!40000 ALTER TABLE `0809_Students` DISABLE KEYS */;
INSERT INTO `0809_Students` (`JMCRecordNumber`,`StuRefNum`,`LastName`,`FirstName`) VALUES 
(7,1070109,'Payne','Max');
/*!40000 ALTER TABLE `0809_Students` ENABLE KEYS */;

Can I get a status update on this bug report please? Thanks.

Thank you for the feedback.

Verified as described with 5.0 and got crashes with 5.1 and 6.0:

$cat src/tests/t/bug40113.test 
--source include/have_innodb.inc

CREATE TABLE `0809_purchbreakfast` (
  `sturefnum` bigint(20) NOT NULL default '0',
  `DayIndex` smallint(6) NOT NULL default '0',
  PRIMARY KEY  (`sturefnum`,`DayIndex`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

INSERT INTO `0809_purchbreakfast` (`sturefnum`,`DayIndex`) VALUES 
 (1070109,99);

CREATE TABLE `0809_students` (
  `jmcrecordnumber` bigint(20) NOT NULL default '0',
  `sturefnum` bigint(20) default NULL,
  `LastName` char(18) default NULL,
  `FirstName` char(12) default NULL,
  PRIMARY KEY  (`jmcrecordnumber`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

INSERT INTO `0809_students` (`jmcrecordnumber`,`sturefnum`,`LastName`,`FirstName`) VALUES

(7,1070109,'Payne','Max');

select * from 0809_purchbreakfast;

begin;

select jmcrecordnumber from 0809_students where jmcrecordnumber='7' for update;

connect (addconroot, localhost, root,,);
connection addconroot;

begin;

#select jmcrecordnumber from 0809_students where jmcrecordnumber='7' for update;

insert into 0809_purchbreakfast (sturefnum) values ((select sturefnum from 0809_students where jmcrecordnumber='7'));

#update 0809_purchbreakfast set sturefnum='7000000' where sturefnum=(select sturefnum from 0809_students where jmcrecordnumber='7');

#delete from 0809_purchbreakfast where sturefnum=(select sturefnum from 0809_students where jmcrecordnumber='7');

select * from 0809_purchbreakfast;

Comment/un-comment queries to test SELECT/INSERT/UPDATE/DELETE

With SELECT - query fails with "Lock wait timeout exceeded;" which is correct
With INSERT - query fails with "Lock wait timeout exceeded;" which is correct
With UPDATE - 4.1 fails with "Lock wait timeout exceeded;" which is correct; 5.0 doesn't fail, but shows warning "Lock wait timeout exceeded;"; 5.1 crashes, 6.0 crashes
With DELETE - 4.1 fails with "Lock wait timeout exceeded;" which is correct; 5.0 doesn't fail, but shows warning "Lock wait timeout exceeded;"; 5.1 crashes, 6.0 crashes

Backtrace is similar in all cases (below is from 5.1 and UPDATE):

mysqld: sql_class.cc:426: void Diagnostics_area::set_ok_status(THD*, ha_rows, ulonglong, const char*): Assertion `! is_set()' failed.
081126 11:17:54 - 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.

key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=2
max_threads=151
threads_connected=2
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 59975 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x9d99eb8
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...
stack_bottom = 0xb29fc448 thread_stack 0x30000
/users/ssmirnova/src/mysql-5.1/sql/mysqld(my_print_stacktrace+0x26)[0x86c9801]
/users/ssmirnova/src/mysql-5.1/sql/mysqld(handle_segfault+0x2d3)[0x828bdab]
[0x2ce420]
/lib/libc.so.6(abort+0xf8)[0x316678]
/lib/libc.so.6(__assert_fail+0xfd)[0x30e269]
/users/ssmirnova/src/mysql-5.1/sql/mysqld(_ZN16Diagnostics_area13set_ok_statusEP3THDyyPKc+0x51)[0x8272593]
/users/ssmirnova/src/mysql-5.1/sql/mysqld(_Z5my_okP3THDyyPKc+0x59)[0x81b4ebf]
/users/ssmirnova/src/mysql-5.1/sql/mysqld(_Z12mysql_updateP3THDP10TABLE_LISTR4ListI4ItemES6_PS4_jP8st_ordery15enum_duplicatesb+0xa7b)[0x83473ad]
/users/ssmirnova/src/mysql-5.1/sql/mysqld(_Z21mysql_execute_commandP3THD+0x2db8)[0x82a382c]
/users/ssmirnova/src/mysql-5.1/sql/mysqld(_Z11mysql_parseP3THDPKcjPS2_+0x230)[0x82aa61a]
/users/ssmirnova/src/mysql-5.1/sql/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0xa78)[0x82ab222]
/users/ssmirnova/src/mysql-5.1/sql/mysqld(_Z10do_commandP3THD+0x260)[0x82ac42a]
/users/ssmirnova/src/mysql-5.1/sql/mysqld(handle_one_connection+0x115)[0x82990f5]
/lib/libpthread.so.0[0x45fbd4]
/lib/libc.so.6(__clone+0x5e)[0x3b74fe]
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0x9db3e38 = update 0809_purchbreakfast set sturefnum='7000000' where sturefnum=(select sturefnum from 0809_students where jmcrecordnumber='7')
thd->thread_id=2
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.
Writing a core file

How are you coming along with this? We are trying to be patient but it is taking awhile. Thanks.

While we're waiting for a status update I just want to mention that this isn't crashing MySQL. The behavior is erroneous but it does not crash MySQL.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/76721

2779 Georgi Kodinov	2009-06-19
      Bug #40113: Embedded SELECT inside UPDATE or DELETE can timeout 
      without error
      
      When using quick access methods for searching rows in UPDATE or 
      DELETE there was no check if a fatal error was not already sent 
      to the client while evaluating the quick condition.
      As a result a false OK (following the error) was sent to the 
      client and the error was thus transformed into a warning.
      
      Fixed by checking for errors sent to the client during 
      SQL_SELECT::check_quick() and treating them as real errors.
      
      Fixed a wrong test case in group_min_max.test
     @ mysql-test/r/bug40113.result
        Bug #40013: test case
     @ mysql-test/r/group_min_max.result
        Bug #40013: fixed a wrong test case
     @ mysql-test/t/bug40113-master.opt
        Bug #40013: test case
     @ mysql-test/t/bug40113.test
        Bug #40013: test case
     @ mysql-test/t/group_min_max.test
        Bug #40013: fixed a wrong test case
     @ sql/sql_delete.cc
        Bug #40113: check for errors evaluating the quick select
     @ sql/sql_update.cc
        Bug #40113: check for errors evaluating the quick select

5.0-patch approved, switching to "in progress" for a new patch on 5.1+

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/78546

2779 Georgi Kodinov	2009-07-13
      Bug #40113: Embedded SELECT inside UPDATE or DELETE can timeout 
      without error
      
      When using quick access methods for searching rows in UPDATE or 
      DELETE there was no check if a fatal error was not already sent 
      to the client while evaluating the quick condition.
      As a result a false OK (following the error) was sent to the 
      client and the error was thus transformed into a warning.
      
      Fixed by checking for errors sent to the client during 
      SQL_SELECT::check_quick() and treating them as real errors.
      
      Fixed a wrong test case in group_min_max.test
      Fixed a wrong return code in mysql_update() and mysql_delete()
     @ mysql-test/r/bug40113.result
        Bug #40013: test case
     @ mysql-test/r/group_min_max.result
        Bug #40013: fixed a wrong test case
     @ mysql-test/t/bug40113-master.opt
        Bug #40013: test case
     @ mysql-test/t/bug40113.test
        Bug #40013: test case
     @ mysql-test/t/group_min_max.test
        Bug #40013: fixed a wrong test case
     @ sql/sql_delete.cc
        Bug #40113: check for errors evaluating the quick select
     @ sql/sql_update.cc
        Bug #40113: check for errors evaluating the quick select

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/78556

3020 Georgi Kodinov	2009-07-13 [merge]
      Merge of the fix for bug #40113 to 5.1.

Pushed into 5.4.4-alpha (revid:alik@sun.com-20090804194615-h40sa098mx4z49qg) (version source revid:joro@sun.com-20090714092156-kec27sgwumv3nuzx) (merge vers: 5.4.4-alpha) (pib:11)

Pushed into 5.1.38 (revid:davi.arnaut@sun.com-20090804204317-ggodqkik7de6nfpz) (version source revid:davi.arnaut@sun.com-20090804204317-ggodqkik7de6nfpz) (merge vers: 5.1.38) (pib:11)

Noted in 5.1.38, 5.4.4 changelogs.

When using quick access methods to search for rows in UPDATE and
DELETE statements, there was no check whether a fatal error had
already been sent to the client while evaluating the quick condition.
Consequently, a false OK (following the error) was sent to the
client, causing the error to be incorrectly transformed into a
warning.

Noted in 5.4.2 changelog because next 5.4 version will be 5.4.2 and not 5.4.4.

Ignore previous comment about 5.4.2.

Pushed into 5.1.39-ndb-6.3.28 (revid:jonas@mysql.com-20091001055605-ap2kiaarr7p40mmv) (version source revid:jonas@mysql.com-20091001055605-ap2kiaarr7p40mmv) (merge vers: 5.1.39-ndb-6.3.28) (pib:11)

Pushed into 5.1.39-ndb-7.0.9 (revid:jonas@mysql.com-20091001072547-kv17uu06hfjhgjay) (version source revid:jonas@mysql.com-20091001071652-irejtnumzbpsbgk2) (merge vers: 5.1.39-ndb-7.0.9) (pib:11)

Pushed into 5.1.39-ndb-7.1.0 (revid:jonas@mysql.com-20091001123013-g9ob2tsyctpw6zs0) (version source revid:jonas@mysql.com-20091001123013-g9ob2tsyctpw6zs0) (merge vers: 5.1.39-ndb-7.1.0) (pib:11)

Pushed into 5.1.39-ndb-6.2.19 (revid:jonas@mysql.com-20091005103850-dwij2dojwpvf5hi6) (version source revid:jonas@mysql.com-20090930185117-bhud4ek1y0hsj1nv) (merge vers: 5.1.39-ndb-6.2.19) (pib:11)

The 5.4 fix has been pushed to 5.4.2.