MySQL Bugs: #56529: Crash due to long semaphore wait in InnoDB with ICP and subqueries

Bug #56529	Crash due to long semaphore wait in InnoDB with ICP and subqueries
Submitted:	3 Sep 2010 9:22	Modified:	11 Dec 2010 17:42
Reporter:	John Embretsen	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Optimizer	Severity:	S1 (Critical)
Version:	bzr_mysql-next-mr-opt-backporting	OS:	Any
Assigned to:	Olav Sandstå	CPU Architecture:	Any
Tags:	index_condition_pushdown, optimizer_switch

Description:
The symptoms described in this bug are more or less equal to the symptoms described in Bug#47183. However, the cause of the symptoms described in this bug seem to be related to the new ICP (Index Condition Pushdown) feature that is not part of any release yet, so it may be useful to track it separately (Bug#47183 describes issues with MySQL 5.1 mainly).

When ICP, aka. Index Condition Pushdown, is enabled (available and enabled by default in mysql-next-mr-opt-backporting), running a certain combination of queries results in an apparent hang in InnoDB.

InnoDB itself reports about a long semaphore wait, which eventually exceeds the limit (600 seconds) and crashes the server.

Excerpt from error log:

InnoDB: Warning: a long semaphore wait:
--Thread 24 has waited at /export/home/tmp/je159969/mysql-dev/bzr-repos/mysql-next-mr-opt-backporting/storage/innobase/btr/btr0sea.c line 1136 for 241.00 seconds the
 semaphore:
X-lock (wait_ex) on RW-latch at 2e2d948 created in file /export/home/tmp/je159969/mysql-dev/bzr-repos/mysql-next-mr-opt-backporting/storage/innobase/btr/btr0sea.c li
ne 182
a writer (thread id 24) has reserved it in mode  wait exclusive
number of readers 1, waiters flag 0, lock_word: ffffffffffffffff
Last time read locked in file /export/home/tmp/je159969/mysql-dev/bzr-repos/mysql-next-mr-opt-backporting/storage/innobase/btr/btr0sea.c line 1059
Last time write locked in file /export/home/tmp/je159969/mysql-dev/bzr-repos/mysql-next-mr-opt-backporting/storage/innobase/btr/btr0sea.c line 636
InnoDB: ###### Starts InnoDB Monitor for 30 secs to print diagnostic info:

(...)

OS WAIT ARRAY INFO: reservation count 88, signal count 88
--Thread 24 has waited at /export/home/tmp/je159969/mysql-dev/bzr-repos/mysql-next-mr-opt-backporting/storage/innobase/btr/btr0sea.c line 1136 for 943.00 seconds the
 semaphore:
X-lock (wait_ex) on RW-latch
(...)
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.
100902 14:45:53  InnoDB: Assertion failure in thread 14 in file /export/home/tmp/je159969/mysql-dev/bzr-repos/mysql-next-mr-opt-backporting/storage/innobase/srv/srv0srv.c line 2370
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.

---------------------

When disabling ICP, this issue seems to go away.

SET GLOBAL optimizer_switch='index_condition_pushdown=off';

How to repeat:
This issue was first observed using the Random Query Generator (RQG). An MTR test case which reproduces this issue is being worked on and will be provided later.

The RQG is available from Launchpad (bzr branch lp:randgen).

RQG command line:

perl runall.pl \
--grammar=conf/optimizer/optimizer_subquery.yy \
--engine=InnoDB \
--basedir=$CODE \
--vardir=$PWD/var-semaphore \
--queries=100K \
--duration=900 \
--threads=1 \
--reporter=Backtrace,Shutdown

(RQG revid gleebix@gmail.com-20100819151225-f4qw55n78tkumdsj was used)

Part of stacktrace from one of the threads upon the crash:

