Bug #68051 Killing a query inside InnoDB causes it to eventually crash with an assertion
Submitted: 8 Jan 2013 19:22 Modified: 11 Mar 2013 19:21
Reporter: Davi Arnaut (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S1 (Critical)
Version:5.5.29 OS:Any
Assigned to: CPU Architecture:Any
Tags: assertion failure, btr0pcur.c, crash, KILL QUERY, regression

[8 Jan 2013 19:22] Davi Arnaut
Description:
Killing a query that is inside InnoDB searching for a row (more precisely,
in row_search_for_mysql) causes InnoDB to crash with an assertion failure
the next time the same table (cursor) instance is used again.

This is a regression introduced by the fix for Bug#14704286 (revision-id:
krunal.bauskar@oracle.com-20121015041950-v9r57913ucuh4f21), which introduce
a check in row_search_for_mysql to interrupt the function if the query has
been killed. The problem is that the error path is not handled correctly as
the cursor position needs to be stored in some cases. When the cursor is
eventually used again, InnoDB asserts with the following message:

 len 224; hex 589e611700000000dd0047abaa2a0000208a19abaa2a00000000000000000000000000000000000000000000000000000300000000000000010000000000000001000000000000000000000000000000000000000000000000000000000000000100000000000000000000000000000016039cc3270100000000000000000000010000000000000083445107000000008f356c170000000003000000000000000100000000000000208a19abaa2a0000010000000000000060e11177000000000200000000000000f80460170000000088356c17000000001800000000000000; asc X a       G  *       *                                                                                              '                    DQ      5l                          *          `  w              `      5l             ;
TRANSACTION 32E9, ACTIVE 1 sec fetching rows
mysql tables in use 6, locked 0
MySQL thread id 6, OS thread handle 0x47ce2940, query id 20825 localhost 127.0.0.1 root preparing
SELECT ...
2013-01-05 08:53:57 42598  InnoDB: Assertion failure in thread 1204693312 in file btr0pcur.c line 250
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.5/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
05:53:57 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.

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

