MySQL Bugs: #41996: multi-table delete crashes server (InnoDB table)

Bug #41996	multi-table delete crashes server (InnoDB table)
Submitted:	9 Jan 2009 12:19	Modified:	26 Feb 2010 9:57
Reporter:	Amit Saha	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server: Optimizer	Severity:	S1 (Critical)
Version:	6.0.6,6.0.10	OS:	Linux (RHEL)
Assigned to:	Assigned Account	CPU Architecture:	Any
Tags:	Contribution, index_condition_pushdown, optimizer_switch

Description:
The attached tests whether run together or individually fails reporting, lost connection to server, possibly due to a server crash

How to repeat:
Run the tests using InnoDB as the default SE

Test 1

Attachment: de_multi_db_table.test (application/octet-stream, text), 21.87 KiB.

Test 2

Attachment: de_multi_db_table_using.test (application/octet-stream, text), 22.06 KiB.

Test 3

Attachment: de_multi_table.test (application/octet-stream, text), 17.43 KiB.

Test 4

Attachment: de_multi_table_using.test (application/octet-stream, text), 17.62 KiB.

Thank you for the bug report. Crashed with first test case:

c:\dbs>c:\dbs\6.0\bin\mysqld --defaults-file=c:\dbs\6.0\my.ini --standalone --console
090109 11:23:49  InnoDB: Started; log sequence number 0 46409
090109 11:23:50 [Note] Event Scheduler: Loaded 0 events
090109 11:23:50 [Note] c:\dbs\6.0\bin\mysqld: ready for connections.
Version: '6.0.10-alpha-nt-debug-log'  socket: ''  port: 3600  Source distribution
090109 11:24: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=8384512
read_buffer_size=131072
max_used_connections=1
max_threads=151
thread_count=1
connection_count=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 337758 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x36e7528
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...
009BECD6    mysqld.exe!mach_read_from_4()[mach0data.ic:172]
00994209    mysqld.exe!btr_copy_externally_stored_field()[btr0cur.c:3759]
0099452E    mysqld.exe!btr_rec_copy_externally_stored_field()[btr0cur.c:3847]
009853D8    mysqld.exe!row_sel_store_mysql_rec()[row0sel.c:2640]
00986AFD    mysqld.exe!row_search_for_mysql()[row0sel.c:4192]
009469CB    mysqld.exe!ha_innobase::index_read()[ha_innodb.cc:4267]
0046A75C    mysqld.exe!handler::index_read_map()[handler.h:1767]
006DA2A3    mysqld.exe!join_read_always_key()[sql_select.cc:16831]
006D8B9F    mysqld.exe!sub_select()[sql_select.cc:16164]
006D92C0    mysqld.exe!evaluate_join_record()[sql_select.cc:16432]
006D8BF5    mysqld.exe!sub_select()[sql_select.cc:16169]
006D8111    mysqld.exe!do_select()[sql_select.cc:15728]
006BBDB0    mysqld.exe!JOIN::exec()[sql_select.cc:2866]
006BC458    mysqld.exe!mysql_select()[sql_select.cc:3049]
0067581D    mysqld.exe!mysql_execute_command()[sql_parse.cc:3291]
0067BE5D    mysqld.exe!mysql_parse()[sql_parse.cc:5735]
00671438    mysqld.exe!dispatch_command()[sql_parse.cc:1007]
00670CBF    mysqld.exe!do_command()[sql_parse.cc:690]
0078AA77    mysqld.exe!handle_one_connection()[sql_connect.cc:1145]
0086CDB8    mysqld.exe!pthread_start()[my_winthread.c:61]
00BAFBB6    mysqld.exe!_threadstartex()[threadex.c:241]
7C80B713    kernel32.dll!GetModuleFileNameA()
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0377A4C0=DELETE     d1.t1, d2.t2 FROM d1.t1, d2.t2, d3.t3 WHERE d1.t1.c1=d2.t2.c2 AND d2.t2.c1=d3.t3.c2
thd->thread_id=1
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.

c:\dbs>

reduced testcase:

#SET session engine_condition_pushdown=OFF;
#SET session optimizer_use_mrr=’disable’;
drop table if exists `t1`;
create table `t1` (`c` bigint, key(`c`),`a` int)engine=innodb;
insert into `t1` values(2,2);
delete `t1` from `t1` `a`, `t1` where `a`.`a`=`t1`.`c` ;

uncommenting the first two lines prevents a crash.