[5] cond_wait(0x0), at 0xfffffd7fff274acb
[6] pthread_cond_wait(0x0, 0x0, 0x0, 0x0, 0x0, 0x0), at 0xfffffd7fff274b01
[7] os_cond_wait(cond = 0x2e2da58, mutex = 0x2e2da30), line 140 in "os0sync.c"
[8] os_event_wait_low(event = 0x2e2da30, reset_sig_count = 1LL), line 567 in "os0sync.c"
[9] sync_array_wait_event(arr = 0x242cc50, index = 0), line 457 in "sync0arr.c"
[10] rw_lock_x_lock_wait(lock = 0x2e2d948, file_name = 0x1dfb6d8 "/export/home/tmp/je159969/mysql-dev/bzr-repos/mysql-next-mr-opt-backporting/storage/innobase/btr/btr0sea.c", line = 1136U), line 530 in "sync0rw.c"
[11] rw_lock_x_lock_low(lock = 0x2e2d948, pass = 0, file_name = 0x1dfb6d8 "/export/home/tmp/je159969/mysql-dev/bzr-repos/mysql-next-mr-opt-backporting/storage/innobase/btr/btr0sea.c", line = 1136U), line 576 in "sync0rw.c"
[12] rw_lock_x_lock_func(lock = 0x2e2d948, pass = 0, file_name = 0x1dfb6d8 "/export/home/tmp/je159969/mysql-dev/bzr-repos/mysql-next-mr-opt-backporting/storage/innobase/btr/btr0sea.c", line = 1136U), line 628 in "sync0rw.c"
[13] pfs_rw_lock_x_lock_func(lock = 0x2e2d948, pass = 0, file_name = 0x1dfb6d8 "/export/home/tmp/je159969/mysql-dev/bzr-repos/mysql-next-mr-opt-backporting/storage/innobase/btr/btr0sea.c", line = 1136U), line 692 in "sync0rw.ic"
[14] btr_search_drop_page_hash_index(block = 0xfffffd7ff0e102c8), line 1136 in "btr0sea.c"
[15] btr_search_build_page_hash_index(index = 0x3960588, block = 0xfffffd7ff0e102c8, n_fields = 1U, n_bytes = 0, left_side = 0), line 1292 in "btr0sea.c"
[16] btr_search_info_update_slow(info = 0x3960948, cursor = 0x398aff8), line 666 in "btr0sea.c"
[17] btr_search_info_update(index = 0x3960588, cursor = 0x398aff8), line 83 in "btr0sea.ic"
[18] btr_cur_search_to_nth_level(index = 0x3960588, level = 0, tuple = 0x398b448, mode = 4U, latch_mode = 1U, cursor = 0x398aff8, has_search_latch = 0, file = 0x1d91780 "/export/home/tmp/je159969/mysql-dev/bzr-repos/mysql-next-mr-opt-backporting/storage/innobase/row/row0sel.c", line = 2901U, mtr = 0xfffffd7fff038568), line 775 in "btr0cur.c"
[19] btr_pcur_open_with_no_init_func(index = 0x3960588, tuple = 0x398b448, mode = 4U, latch_mode = 1U, cursor = 0x398aff8, has_search_latch = 0, file = 0x1d91780 "/export/home/tmp/je159969/mysql-dev/bzr-repos/mysql-next-mr-opt-backporting/storage/innobase/row/row0sel.c", line = 2901U, mtr = 0xfffffd7fff038568), line 544 in "btr0pcur.ic"
[20] row_sel_get_clust_rec_for_mysql(prebuilt = 0x39e9388, sec_index = 0x3962b78, rec = 0xfffffd7ff13c8169 "c\x80", thr = 0x3b26f08, out_rec = 0xfffffd7fff038a48, offsets = 0xfffffd7fff038238, offset_heap = 0xfffffd7fff038560, mtr = 0xfffffd7fff038568), line 2901 in "row0sel.c"
[21] row_search_for_mysql(buf = 0x39e91f0 "ð", mode = 2U, prebuilt = 0x39e9388, match_mode = 1U, direction = 0), line 4389 in "row0sel.c"
[22] ha_innobase::index_read(this = 0x39e8f30, buf = 0x39e91f0 "ð", key_ptr = 0x3acef70 "", key_len = 4U, find_flag = HA_READ_KEY_EXACT), line 5695 in "ha_innodb.cc"
[23] handler::index_read_map(this = 0x39e8f30, buf = 0x39e91f0 "ð", key = 0x3acef70 "", keypart_map = 1U, find_flag = HA_READ_KEY_EXACT), line 1791 in "handler.h"
[24] handler::ha_index_read_map(this = 0x39e8f30, buf = 0x39e91f0 "ð", key = 0x3acef70 "", keypart_map = 1U, find_flag = HA_READ_KEY_EXACT), line 2223 in "handler.cc"
[25] join_read_always_key(tab = 0x3acecc0), line 17737 in "sql_select.cc"
[26] sub_select(join = 0x3aa5470, join_tab = 0x3acecc0, end_of_records = false), line 16975 in "sql_select.cc"
[27] JOIN_CACHE::generate_full_extensions(this = 0x3ad03e0, rec_ptr = 0x3a2206d ""), line 1951 in "sql_join_cache.cc"
[28] JOIN_CACHE_BNL::join_matching_records(this = 0x3ad03e0, skip_last = false), line 1843 in "sql_join_cache.cc"
[29] JOIN_CACHE::join_records(this = 0x3ad03e0, skip_last = false), line 1649 in "sql_join_cache.cc"
[30] sub_select_cache(join = 0x3aa5470, join_tab = 0x3acea10, end_of_records = true), line 16778 in "sql_select.cc"
[31] sub_select(join = 0x3aa5470, join_tab = 0x3ace760, end_of_records = true), line 16947 in "sql_select.cc"
[32] do_select(join = 0x3aa5470, fields = (nil), table = 0x3af7fb0, procedure = (nil)), line 16535 in "sql_select.cc"
[33] JOIN::exec(this = 0x3aa5470), line 2767 in "sql_select.cc"
[34] mysql_select(thd = 0x393ef30, rref_pointer_array = 0x3940fe0, tables = 0x39968a8, wild_num = 0, fields = CLASS, conds = 0x39dad80, og_num = 3U, order = 0x39ddae8, group = 0x39daf78, having = 0x39dd850, proc_param = (nil), select_options = 2147748608ULL, result = 0x39ddd20, unit = 0x39407e0, select_lex = 0x3940df8), line 3359 in "sql_select.cc"
[35] handle_select(thd = 0x393ef30, lex = 0x3940730, result = 0x39ddd20, setup_tables_done_option = 0), line 310 in "sql_select.cc"
[36] execute_sqlcom_select(thd = 0x393ef30, all_tables = 0x39968a8), line 4562 in "sql_parse.cc"
[37] mysql_execute_command(thd = 0x393ef30), line 2166 in "sql_parse.cc"