Thread pointer: 0x175e8910
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 = 47ce20f8 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x2e) [0x7c9d5e]
/usr/sbin/mysqld(handle_fatal_signal+0x38a) [0x68296a]
/lib64/libpthread.so.0 [0x2b713a2eeb10]
/lib64/libc.so.6(gsignal+0x35) [0x2b713b719265]
/lib64/libc.so.6(abort+0x110) [0x2b713b71ad10]
/usr/sbin/mysqld [0x883f40]
/usr/sbin/mysqld [0x83c864]
/usr/sbin/mysqld [0x8407a7]
/usr/sbin/mysqld [0x81bfe9]
/usr/sbin/mysqld(subselect_indexsubquery_engine::exec()+0x257) [0x703d37]
/usr/sbin/mysqld(Item_subselect::exec()+0x4d) [0x7015bd]
/usr/sbin/mysqld(Item_in_subselect::val_bool()+0x20) [0x701c00]
/usr/sbin/mysqld(Item::val_bool_result()+0xd) [0x5113cd]
/usr/sbin/mysqld(Item_in_optimizer::val_int()+0x141) [0x6b2101]
/usr/sbin/mysqld(Item::val_bool()+0x62) [0x6906c2]
/usr/sbin/mysqld(Item_func_not::val_int()+0x1c) [0x6adeec]
/usr/sbin/mysqld [0x59769e]
/usr/sbin/mysqld(sub_select_cache(JOIN*, st_join_table*, bool)+0x77) [0x597e67]
/usr/sbin/mysqld [0x59895b]
/usr/sbin/mysqld(JOIN::exec()+0x1272) [0x5acb92]
/usr/sbin/mysqld(mysql_select(THD*, Item***, TABLE_LIST*, unsigned int, List<Item>&, Item*, unsigned int, st_order*, st_order*, Item*, st_order*, unsigned long long, select_result*, st_select_lex_unit*, st_select_lex*)+0x192) [0x5ae0a2]
/usr/sbin/mysqld(handle_select(THD*, LEX*, select_result*, unsigned long)+0x16d) [0x5b1d6d]
/usr/sbin/mysqld [0x570ff1]
/usr/sbin/mysqld(mysql_execute_command(THD*)+0x164a) [0x57400a]
/usr/sbin/mysqld(mysql_parse(THD*, char*, unsigned int, Parser_state*)+0x184) [0x578e94]
/usr/sbin/mysqld(dispatch_command(enum_server_command, THD*, char*, unsigned int)+0x68b) [0x579a5b]
/usr/sbin/mysqld(do_command(THD*)+0xc4) [0x57aaa4]
/usr/sbin/mysqld(do_handle_one_connection(THD*)+0xfc) [0x60e82c]
/usr/sbin/mysqld(handle_one_connection+0x9) [0x60e909]
/lib64/libpthread.so.0 [0x2b713a2e673d]
/lib64/libc.so.6(clone+0x6d) [0x2b713b7bcf6d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (176d3130): SELECT ...

How to repeat:
The problem can be easily reproduced using the HANDLER statement:

CREATE TABLE t1 (a INT PRIMARY KEY) ENGINE=InnoDB;
INSERT INTO t1 VALUES (1),(2),(3),(4),(5),(6);
HANDLER t1 OPEN;
HANDLER t1 READ FIRST;
SET DEBUG_SYNC = 'row_search_rec_loop SIGNAL parked WAIT_FOR go';
send HANDLER t1 READ NEXT;
connect(con1,localhost,root,,);
SET DEBUG_SYNC = 'now WAIT_FOR parked';
SELECT ID INTO @conn_id FROM INFORMATION_SCHEMA.PROCESSLIST
  WHERE STATE = 'debug sync point: row_search_rec_loop';
KILL QUERY @conn_id;
connection default;
--error ER_QUERY_INTERRUPTED
reap;
HANDLER t1 READ NEXT;

--- a/storage/innobase/row/row0sel.c
+++ b/storage/innobase/row/row0sel.c
@@ -30,6 +30,9 @@ Select
 Created 12/19/1997 Heikki Tuuri
 *******************************************************/
 
+#include "m_string.h" /* for my_sys.h */
+#include "my_sys.h" /* DEBUG_SYNC_C */
+
 #include "row0sel.h"
 
 #ifdef UNIV_NONINL
@@ -3918,6 +3921,7 @@ wait_table_again:
        }
 
 rec_loop:
