Bug #69969 Failing assertion: prebuilt->trx->conc_state == 1 from subselect
Submitted: 9 Aug 2013 5:47 Modified: 7 Feb 2014 2:14
Reporter: Raghavendra Prabhu Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Optimizer Severity:S2 (Serious)
Version:5.5.33 OS:Any
Assigned to: CPU Architecture:Any
Tags: crash, subselect

[9 Aug 2013 5:47] Raghavendra Prabhu
Description:
When testing with RQG with a grammar containing subselect, the server crashes as:

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

# 2013-08-09T10:57:31 [50216] Killing remaining worker process with pid 52399...
130809 10:57:30 [ERROR] /usr/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130809 10:57:30 [ERROR] /usr/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130809 10:57:30 [ERROR] /usr/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130809 10:57:30 [ERROR] /usr/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130809 10:57:30 [ERROR] /usr/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130809 10:57:30 [ERROR] /usr/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130809 10:57:30 [ERROR] /usr/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130809 10:57:30 [ERROR] /usr/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130809 10:57:30 [ERROR] /usr/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
130809 10:57:30  InnoDB: Assertion failure in thread 139951647098624 in file ha_innodb.cc line 5642
InnoDB: Failing assertion: prebuilt->trx->conc_state == 1
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.
130809 10:57:30 [ERROR] /usr/bin/mysqld: Deadlock found when trying to get lock; try restarting transaction
130809 10:57:30 [ERROR] /usr/bin/mysqld: Sort aborted: Deadlock found when trying to get lock; try restarting transaction
05:27:30 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=8388608
read_buffer_size=131072
max_used_connections=13
max_threads=151
thread_count=13
connection_count=13
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 338503 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x2695980
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 = 7f490835fed8 thread_stack 0x40000
/usr/bin/mysqld(my_print_stacktrace+0x2c)[0x7e190a]
/usr/bin/mysqld(handle_fatal_signal+0x2f9)[0x6a5e0d]
/usr/lib/libpthread.so.0(+0xf0e0)[0x7f490d9880e0]
/usr/lib/libc.so.6(gsignal+0x39)[0x7f490c1371c9]
/usr/lib/libc.so.6(abort+0x148)[0x7f490c1385c8]
/usr/bin/mysqld[0x7f6215]
/usr/bin/mysqld(_ZN12ha_partition10unlock_rowEv+0x4a)[0x9f16ae]
/usr/bin/mysqld(_Z8filesortP3THDP5TABLEP13st_sort_fieldjP10SQL_SELECTybPy+0x1af6)[0x6a4d23]
/usr/bin/mysqld(_Z12mysql_deleteP3THDP10TABLE_LISTP4ItemP10SQL_I_ListI8st_orderEyy+0x7e6)[0x7989ff]
/usr/bin/mysqld(_Z21mysql_execute_commandP3THD+0x3244)[0x594c3e]
/usr/bin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x142)[0x599658]
/usr/bin/mysqld(_Z16dispatch_command19enum_server_commandP3THDPcj+0x780)[0x59a7cd]
/usr/bin/mysqld(_Z10do_commandP3THD+0x242)[0x59c096]
/usr/bin/mysqld(_Z24do_handle_one_connectionP3THD+0x103)[0x642592]
/usr/bin/mysqld(handle_one_connection+0x49)[0x64264f]
/usr/lib/libpthread.so.0(+0x7dd2)[0x7f490d980dd2]
/usr/lib/libc.so.6(clone+0x6d)[0x7f490c1e7cdd]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f48e8029d80): DELETE  FROM `table100_innodb_key_pk_parts_2_int` WHERE `col_char_12_key` IN ( SELECT `col_char_12_key` FROM `table100_innodb_int` WHERE `pk` = 'o' ) ORDER BY `col_char_12`,`col_char_12_key`,`col_int`,`col_int_key`,`pk` LIMIT 3
Connection ID (thread ID): 6
Status: 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

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

Related to http://bugs.mysql.com/bug.php?id=69127 
however,

one of the commits state 

%%%%%%%%%%%%
     revno: 4334.1.2
     committer: Jon Olav Hauglid <jon.hauglid@oracle.com>
     branch nick: mysql-5.5.32-release
     timestamp: Mon 2013-05-06 16:06:32 +0200
     message:
       Bug#16757869: INNODB: POSSIBLE REGRESSION IN 5.5.31, BUG#16004999

       The problem was that if UPDATE with subselect caused a
       deadlock inside InnoDB, this deadlock was not properly
       handled by the SQL layer. This meant that the SQL layer
       would try to unlock the row after InnoDB had rolled
       back the transaction. This caused an assertion inside
       InnoDB.

       This patch fixes the problem by checking for errors
       reported by SQL_SELECT::skip_record() and not calling
       unlock_row() if any errors have been reported.

       This bug is similar to Bug#13586591, but for UPDATE
      rather than DELETE. Similar issues in filesort/opt_range/
       sql_select will be investigated and handled in the scope
       of Bug#16767929

%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%%

So, the filesort case still seems to be not fixed.

The grammar (which I will attach) should contain subselect to reproduce this.

How to repeat:
Test with attached grammar as follows:

perl runall-new.pl --basedir=/usr --vardir=/tmp/tmp.WXuFhS17aL --grammar=subselect.yy --gendata=data.zz --threads=16 --queries=1000 --seed=time

Suggested fix:
It shouldn't crash.
[9 Aug 2013 5:49] Raghavendra Prabhu
RQG Grammar

Attachment: subselect.yy (application/octet-stream, text), 3.00 KiB.

[9 Aug 2013 5:49] Raghavendra Prabhu
Gendata file