Full stacktraces will be attached later.

Stacktraces from all threads on semaphore wait timeout crash (debug build).

Attachment: stacktraces_bug56529_debug.txt (text/plain), 31.23 KiB.

MTR-style test case reproducing this bug.

Attachment: bug56529.test (application/octet-stream, text), 23.65 KiB.

Attached MTR test case which reproduces this issue on every run in my environment.
It seems like three queries querying 4 tables are needed to reproduce the issue. Queries are rather nasty SELECTs with subqueries.

It may be possible to simplify the test case further.

I will have to fix this as part of my ICP cleanup. It looks like this could be caused by a latching order violation related to btr_search_latch. We need to test this with UNIV_DEBUG and UNIV_SYNC_DEBUG.

Running the test case with UNIV_DEBUG and UNIV_SYNC_DEBUG enabled makes the test fail earlier and the following crash is produced:

  ---- called from signal handler with signal 11 (SIGSEGV) ------
  [8] que_thr_stop_for_mysql_no_error(thr = 0xb41f8d8, trx = 0xb3430d0), line 1040 in "que0que.c"
  [9] row_search_for_mysql(buf = 0xb3b7840 "ýÿ", mode = 1U, prebuilt = 0xb3b8280, match_mode = 0, direction = 0), line 4755 in "row0sel.c"
  [10] ha_innobase::index_read(this = 0xb3b7680, buf = 0xb3b7840 "ýÿ", key_ptr = (nil), key_len = 0, find_flag = HA_READ_AFTER_KEY), line 5829 in "ha_innodb.cc"
  [11] ha_innobase::index_first(this = 0xb3b7680, buf = 0xb3b7840 "ýÿ"), line 6132 in "ha_innodb.cc"
  [12] ha_innobase::rnd_next(this = 0xb3b7680, buf = 0xb3b7840 "ýÿ"), line 6229 in "ha_innodb.cc"
  [13] handler::ha_rnd_next(this = 0xb3b7680, buf = 0xb3b7840 "ýÿ"), line 2197 in "handler.cc"
  [14] rr_sequential(info = 0xb3bf660), line 449 in "records.cc"
  [15] join_init_read_record(tab = 0xb3bf61c), line 18094 in "sql_select.cc"
  [16] sub_select(join = 0xb3a20a0, join_tab = 0xb3bf61c, end_of_records = false), line 17187 in "sql_select.cc"
  [17] do_select(join = 0xb3a20a0, fields = 0xb3a762c, table = (nil), procedure = (nil)), line 16745 in "sql_select.cc"
  [18] JOIN::exec(this = 0xb3a20a0), line 3300 in "sql_select.cc"
  [19] subselect_single_select_engine::exec(this = 0xb3c5508), line 2316 in "item_subselect.cc"
  [20] Item_subselect::exec(this = 0xb3c5430), line 311 in "item_subselect.cc"
  [21] Item_in_subselect::exec(this = 0xb3c5430), line 364 in "item_subselect.cc"
  [22] Item_in_subselect::val_bool(this = 0xb3c5430), line 960 in "item_subselect.cc"
  [23] Item::val_bool_result(this = 0xb3c5430), line 860 in "item.h"
  [24] Item_in_optimizer::val_int(this = 0xb3a23c8), line 1925 in "item_cmpfunc.cc"
  [25] Item_func_nop_all::val_int(this = 0xb3c5530), line 359 in "item_cmpfunc.cc"
  [26] Item::val_bool(this = 0xb3c5530), line 200 in "item.cc"
  [27] Item_cond_or::val_int(this = 0xb3a5a50), line 4627 in "item_cmpfunc.cc"
  [28] innobase_index_cond(file = 0xb3b48c0), line 11872 in "ha_innodb.cc"
  [29] row_search_idx_cond_check(mysql_rec = 0xb3b4a80 "ýü^P", prebuilt = 0xb39ea68, rec = 0xfdec4169 "c\x80", offsets = 0xfec4aab0), line 3360 in "row0sel.c"
  [30] row_search_for_mysql(buf = 0xb3b4a80 "ýü^P", mode = 2U, prebuilt = 0xb39ea68, match_mode = 1U, direction = 0), line 4399 in "row0sel.c"
  [31] ha_innobase::index_read(this = 0xb3b48c0, buf = 0xb3b4a80 "ýü^P", key_ptr = 0xb3a3a48 "", key_len = 4U, find_flag = HA_READ_KEY_EXACT), line 5829 in "ha_innodb.cc"
  [32] handler::index_read_map(this = 0xb3b48c0, buf = 0xb3b4a80 "ýü^P", key = 0xb3a3a48 "", keypart_map = 1U, find_flag = HA_READ_KEY_EXACT), line 1791 in "handler.h"
  [33] handler::ha_index_read_map(this = 0xb3b48c0, buf = 0xb3b4a80 "ýü^P", key = 0xb3a3a48 "", keypart_map = 1U, find_flag = HA_READ_KEY_EXACT), line 2223 in "handler.cc"
  [34] join_read_always_key(tab = 0xb3a4a2c), line 17962 in "sql_select.cc"
  [35] sub_select(join = 0xb3a1bc0, join_tab = 0xb3a4a2c, end_of_records = false), line 17187 in "sql_select.cc"
  [36] JOIN_CACHE::generate_full_extensions(this = 0xb3a58a0, rec_ptr = 0xb664d00 "ýÿ^B"), line 1956 in "sql_join_cache.cc"
  [37] JOIN_CACHE_BNL::join_matching_records(this = 0xb3a58a0, skip_last = false), line 1848 in "sql_join_cache.cc"
  [38] JOIN_CACHE::join_records(this = 0xb3a58a0, skip_last = false), line 1654 in "sql_join_cache.cc"
  [39] sub_select_cache(join = 0xb3a1bc0, join_tab = 0xb3a4870, end_of_records = true), line 16990 in "sql_select.cc"
  [40] sub_select(join = 0xb3a1bc0, join_tab = 0xb3a46b4, end_of_records = true), line 17159 in "sql_select.cc"
  [41] do_select(join = 0xb3a1bc0, fields = (nil), table = 0xb3c2470, procedure = (nil)), line 16747 in "sql_select.cc"
  [42] JOIN::exec(this = 0xb3a1bc0), line 2909 in "sql_select.cc"
  [43] mysql_select(thd = 0xb2ae2d0, rref_pointer_array = 0xb2af9b8, tables = 0xb2fb690, wild_num = 0, fields = CLASS, conds = 0xb3c5e00, og_num = 3U, order = 0xb3c6248, group = 0xb3c5f50, having = 0xb3c6078, proc_param = (nil), select_options = 2147748608ULL, result = 0xb3c63d0, unit = 0xb2af47c, select_lex = 0xb2af8b4), line 3501 in "sql_select.cc"
  [44] handle_select(thd = 0xb2ae2d0, lex = 0xb2af418, result = 0xb3c63d0, setup_tables_done_option = 0), line 310 in "sql_select.cc"
  [45] execute_sqlcom_select(thd = 0xb2ae2d0, all_tables = 0xb2fb690), line 4562 in "sql_parse.cc"
  [46] mysql_execute_command(thd = 0xb2ae2d0), line 2166 in "sql_parse.cc"
  [47] mysql_parse(thd = 0xb2ae2d0, rawbuf = 0xb2fa930 "SELECT    ( ( table1 . `col_int_nokey` ) * ( table1 . `col_int_nokey` ) ) AS field1 FROM ( C AS table1 STRAIGHT_JOIN ( ( C AS table2 INNER JOIN C AS table3 ON (table3 . `col_varchar_key` = table2 . `col_varchar_key`  ) ) ) ON (table3 . `col_int_nokey` = table2 . `col_int_key`  ) ) WHERE (  table3 . `col_int_key` != SOME ( SELECT   SUBQUERY1_t1 . `col_int_nokey` AS SUBQUERY1_field1 FROM ( D AS SUBQUERY1_t1 LEFT OUTER JOIN C AS SUBQUERY1_t2 ON (SUBQUERY1_t2 . `col_int_key` = SUBQUERY1_t1 . `pk`  ) ) WHERE SUB" ..., length = 773U, parser_state = 0xfec4dc44), line 5591 in "sql_parse.cc"
  [48] dispatch_command(command = COM_QUERY, thd = 0xb2ae2d0, packet = 0xb2f2901 "SELECT    ( ( table1 . `col_int_nokey` ) * ( table1 . `col_int_nokey` ) ) AS field1 FROM ( C AS table1 STRAIGHT_JOIN ( ( C AS table2 INNER JOIN C AS table3 ON (table3 . `col_varchar_key` = table2 . `col_varchar_key`  ) ) ) ON (table3 . `col_int_nokey` = table2 . `col_int_key`  ) ) WHERE (  table3 . `col_int_key` != SOME ( SELECT   SUBQUERY1_t1 . `col_int_nokey` AS SUBQUERY1_field1 FROM ( D AS SUBQUERY1_t1 LEFT OUTER JOIN C AS SUBQUERY1_t2 ON (SUBQUERY1_t2 . `col_int_key` = SUBQUERY1_t1 . `pk`  ) ) WHERE SUB" ..., packet_length = 773U), line 1130 in "sql_parse.cc"
  [49] do_command(thd = 0xb2ae2d0), line 802 in "sql_parse.cc"
  [50] do_handle_one_connection(thd_arg = 0xb2ae2d0), line 1201 in "sql_connect.cc"
  [51] handle_one_connection(arg = 0xb2ae2d0), line 1140 in "sql_connect.cc"
  [52] pfs_spawn_thread(arg = 0xb2cd820), line 1078 in "pfs.cc"
  [53] _thrp_setup(0xfec85a00), at 0xfeaefa63 
  [54] _lwp_start(0xf, 0xb, 0x0, 0xfeaed64a, 0xfec49838, 0x8ce044c), at 0xfeaefcf0 