+       DEBUG_SYNC_C("row_search_rec_loop");
        if (trx_is_interrupted(trx)) {
                err = DB_INTERRUPTED;
                goto normal_return;

Suggested fix:
Either revert the change that caused the problem, or fix the error/interrupted path
to properly store the cursor position and/or perform the necessary cleanups.
[8 Jan 2013 20:10] Davi Arnaut
Also worth mentioning that the test for Bug#14704286 does not actually test
the change, it is just killing a query at some random point of its execution.
[9 Jan 2013 6:15] Shane Bester
Version: '5.5.29-debug' MySQL Community Server - Debug (GPL)
[ERROR] mysql_ha_read: Got error -1 when reading table 't1'
[ERROR] mysql_ha_read: Got error -1 when reading table 't1'
 len 120; hex 1085530463c0df04c0f2550400000000000 <cut>
InnoDB: Assertion failure in thread 5024 in file btr0pcur.c line 250
InnoDB: We intentionally generate a memory trap.

mysqld-debug.exe!btr_pcur_restore_position_func()[btr0pcur.c:250]
mysqld-debug.exe!sel_restore_position_for_mysql()[row0sel.c:3100]
mysqld-debug.exe!row_search_for_mysql()[row0sel.c:3848]
mysqld-debug.exe!ha_innobase::general_fetch()[ha_innodb.cc:6195]
mysqld-debug.exe!ha_innobase::rnd_next()[ha_innodb.cc:6389]
mysqld-debug.exe!mysql_ha_read()[sql_handler.cc:660]
mysqld-debug.exe!mysql_execute_command()[sql_parse.cc:3737]
mysqld-debug.exe!mysql_parse()[sql_parse.cc:5627]
mysqld-debug.exe!dispatch_command()[sql_parse.cc:1037]
mysqld-debug.exe!do_command()[sql_parse.cc:773]
mysqld-debug.exe!do_handle_one_connection()[sql_connect.cc:853]
mysqld-debug.exe!handle_one_connection()[sql_connect.cc:772]
mysqld-debug.exe!pthread_start()[my_winthread.c:61]
mysqld-debug.exe!_callthreadstartex()[threadex.c:348]
mysqld-debug.exe!_threadstartex()[threadex.c:331]
[16 Feb 2013 1:13] Jervin R
Davi,

I tested your test case on 5.5.29 without much luck, even manually - is there something I might be missing? The running sandbox has debug-sync-timeout=5.

[revin@forge mysql-test]$ ./mtr --vardir=/ssd/msb/var --extern socket=/tmp/mysql_sandbox5529.sock t/68051.test
Logging: ./mtr  --vardir=/ssd/msb/var --extern socket=/tmp/mysql_sandbox5529.sock t/68051.test
MySQL Version 5.5.29
Checking supported features...
 - skipping ndbcluster
 - skipping SSL, mysqld not compiled with SSL
Collecting tests...
vardir: /ssd/msb/var
Using server port 45511

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

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 13000..13009
CREATE TABLE t1 (a INT PRIMARY KEY) ENGINE=InnoDB;
INSERT INTO t1 VALUES (1),(2),(3),(4),(5),(6);
HANDLER t1 OPEN;
HANDLER t1 READ FIRST;
a
1
SET DEBUG_SYNC = 'row_search_rec_loop SIGNAL parked WAIT_FOR go';
HANDLER t1 READ NEXT;
SELECT @@version;
@@version
5.5.29-debug
SET DEBUG_SYNC = 'now WAIT_FOR parked';
Warnings:
Warning 1639    debug sync point wait timed out
SELECT ID INTO @conn_id FROM INFORMATION_SCHEMA.PROCESSLIST
WHERE STATE = 'debug sync point: row_search_rec_loop';
Warnings:
Warning 1329    No data - zero rows fetched, selected, or processed
main.68051                               [ fail ]
        Test ended at 2013-02-15 20:03:05

mysqltest: At line 13: query 'KILL QUERY @conn_id' failed: 1094: Unknown thread id: 0

mysqltest failed but provided no output

 - saving '/ssd/msb/var/log/main.68051/' to '/ssd/msb/var/log/main.68051/'
--------------------------------------------------------------------------
The servers were restarted 0 times
Spent 0.000 of 6 seconds executing testcases

Completed: Failed 1/1 tests, 0.00% were successful.

Failing test(s): main.68051

The log files in var/log may give you some hint of what went wrong.

If you want to report this error, please read first the documentation
at http://dev.mysql.com/doc/mysql/en/mysql-test-suite.html

mysql-test-run: *** ERROR: there were failing test cases
[11 Mar 2013 19:21] Bugs System
Added 5.1.69, 5.5.31, 5.6.11, 5.7.1 changelog.

Killing a query caused an InnoDB assertion failure when the same
table (cursor) instance was used again. This is the result of a
regression error introduced by the fix for Bug#14704286. The fix
introduced a check to handle kill signals for long running
queries but the cursor was not restored to the proper state.
[11 Apr 2013 9:39] Shane Bester
bug #68928 is a duplicate
[7 Jun 2013 17:42] Shane Bester
Bug #69426 is a duplicate
[24 Dec 2014 7:23] Umesh Shastry
Bug #75304 marked as duplicate of this
[25 Apr 2015 10:13] Shane Bester
http://bugs.mysql.com/bug.php?id=76584 is a duplicate of this
[28 Apr 2015 12:10] Shane Bester
http://bugs.mysql.com/bug.php?id=69312 is a duplicate of this