Attachment: data.zz (application/octet-stream, text), 1.17 KiB.

[9 Aug 2013 5:50] Raghavendra Prabhu
Full backtrace of the crash.

Attachment: full-bt-of-crash (application/octet-stream, text), 326.99 KiB.

[9 Aug 2013 5:53] Raghavendra Prabhu
The binaries were built from bzr source upto rev. 4412
[13 Aug 2013 10:17] Raghavendra Prabhu
One more thing, you need the debug (UNIV_DEBUG) build of mysql for this.
[13 Aug 2013 14:36] Sinisa Milivojevic
Sorry, we need to know the exact version of RQG that you have used.

Thank you in advance !!!!
[13 Aug 2013 18:32] Shane Bester
InnoDB: Assertion failure in thread 9048 in file ha_innodb.cc line 5642
InnoDB: Failing assertion: prebuilt->trx->conc_state == 1

mysqld-debug.exe!my_sigabrt_handler()[my_thr_init.c:501]
mysqld-debug.exe!raise()[winsig.c:590]
mysqld-debug.exe!abort()[abort.c:71]
mysqld-debug.exe!ha_innobase::unlock_row()[ha_innodb.cc:5642]
mysqld-debug.exe!ha_partition::unlock_row()[ha_partition.cc:3190]
mysqld-debug.exe!find_all_keys()[filesort.cc:651]
mysqld-debug.exe!filesort()[filesort.cc:246]
mysqld-debug.exe!mysql_delete()[sql_delete.cc:247]
mysqld-debug.exe!mysql_execute_command()[sql_parse.cc:3039]
mysqld-debug.exe!mysql_parse()[sql_parse.cc:5632]
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]
[13 Aug 2013 18:46] Shane Bester
a pseudo-random testcase for the RQG-impaired :)

Attachment: bug69969.c (text/plain), 6.98 KiB.

[13 Aug 2013 18:50] Shane Bester
-----
init:
-----
drop table if exists t1,t2;
create table t1(a char(255) primary key,b char(255),key(b) )engine=innodb partition by key(a) partitions 5;
create table t2(c char(255) primary key,d char(255),key(d) )engine=innodb partition by key(c) partitions 5;
-----

Testcase randomly runs the statements:

----
start transaction;
insert ignore into t1(a,b) values ('?','1'); # random tinyint
insert ignore into t2(c,d) values ('?','2'); # random tinyint
replace into t1 select * from t2;
replace into t2 select * from t1;
delete from t1 where b not in ( select c from t2 ) order by a desc,b asc;
commit;
----
[13 Aug 2013 21:27] Raghavendra Prabhu
@Sinisa,

The lp:randgen HEAD from launchpad should do (with .yy and .zz files I have provided).

@Shane,

Thanks for verifying and the test case.
[4 Sep 2013 20:53] Roel Van de Paar
This is seen as:

130824 10:46:46  InnoDB: Assertion failure in thread 140702210119424 in file ha_innodb.cc line 6589
InnoDB: Failing assertion: prebuilt->trx->state == 1

In the server.
[4 Sep 2013 20:57] Roel Van de Paar
error log

Attachment: master_6_050913-0654.err (application/octet-stream, text), 69.54 KiB.

[4 Sep 2013 21:10] Roel Van de Paar
thread apply all bt on core

Attachment: gdb_6_050913-0654_STD.txt (text/plain), 87.68 KiB.

[4 Sep 2013 21:11] Roel Van de Paar
thread apply all bt FULL on core

Attachment: gdb_6_050913-0654_FULL.txt (text/plain), 573.69 KiB.

[4 Sep 2013 21:14] Roel Van de Paar
Can someone at oracle please update the bug tile to "Failing assertion: prebuilt->trx->conc_state == 1 from subselect | Failing assertion: prebuilt->trx->state == 1" so that it is easier to find via Google on that assertion text? Thanks.
[16 Sep 2013 17:52] Sinisa Milivojevic
Roel, 

You would like to add a string :

"| Failing assertion: prebuilt->trx->state == 1"

to the title ???

We can't. It is too long. We can only replace one assertion with another. What say you ???
[17 Sep 2013 0:28] Roel Van de Paar
Ok, how about

Failing assertion: prebuilt->trx->conc_state == 1 | prebuilt->trx->state == 1

That will at least make both searchable in Google
[7 Feb 2014 2:14] Paul Dubois
Noted in 5.5.37, 5.6.17, 5.7.4 changelog.

A deadlock error occurring during subquery execution could cause an
assertion to be raised.
[7 Feb 2014 22:09] Roel Van de Paar
Pleeeeaaasse update the title
[27 Mar 2014 13:43] Laurynas Biveinis
5.5$ bzr log -r 4577
------------------------------------------------------------
revno: 4577
committer: mithun <mithun.c.y@oracle.com>
branch nick: mysql-5.5
timestamp: Thu 2014-01-09 11:17:51 +0530
message:
  Bug #17307201 : FAILING ASSERTION: PREBUILT->TRX->CONC_STATE == 1
                  FROM SUBSELECT
  ISSUE         : In function find_all_keys.
                  If selected row do not satisfy condition
                  then we call unlock_row to release the locked
                  row. Suppose if we have subquery in condition
                  and we have an innodb error during its execution.
                  Then we should not call the unlock_row. If the error
                  is because of deadlock, innodb will rollback the
                  transaction. And calling unlock_row without
                  transaction is an invalid case hence an assertion
                  failure.
  SOLUTION      : We call unlock_row only if only there is no
                  error occurred previously.
                  The solution is back ported from 5.6
                  defect number 14226481