reclassifying as optimizer bug based on my last testcase.

goes away / comes back after disabling/enabling ICP in InnoDB.
By the way, stack trace has common points to the one in bug#36981

Valgrind reports the following use of uninitialized memory in the function row_sel_store_mysql_rec (storage/innobase/row/row0sel.c:2614) when running the test case:

==7119== Thread 12:
==7119== Conditional jump or move depends on uninitialised value(s)
==7119==    at 0x95CD01: row_sel_store_mysql_rec (row0sel.c:2614)
==7119==    by 0x95F380: row_search_for_mysql (row0sel.c:4154)
==7119==    by 0x8F3692: ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned, ha_rkey_function) (ha_innodb.cc:4515)
==7119==    by 0x7E5653: handler::index_read_map(unsigned char*, unsigned char const*, unsigned long, ha_rkey_function) (handler.h:1796)
==7119==    by 0x703121: join_read_always_key(st_join_table*) (sql_select.cc:16992)
==7119==    by 0x70653C: sub_select(JOIN*, st_join_table*, bool) (sql_select.cc:16307)
==7119==    by 0x7062BB: evaluate_join_record(JOIN*, st_join_table*, int) (sql_select.cc:16577)
==7119==    by 0x70658C: sub_select(JOIN*, st_join_table*, bool) (sql_select.cc:16312)
==7119==    by 0x7141EE: do_select(JOIN*, List<Item>*, TABLE*, Procedure*) (sql_select.cc:15870)
==7119==    by 0x731B3D: JOIN::exec() (sql_select.cc:2929)
==7119==    by 0x72C157: mysql_select(THD*, Item***, TABLE_LIST*, unsigned, List<Item>&, Item*, unsigned, st_order*, st_order*, Item*, st_order*, unsigned long
long, select_result*, st_select_lex_unit*, st_select_lex*) (sql_select.cc:3120)
==7119==    by 0x68AC9E: mysql_execute_command(THD*) (sql_parse.cc:3427)
==7119==    by 0x68FB0D: mysql_parse(THD*, char const*, unsigned, char const**)
(sql_parse.cc:5979)
==7119==    by 0x690FEA: dispatch_command(enum_server_command, THD*, char*, unsigned) (sql_parse.cc:1076)
==7119==    by 0x6924B5: do_command(THD*) (sql_parse.cc:758)
==7119==    by 0x67FB9C: handle_one_connection (sql_connect.cc:1164)
==7119==

Besides any MRR/InnoDB problem this bug may hit, there seems to be something wrong on SQL layer as well.

If I take test1 (de_multi_db_table.test), put at the top:

  set optimizer_use_mrr='disable';

make it into a testcase and run it under valgrind, I get this failure:

==9220== Thread 3:
==9220== Conditional jump or move depends on uninitialised value(s)
==9220==    at 0x832B4A7: make_cond_for_table_from_pred(Item*, Item*, unsigned long long, unsigned long long, bool) (sql_select.cc:18147)
==9220==    by 0x832BA33: make_cond_for_table(Item*, unsigned long long, unsigned long long, bool) (sql_select.cc:18139)
==9220==    by 0x83431AC: make_join_select(JOIN*, Item*) (sql_select.cc:8916)
==9220==    by 0x8350989: JOIN::optimize() (sql_select.cc:1720)
==9220==    by 0x8354440: 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*) (sql_select.cc:3126)
==9220==    by 0x82BC53A: mysql_execute_command(THD*) (sql_parse.cc:3427)
==9220==    by 0x82C1D39: mysql_parse(THD*, char const*, unsigned int, char const**) (sql_parse.cc:5975)
==9220==    by 0x82C28D3: dispatch_command(enum_server_command, THD*, char*, unsigned int) (sql_parse.cc:1076)
==9220==    by 0x82C3E6E: do_command(THD*) (sql_parse.cc:758)
==9220==    by 0x82B06DC: handle_one_connection (sql_connect.cc:1164)
==9220==    by 0x40524FE: start_thread (in /lib/tls/i686/cmov/libpthread-2.9.so)
==9220==    by 0x42BD49D: clone (in /lib/tls/i686/cmov/libc-2.9.so)

The run was on mysql-6.0-codebase-bugfixing, tip cset:
---
revno: 3737
committer: Alexey Botchkov <holyfoot@mysql.com>
branch nick: 60mrg
timestamp: Wed 2009-11-25 16:30:04 +0400
message:
  merging.