The assert that fails is the following in que_thr_stop_for_mysql_no_error():

  ut_ad(trx->n_active_thrs == 1);

Inspecting the core file shows that the actual value of n_active_thrs is 2.

For what it is worth, I can trigger it even earlier with these assertions:

=== modified file 'storage/innobase/que/que0que.c'
--- storage/innobase/que/que0que.c	revid:jorgen.loland@oracle.com-20100915085308-lygr5tud7qmeut4u
+++ storage/innobase/que/que0que.c	2010-10-25 13:14:50 +0000
@@ -839,6 +839,7 @@ que_thr_dec_refer_count(
 
 	ut_ad(fork->n_active_thrs == 1);
 	ut_ad(trx->n_active_thrs == 1);
+	ut_ad(thr->is_active);
 
 	fork->n_active_thrs--;
 	trx->n_active_thrs--;
@@ -1020,6 +1021,8 @@ que_thr_move_to_run_state_for_mysql(
 		trx->n_active_thrs++;
 
 		thr->is_active = TRUE;
+		ut_ad(trx->n_active_thrs == 1);
+		ut_ad(thr->graph->n_active_thrs == 1);
 	}
 
 	thr->state = QUE_THR_RUNNING;

The stack trace is interesting. InnoDB does not expect index condition pushdown (frame #21 0x0848e5d7 in innobase_index_cond below) to execute a subquery like this.

#0  ut_dbg_assertion_failed (expr=0x87be4a1 "trx->n_active_thrs == 1", file=0x87be224 "storage/innobase/que/que0que.c", line=1024) at storage/innobase/ut/ut0dbg.c:55
#1  0x08582f74 in que_thr_move_to_run_state_for_mysql (thr=0x8deee88, trx=0x8d826a8) at storage/innobase/que/que0que.c:1024
#2  0x084b0a1a in row_search_for_mysql (buf=0x8db9390 "\377\377", mode=1, prebuilt=0x8db9ea0, match_mode=0, direction=0) at storage/innobase/row/row0sel.c:3813
#3  0x08485f74 in ha_innobase::index_read (this=0x8db91d0, buf=0x8db9390 "\377\377", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at storage/innobase/handler/ha_innodb.cc:5846
#4  0x08486873 in ha_innobase::index_first (this=0x8db91d0, buf=0x8db9390 "\377\377") at storage/innobase/handler/ha_innodb.cc:6148
#5  0x08486a3e in ha_innobase::rnd_next (this=0x8db91d0, buf=0x8db9390 "\377\377") at storage/innobase/handler/ha_innodb.cc:6245
#6  0x083223ca in handler::ha_rnd_next (this=0x8db91d0, buf=0x8db9390 "\377\377") at sql/handler.cc:2197
#7  0x083db36a in rr_sequential (info=0x8db1528) at sql/records.cc:449
#8  0x0822dcb1 in join_init_read_record (tab=0x8db14e4) at sql/sql_select.cc:18068
#9  0x0822bfe0 in sub_select (join=0x8da86f0, join_tab=0x8db14e4, end_of_records=false) at sql/sql_select.cc:17161
#10 0x0822b64d in do_select (join=0x8da86f0, fields=0x8df22e4, table=0x0, procedure=0x0) at sql/sql_select.cc:16719
#11 0x0820e23a in JOIN::exec (this=0x8da86f0) at sql/sql_select.cc:3290
#12 0x0839660d in subselect_single_select_engine::exec (this=0x8df4018) at sql/item_subselect.cc:2323
#13 0x08391285 in Item_subselect::exec (this=0x8df3f58) at sql/item_subselect.cc:311
#14 0x08391417 in Item_in_subselect::exec (this=0x8df3f58) at sql/item_subselect.cc:364
#15 0x08392e78 in Item_in_subselect::val_bool (this=0x8df3f58) at sql/item_subselect.cc:960
#16 0x081841e2 in Item::val_bool_result (this=0x8df3f58) at sql/item.h:860
#17 0x0834a071 in Item_in_optimizer::val_int (this=0x8dad998) at sql/item_cmpfunc.cc:1845
#18 0x083467ad in Item_func_nop_all::val_int (this=0x8df4040) at sql/item_cmpfunc.cc:359
#19 0x0832b4cc in Item::val_bool (this=0x8df4040) at sql/item.cc:200
#20 0x083522a1 in Item_cond_or::val_int (this=0x8db0a38) at sql/item_cmpfunc.cc:4547
#21 0x0848e5d7 in innobase_index_cond (file=0x8db5db8) at storage/innobase/handler/ha_innodb.cc:11898
#22 0x084b0055 in row_search_idx_cond_check (mysql_rec=0x8db5f78 "\375\374\020", prebuilt=0x8db69a0, rec=0xb6814169 "c\200", offsets=0xafc79254) at storage/innobase/row/row0sel.c:3370
#23 0x084b18f5 in row_search_for_mysql (buf=0x8db5f78 "\375\374\020", mode=2, prebuilt=0x8db69a0, match_mode=1, direction=0) at storage/innobase/row/row0sel.c:4409
#24 0x08485f74 in ha_innobase::index_read (this=0x8db5db8, buf=0x8db5f78 "\375\374\020", key_ptr=0x8dafab8 "", key_len=4, find_flag=HA_READ_KEY_EXACT) at storage/innobase/handler/ha_innodb.cc:5846
#25 0x0832934c in handler::index_read_map (this=0x8db5db8, buf=0x8db5f78 "\375\374\020", key=0x8dafab8 "", keypart_map=1, find_flag=HA_READ_KEY_EXACT) at sql/handler.h:1791
#26 0x083224d8 in handler::ha_index_read_map (this=0x8db5db8, buf=0x8db5f78 "\375\374\020", key=0x8dafab8 "", keypart_map=1, find_flag=HA_READ_KEY_EXACT) at sql/handler.cc:2223
#27 0x0822d7fd in join_read_always_key (tab=0x8daf8fc) at sql/sql_select.cc:17936
#28 0x0822bfe0 in sub_select (join=0x8da34d8, join_tab=0x8daf8fc, end_of_records=false) at sql/sql_select.cc:17161
#29 0x0841584f in JOIN_CACHE::generate_full_extensions (this=0x8db0888, rec_ptr=0x8e192b0 "\375\377\002") at sql/sql_join_cache.cc:1956
#30 0x08415638 in JOIN_CACHE_BNL::join_matching_records (this=0x8db0888, skip_last=false) at sql/sql_join_cache.cc:1848
#31 0x0841510f in JOIN_CACHE::join_records (this=0x8db0888, skip_last=false) at sql/sql_join_cache.cc:1654
#32 0x0822bd82 in sub_select_cache (join=0x8da34d8, join_tab=0x8daf740, end_of_records=true) at sql/sql_select.cc:16964
#33 0x0822bf46 in sub_select (join=0x8da34d8, join_tab=0x8daf584, end_of_records=true) at sql/sql_select.cc:17134
#34 0x0822b67f in do_select (join=0x8da34d8, fields=0x0, table=0x8df5558, procedure=0x0) at sql/sql_select.cc:16721
#35 0x0820cbb9 in JOIN::exec (this=0x8da34d8) at sql/sql_select.cc:2899
#36 0x0820e8e7 in mysql_select (thd=0x8d360a0, rref_pointer_array=0x8d377c8, tables=0x8d7ebb8, wild_num=0, fields=..., conds=0x8df4898, og_num=3, order=0x8df4cb8, group=0x8df49e8, having=0x8df4b10, proc_param=0x0, select_options=2147748608, result=0x8df4e38, unit=0x8d3728c, select_lex=0x8d376c4) at sql/sql_select.cc:3491
#37 0x08206788 in handle_select (thd=0x8d360a0, lex=0x8d37228, result=0x8df4e38, setup_tables_done_option=0) at sql/sql_select.cc:322
#38 0x081ec18f in execute_sqlcom_select (thd=0x8d360a0, all_tables=0x8d7ebb8) at sql/sql_parse.cc:4562
#39 0x081e4e59 in mysql_execute_command (thd=0x8d360a0) at sql/sql_parse.cc:2166
#40 0x081edf6b in mysql_parse (thd=0x8d360a0, rawbuf=0x8d7dea8 "SELECT    ( ( table1 . `col_int_nokey` ) * ( table1 . `col_int_nokey` ) ) AS field1 FROM ( C AS table1 STRAIGHT_JOIN ( ( C AS table2 INNER JOIN C AS table3 ON (table3 . `col_varchar_key` = table2 . `c"..., length=773, parser_state=0xafc7ad4c) at sql/sql_parse.cc:5591
#41 0x081e2c35 in dispatch_command (command=COM_QUERY, thd=0x8d360a0, packet=0x8d75e79 "SELECT    ( ( table1 . `col_int_nokey` ) * ( table1 . `col_int_nokey` ) ) AS field1 FROM ( C AS table1 STRAIGHT_JOIN ( ( C AS table2 INNER JOIN C AS table3 ON (table3 . `col_varchar_key` = table2 . `c"..., packet_length=773) at sql/sql_parse.cc:1130
#42 0x081e2197 in do_command (thd=0x8d360a0) at sql/sql_parse.cc:802
#43 0x082ac2d7 in do_handle_one_connection (thd_arg=0x8d360a0) at sql/sql_connect.cc:1192
#44 0x082ac14a in handle_one_connection (arg=0x8d360a0) at sql/sql_connect.cc:1131
#45 0xb7fb9955 in start_thread (arg=0xafc7bb70) at pthread_create.c:300
#46 0xb7dabe7e in clone () at ../sysdeps/unix/sysv/linux/i386/clone.S:130

I do not know in detail how subqueries work outside index condition pushdown, but I presume that they would open a separate handler.

The index condition pushdown is attempted on the clustered index of table C.

Simplified version of the original test case:

CREATE TABLE C (
  col_int_nokey INTEGER,
  col_int_key INTEGER,
  col_varchar_key VARCHAR(1),

  KEY (col_int_key),
  KEY (col_varchar_key, col_int_key)
) ENGINE=InnoDB;

INSERT INTO C VALUES (NULL,2,'w');
INSERT INTO C VALUES (7,9,'m');
INSERT INTO C VALUES (9,3,'m');
INSERT INTO C VALUES (7,9,'k');
INSERT INTO C VALUES (4,NULL,'r');
INSERT INTO C VALUES (2,9,'t');
INSERT INTO C VALUES (6,3,'j');
INSERT INTO C VALUES (8,8,'u');
INSERT INTO C VALUES (NULL,8,'h');
INSERT INTO C VALUES (5,53,'o');
INSERT INTO C VALUES (NULL,0,NULL);
INSERT INTO C VALUES (6,5,'k');
INSERT INTO C VALUES (188,166,'e');
INSERT INTO C VALUES (2,3,'n');
INSERT INTO C VALUES (1,0,'t');
INSERT INTO C VALUES (1,1,'c');
INSERT INTO C VALUES (0,9,'m');
INSERT INTO C VALUES (9,5,'y');
INSERT INTO C VALUES (NULL,6,'f');

CREATE TABLE D (
    c1 INTEGER
) ENGINE=InnoDB;

EXPLAIN SELECT table1.col_int_nokey
FROM 
  ( 
    C AS table1 STRAIGHT_JOIN 
      ( 
        ( 
          C AS table2 
          INNER JOIN 
          C AS table3
          ON (table3.col_varchar_key = table2.col_varchar_key) 
        ) 
      ) 
    ON (table3.col_int_nokey = table1.col_int_key) 
  ) 
WHERE table3.col_int_key != SOME ( SELECT c1 FROM D );

DROP TABLE C;
DROP TABLE D;

Note that in order for this to reproduce the issue MySQL must be compiled with debug (and UNIV_DEBUG enabled in InnoDB).

Explain output for the query in the test case above:

id	select_type	table	type	possible_keys	key	key_len	ref	rows	Extra
1	PRIMARY	table2	index	col_varchar_key	col_varchar_key	9	NULL	19	Using where; Using index
1	PRIMARY	table3	ref	col_varchar_key	col_varchar_key	4	test.table2.col_varchar_key	1	Using index condition; Using where
1	PRIMARY	table1	ref	col_int_key	col_int_key	5	test.table3.col_int_nokey	1	
2	DEPENDENT SUBQUERY	D	ALL	NULL	NULL	NULL	NULL	1	Using where

The index condition we push down to InnoDB for "table3" for the (col_varchar_key, col_in_key) index looks like (see second line in the explain above):

<nop>(<in_optimizer>(`test`.`table3`.`col_int_key`,<exists>(select 1 from `test`.`D` where trigcond(((<cache>(`test`.`table3`.`col_int_key`) <> `test`.`D`.`c1`) or isnull(`test`.`D`.`c1`))) having trigcond(<is_not_null_test>(`test`.`D`.`c1`)))))

Here is a summary of what causes this to trigger the assert in InnoDB:

1. For the ref-access on "table3" (which is an alias for the real
   table C) the server pushes down the following index condition to be
   evaluated by InnoDB:

   <nop>(<in_optimizer>(`test`.`table3`.`col_int_key`,<exists>(select 1 from `test`.`D` where trigcond(((<cache>(`test`.`table3`.`col_int_key`) <> `test`.`D`.`c1`) or isnull(`test`.`D`.`c1`))) having trigcond(<is_not_null_test>(`test`.`D`.`c1`)))))

2. The server requests a record from InnoDB from table3 (using the
   handler for table3)

3. InnoDB: increments the trx->n_active_thrs (in
   que_thr_move_to_run_state_for_mysql()). New value: 1

4. InnoDB: when the first record in table3 is found it executes the
   index condition function (see step 1). This is a call-back to
   server code.

5. Index condition function: since this condition contains a "SELECT
   FROM D" this will be executed (and we are still in the call back
   from InnoDB):

6. To execute of SELECT FROM D will be done using the handler for
   table D (which is not the same as for table3).

7. InnoDB will find the trx object for the transaction and increment
   trx->n_active_thrs (in que_thr_move_to_run_state_for_mysql()). New
   value: 2

8. The new value for trx->n_active_thrs triggers the assert:

     ut_ad(trx->n_active_thrs == 1);

   (in que_thr_stop_for_mysql_no_error()).

Idea for a solution: do not push down index conditions to storage
engines that contain execution of statments that might trigger new
calls to the storage engine.

The code that makes the final decision that the subselect part of
table3's condition can be pushed down to the storage engine is the
following test in uses_index_fields_only() in sql_select.cc:

  if (!(item->used_tables() & tbl->map))
    return other_tbls_ok;

This checks whether a part of the condition is using only other tables
(than table3) and if so then accepts to push it down (other_tbls_ok is
true in this case). When it evaluates the following part of the
condition:

  <exists>(select 1 from `test`.`D` where trigcond(((<cache>(`test`.`table3`.`col_int_key`) <> `test`.`D`.`c1`) or isnull(`test`.`D`.`c1`))) having trigcond(<is_not_null_test>(`test`.`D`.`c1`)))

this is stored in a Item_subselect object. When calling used_tables()
on this object it returns 0 (ie. the item is supposed to not use any
tables at all during evaluation of it (if I have understood
correctly)). This causes the code above to conclude that the subselect
part of the condition is safe to push down to the handler/storage
engine.

If item->used_tables() had returned the expect result that both table
"D" and "table3" would be used for evaluating the Item_subselect code
later in uses_index_fields_only() would have rejected that this part
of the condition could be pushed down to the handler/storage engine.

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/123895

3281 Olav Sandstaa 2010-11-15
Fix for Bug#56529 Crash due to long semaphore wait in InnoDB with ICP and subqueries

This crash was caused by the server pushing down an index condition to
InnoDB that contained a subselect. When InnoDB executed this index
condition the subselect would open a new handler object and access
InnoDB a second time. This caused the same transaction to have two
active data accesses to InnoDB which triggered the assert in InnoDB.

The fix for this is to not push down index conditions to the handler
that contain a subselect.
@ mysql-test/include/icp_tests.inc
Test case for Bug#56529 Crash due to long semaphore wait in InnoDB
with ICP and subqueries.
@ mysql-test/r/innodb_icp.result
Result file for Test case for Bug#56529 Crash due to long semaphore
wait in InnoDB with ICP and subqueries.
@ mysql-test/r/innodb_icp_all.result
Result file for Test case for Bug#56529 Crash due to long semaphore
wait in InnoDB with ICP and subqueries.
@ mysql-test/r/innodb_icp_none.result
Result file for Test case for Bug#56529 Crash due to long semaphore
wait in InnoDB with ICP and subqueries.
@ mysql-test/r/myisam_icp.result
Result file for Test case for Bug#56529 Crash due to long semaphore
wait in InnoDB with ICP and subqueries.
@ mysql-test/r/myisam_icp_all.result
Result file for Test case for Bug#56529 Crash due to long semaphore
wait in InnoDB with ICP and subqueries.
@ mysql-test/r/myisam_icp_none.result
Result file for Test case for Bug#56529 Crash due to long semaphore
wait in InnoDB with ICP and subqueries.
@ sql/sql_select.cc
We should not push down index conditions to the handler that contains
a subselect. This was already handled by the default case of the
switch in uses_index_fields_only() but due to an earlier check in
uses_index_fields() the code for checking that the condition only
used "other tables" could return ok early.

Fix this by adding an explicite check for if the condition
contains a subselect and if so return false.

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/123992

3281 Olav Sandstaa 2010-11-16
Fix for Bug#56529 Crash due to long semaphore wait in InnoDB with ICP and subqueries

Fix this by adding an explicite check for if the condition
contains a subselect and if so return false.

Pushed to mysql-next-mr-opt-backporting with revision id:
olav.sandstaa@oracle.com-20101116082256-pa1hbb0w4pz2hixs .

Pushed into mysql-trunk 5.6.1 (revid:alexander.nozdrin@oracle.com-20101205122447-6x94l4fmslpbttxj) (version source revid:alexander.nozdrin@oracle.com-20101205122447-6x94l4fmslpbttxj) (merge vers: 5.6.1) (pib:23)

Bug does not appear in any released 5.6.x version. No changelog entry needed.