Simplifed testcase:

--disable_warnings
drop table if exists t1,t2,t3;
--enable_warnings
set @@optimizer_use_mrr='disable';

CREATE TABLE t1 (c1 TINYINT NOT NULL PRIMARY KEY, c2 INTEGER, KEY(c2));
CREATE TABLE t2 (c1 TINYINT NOT NULL PRIMARY KEY, c2 INTEGER, KEY(c2));
CREATE TABLE t3 (c1 TINYINT NOT NULL PRIMARY KEY, c2 INTEGER, KEY(c2));
INSERT INTO t1 VALUES(1,1),(2,2),(3,3),(4,4),(5,5);
INSERT INTO t2 VALUES(11,1),(12,1),(13,1),(14,2),(15,6);
INSERT INTO t3 VALUES(21,11),(22,11),(23,13),(24,14),(25,15);
DELETE     
  t1, t2 
FROM t1, t2, t3 WHERE t1.c1=t2.c2 AND t2.c1=t3.c2;

drop table t1,t2,t3;

The above mentioned problem doesn't show if @@engine_condition_pushdown is off.

Investigation:
The source of the problem is add_cond_and_fix() function. After the exection
that passes the

    if ((res= new Item_cond_and(*e1, e2)))
    {
      *e1= res;
      res->quick_fix_field();

lines in it, we get:

(gdb) print res
  $28 = (Item_cond_and *) 0xaa49cd8
(gdb) p res->fixed
  $29 = 0 '\0'
(gdb) p res->used_tables()
  $30 = 0
(gdb) p res->list->first.info
  $31 = (void *) 0xa9f6e88
(gdb) p ((Item*)(res->list->first.info))->used_tables()
  $32 = 6

That is, add_cond_and_fix() creates an Item_cond_and which is marked as fixed
but which has no correct table_map() attribute.

Then, the code reaches this part in make_join_select():

	  if (thd->variables.engine_condition_pushdown && !first_inner_tab)
          {
            COND *push_cond= 
              make_cond_for_table(tmp, current_map, current_map, 0);
            if (push_cond)
            {
              /* Push condition to handler */
              if (!tab->table->file->cond_push(push_cond))
                tab->table->file->pushed_cond= push_cond;
            }
          }

If engine_condition_pushdown is on, we get to make_cond_for_table() call, which
produces the valgrind warning. Without condition pushdown, the obtained
Item_cond_and is used in query execution, which doesn't cause any problems as
execution itself doesn't depend on used_tables()

Suggested fix:

=== modified file 'sql/sql_select.cc'
--- sql/sql_select.cc	2009-11-25 15:05:56 +0000
+++ sql/sql_select.cc	2009-12-01 21:31:43 +0000
@@ -8483,6 +8483,7 @@ inline void add_cond_and_fix(Item **e1, 
     {
       *e1= res;
       res->quick_fix_field();
+      res->update_used_tables();
     }
   }
   else

The above patch has been posted to internals@lists.mysql.com under SCA license:

http://lists.mysql.com/internals/37586

The bug described and the patch proposed by Sergey Petrunya has been filed as a separate bug: Bug#49506 Valgrind error in make_cond_for_table_from_pred

This bug is a duplicate of Bug#43360 and/or Bug#36981. I have verified that this crash does no longer occur after applying the fixes for these two bugs.

Test case for this bug is committed here:

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

Patch containing updated version of test case:

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

Patch containing test case pushed to mysql-6.0-codebase-bugfixing with revision-id: olav@sun.com-20100226091930-qxvakxmcp6463t5w .

Closing this as duplicate of Bug#36981.

Pushed into 6.0.14-alpha (revid:alik@sun.com-20100306102742-yw9zzgw9ac5r65m5) (version source revid:bar@mysql.com-20100305074327-h09o5lw290s04lcf) (merge vers: 6.0.14-alpha) (pib:16)

Pushed into mysql-next-mr (revid:alik@sun.com-20100816062819-bluwgdq8q4xysmlg) (version source revid:alik@sun.com-20100816062612-enatdwnv809iw3s9) (pib:20)

Pushed into mysql-trunk 5.6.99-m5 (revid:alexander.nozdrin@oracle.com-20101113155825-czmva9kg4n31anmu) (version source revid:vasil.dimov@oracle.com-20100629074804-359l9m9gniauxr94) (merge vers: 5.6.99-m4) (pib:21)