[MDEV-4610] SQL query crashes MariaDB with derived_with_keys - JIRA

Details

Type: Bug
Status: Closed
Priority: Major
Resolution: Fixed
Affects Version/s: 10.0.3, 5.5.31, 5.3.12
Fix Version/s: 10.0.4, 5.5.32, 5.3.13
Component/s: None
Labels:
None
Environment:
ubuntu 12.04 LTS
centos 6

Description

Found my MariaDB 5.5,29 server crashing this morning in production,
Just boiled down a testcase that crashes 5.5.31.

to repeat, execute the following:

drop table if exists T1;
CREATE TABLE `T1` (
  `typeCd` char(4) NOT NULL,
  PRIMARY KEY (`typeCd`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8 ;
insert into T1 values ('AAAA');

drop table if exists T2;
CREATE TABLE `T2` (
 `textCol` text,
 `typeCd` char(4) NOT NULL
) ENGINE=InnoDB  DEFAULT CHARSET=utf8 ;

drop table if exists T3 ;
CREATE TABLE `T3` (
 `id` int(11) NOT NULL
) ENGINE=InnoDB  DEFAULT CHARSET=utf8 ;

drop table if exists T4;
create table T4 (
  val int not null
) Engine=InnoDB default character set =utf8;

SELECT 1 FROM (
     select
      c.textCol
     , c.typeCd

     ,t4.val
     ,count(T3.id) joined

     from T4 t4
     join T2 c
     left outer join T3  on 1=0
 ) top
JOIN T1 t1 ON t1.typeCd = top.typeCd
WHERE top.typeCd =  'AAAA'
ORDER BY val

stack trace:

130603 11:03:41 InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
130603 11:03:41 InnoDB: The InnoDB memory heap is disabled
130603 11:03:41 InnoDB: Mutexes and rw_locks use GCC atomic builtins
130603 11:03:41 InnoDB: Compressed tables use zlib 1.2.3.4
130603 11:03:41 InnoDB: Using Linux native AIO
130603 11:03:41 InnoDB: Initializing buffer pool, size = 256.0M
130603 11:03:41 InnoDB: Completed initialization of buffer pool
130603 11:03:41 InnoDB: highest supported file format is Barracuda.
130603 11:03:42  InnoDB: Waiting for the background threads to start
130603 11:03:43 Percona XtraDB (http://www.percona.com) 5.5.31-MariaDB-30.2 started; log
 sequence number 555155077480
130603 11:03:43 [Note] Plugin 'FEEDBACK' is disabled.
130603 11:03:44 [Note] Server socket created on IP: '127.0.0.1'.
130603 11:03:44 [Note] Event Scheduler: Loaded 0 events
130603 11:03:44 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.5.31-MariaDB-debug-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  Source distribution
InnoDB: DEBUG: update_statistics for cm_dev/T1.
InnoDB: DEBUG: update_statistics for cm_dev/T1.
InnoDB: DEBUG: update_statistics for cm_dev/T2.
InnoDB: DEBUG: update_statistics for cm_dev/T3.
InnoDB: DEBUG: update_statistics for cm_dev/T4.
InnoDB: DEBUG: update_statistics for cm_dev/T4.
InnoDB: DEBUG: update_statistics for cm_dev/T2.
InnoDB: DEBUG: update_statistics for cm_dev/T3.
InnoDB: DEBUG: update_statistics for cm_dev/T4.
InnoDB: DEBUG: update_statistics for cm_dev/T2.
InnoDB: DEBUG: update_statistics for cm_dev/T3.
InnoDB: DEBUG: update_statistics for cm_dev/T1.
130603 11:04:57 [ERROR] mysqld got signal 11 ;
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.

To report this bug, see http://kb.askmonty.org/en/reporting-bugs

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.

Server version: 5.5.31-MariaDB-debug-log
key_buffer_size=134217728
read_buffer_size=2097152
max_used_connections=1
max_threads=102
thread_count=1
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 759611 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x0x4142f90
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 = 0x7fde4b468e48 thread_stack 0x48000
mysys/stacktrace.c:246(my_print_stacktrace)[0xcba06c]
sql/signal_handler.cc:155(handle_fatal_signal)[0x7c85dd]
??:0(??)[0x7fde4aa7acb0]
sql/multi_range_read.cc:1561(DsMrr_impl::choose_mrr_impl(unsigned int, unsigned long long, unsigned int*, unsigned int*, COST_VECT*))[0x74d41c]
sql/multi_range_read.cc:1417(DsMrr_impl::dsmrr_info(unsigned int, unsigned int, unsigned int, unsigned int, unsigned int*, unsigned int*, COST_VECT*))[0x74d101]
maria/ha_maria.cc:3788(ha_maria::multi_range_read_info(unsigned int, unsigned int, unsigned int, unsigned int, unsigned int*, unsigned int*, COST_VECT*))[0x972283]
sql/opt_range.cc:10556(get_quick_select_for_ref(THD*, TABLE*, st_table_ref*, unsigned long long))[0x8de99c]
sql/sql_select.cc:19224(create_sort_index)[0x66e1c9]
sql/sql_select.cc:2798(JOIN::exec())[0x6466f4]
sql/sql_select.cc:3056(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*))[0x647127]
sql/sql_select.cc:318(handle_select(THD*, LEX*, select_result*, unsigned long))[0x63dcde]
sql/sql_parse.cc:4642(execute_sqlcom_select)[0x616a71]
sql/sql_parse.cc:2196(mysql_execute_command(THD*))[0x60f4c0]
sql/sql_parse.cc:5760(mysql_parse(THD*, char*, unsigned int, Parser_state*))[0x619310]
sql/sql_parse.cc:1070(dispatch_command(enum_server_command, THD*, char*, unsigned int))[0x60ca00]
sql/sql_parse.cc:794(do_command(THD*))[0x60bc41]
sql/sql_connect.cc:1266(do_handle_one_connection(THD*))[0x7120e5]
sql/sql_connect.cc:1182(handle_one_connection)[0x711acc]
??:0(??)[0x7fde4aa72e9a]
??:0(??)[0x7fde49d66cbd]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x41c3618): SELECT 1 FROM (
     select
      c.textCol
     , c.typeCd

     ,t4.val
     ,count(T3.id) joined

     from T4 t4
     join T2 c
     left outer join T3  on 1=0
 ) top
JOIN T1 t1 ON t1.typeCd = top.typeCd
WHERE top.typeCd =  'AAAA'
ORDER BY val

Connection ID (thread ID): 137
Status: NOT_KILLED

Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=off

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.
130603 11:04:58 InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
130603 11:04:58 InnoDB: The InnoDB memory heap is disabled
130603 11:04:58 InnoDB: Mutexes and rw_locks use GCC atomic builtins
130603 11:04:58 InnoDB: Compressed tables use zlib 1.2.3.4
130603 11:04:58 InnoDB: Using Linux native AIO
130603 11:04:58 InnoDB: Initializing buffer pool, size = 256.0M
130603 11:04:59 InnoDB: Completed initialization of buffer pool
130603 11:04:59 InnoDB: highest supported file format is Barracuda.
InnoDB: Log scan progressed past the checkpoint lsn 555155077480
130603 11:04:59  InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
InnoDB: Doing recovery: scanned up to log sequence number 555155094134
130603 11:05:02  InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percents: 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99
InnoDB: Apply batch completed
InnoDB: Last MySQL binlog file position 0 713, file name /var/log/mysql/mariadb-bin.002845
130603 11:05:03  InnoDB: Waiting for the background threads to start
130603 11:05:04 Percona XtraDB (http://www.percona.com) 5.5.31-MariaDB-30.2 started; log sequence number 555155094134
130603 11:05:04 [Note] Plugin 'FEEDBACK' is disabled.
130603 11:05:04 [Note] Recovering after a crash using /var/log/mysql/mariadb-bin
130603 11:05:04 [Note] Starting crash recovery...
130603 11:05:04 [Note] Crash recovery finished.
130603 11:05:04 [Note] Server socket created on IP: '127.0.0.1'.
130603 11:05:04 [Note] Event Scheduler: Loaded 0 events
130603 11:05:04 [Note] /usr/sbin/mysqld: ready for connections.

Gliffy Diagrams

Attachments

Issue Links

is duplicated by

MDEV-4643 MariaDB crashes consistently when trying a SELECT on VIEW with a UNION and an additional JOIN in SELECT

Closed

Activity

Ascending order - Click to sort in descending order

Hide

Permalink

Sergei Petrunia added a comment - 2013-06-03 20:04

The crash happens in ha_maria::multi_range_read_info() call.

The cause of the crash is:

(gdb) p this
$87 = (ha_maria *) 0x7fff2c00a2b8
(gdb) p this->table
$89 = (TABLE *) 0x0

handler->table is NULL, because this is a temporary table:

(gdb) up
#3 0x00000000008c89e0 in get_quick_select_for_ref (thd=0xa750670, table=0x7fff2c0838b8, ref=0x7fff2c083200, records=2) at /home/psergey/dev2/5.5/sql/opt_range.cc:10559
(gdb) p table->file
$93 = (ha_maria *) 0x7fff2c00a2b8
(gdb) p table->s->table_name
$95 =

{str = 0x7fff2c0849a0 "/tmp/#sql_61f0_0", length = 16}

The temporary table is a DERIVED temporary table.

Show

Sergei Petrunia added a comment - 2013-06-03 20:04 The crash happens in ha_maria::multi_range_read_info() call. The cause of the crash is: (gdb) p this $87 = (ha_maria *) 0x7fff2c00a2b8 (gdb) p this->table $89 = (TABLE *) 0x0 handler->table is NULL, because this is a temporary table: (gdb) up #3 0x00000000008c89e0 in get_quick_select_for_ref (thd=0xa750670, table=0x7fff2c0838b8, ref=0x7fff2c083200, records=2) at /home/psergey/dev2/5.5/sql/opt_range.cc:10559 (gdb) p table->file $93 = (ha_maria *) 0x7fff2c00a2b8 (gdb) p table->s->table_name $95 = {str = 0x7fff2c0849a0 "/tmp/#sql_61f0_0", length = 16} The temporary table is a DERIVED temporary table.

Hide

Permalink

Sergei Petrunia added a comment - 2013-06-03 20:05 - edited

Btw, the crash goes away if one specifies optimizer_switch='derived_merge=off'. (CORRECTION: derived_with_keys, not derived_merge)

Show

Sergei Petrunia added a comment - 2013-06-03 20:05 - edited Btw, the crash goes away if one specifies optimizer_switch='derived_merge=off'. (CORRECTION: derived_with_keys, not derived_merge)

Hide

Permalink

Sergei Petrunia added a comment - 2013-06-03 20:06

mysql-5.6 has the same query plan and does not crash:

+id select_type table type possible_keys key key_len ref rows Extra
+1 PRIMARY t1 const PRIMARY PRIMARY 12 const 1 Using index; Using filesort
+1 PRIMARY <derived2> ref <auto_key0> <auto_key0> 15 const 0 Using index condition; Using where
+2 DERIVED t4 ALL NULL NULL NULL NULL 1 NULL
+2 DERIVED c ALL NULL NULL NULL NULL 1 Using join buffer (Block Nested Loop)
+2 DERIVED T3 ALL NULL NULL NULL NULL 1 Using where; Using join buffer (Block Nested Loop)

5.5
id select_type table type possible_keys key key_len ref rows Extra
1 PRIMARY t1 const PRIMARY PRIMARY 12 const 1 Using index; Using filesort
1 PRIMARY <derived2> ref key0 key0 13 const 0 Using where
2 DERIVED t4 ALL NULL NULL NULL NULL 1
2 DERIVED c ALL NULL NULL NULL NULL 1 Using join buffer (flat, BNL join)
2 DERIVED T3 ALL NULL NULL NULL NULL 1 Using where; Using join buffer (incremental, BNL join)

Query results are different between maria-5.5 and 5.6

Show

Sergei Petrunia added a comment - 2013-06-03 20:06 mysql-5.6 has the same query plan and does not crash: +id select_type table type possible_keys key key_len ref rows Extra +1 PRIMARY t1 const PRIMARY PRIMARY 12 const 1 Using index; Using filesort +1 PRIMARY <derived2> ref <auto_key0> <auto_key0> 15 const 0 Using index condition; Using where +2 DERIVED t4 ALL NULL NULL NULL NULL 1 NULL +2 DERIVED c ALL NULL NULL NULL NULL 1 Using join buffer (Block Nested Loop) +2 DERIVED T3 ALL NULL NULL NULL NULL 1 Using where; Using join buffer (Block Nested Loop) 5.5 id select_type table type possible_keys key key_len ref rows Extra 1 PRIMARY t1 const PRIMARY PRIMARY 12 const 1 Using index; Using filesort 1 PRIMARY <derived2> ref key0 key0 13 const 0 Using where 2 DERIVED t4 ALL NULL NULL NULL NULL 1 2 DERIVED c ALL NULL NULL NULL NULL 1 Using join buffer (flat, BNL join) 2 DERIVED T3 ALL NULL NULL NULL NULL 1 Using where; Using join buffer (incremental, BNL join) Query results are different between maria-5.5 and 5.6

Hide

Permalink

Sergei Petrunia added a comment - 2013-06-03 20:16

Looking at mysql-5.6:

#1 0x0000000000a52363 in ha_myisam::multi_range_read_info (this=0x7fffbc05ed20, keyno=0, n_ranges=1, keys=2, bufsz=0x7fffbc048b5c, flags=0x7fffbc048b58, cost=0x7ffff4203a20) at mysql-5.6-ga/storage/myisam/ha_myisam.cc:2221
(gdb) p this
$11 = (ha_myisam *) 0x7fffbc05ed20
(gdb) p table
$13 = (TABLE *) 0x7fffbc05d970

They also call for ha_myisam::multi_range_read_info(). But their temporary table doesn't have ha_myisam->table==NULL.

Show

Sergei Petrunia added a comment - 2013-06-03 20:16 Looking at mysql-5.6: #1 0x0000000000a52363 in ha_myisam::multi_range_read_info (this=0x7fffbc05ed20, keyno=0, n_ranges=1, keys=2, bufsz=0x7fffbc048b5c, flags=0x7fffbc048b58, cost=0x7ffff4203a20) at mysql-5.6-ga/storage/myisam/ha_myisam.cc:2221 (gdb) p this $11 = (ha_myisam *) 0x7fffbc05ed20 (gdb) p table $13 = (TABLE *) 0x7fffbc05d970 They also call for ha_myisam::multi_range_read_info(). But their temporary table doesn't have ha_myisam->table==NULL.

Hide

Permalink

Sergei Petrunia added a comment - 2013-06-03 20:31

mysql assigns ha_myisam->table here:

#0 handler::ha_open (this=0x7fffbc05ed20, table_arg=0x7fffbc05d970, name=0x7fffbc05e8f0 "/tmp/#sql_77a4_0", mode=2, test_if_locked=516) at /home/psergey/dev2/mysql-5.6-ga/sql/handler.cc:2434
#1 0x0000000000815e3e in open_tmp_table (table=0x7fffbc05d970) at /home/psergey/dev2/mysql-5.6-ga/sql/sql_tmp_table.cc:1599
#2 0x00000000008167ce in instantiate_tmp_table (table=0x7fffbc05d970, keyinfo=0x7fffbc05ebf0, start_recinfo=0x7fffbc05e6b0, recinfo=0x7fffbc044e70, options=2416188160, big_tables=0 '\000', trace=0x1ff1818) at /home/psergey/dev2/mysql-5.6-ga/sql/sql_tmp_table.cc:1828
#3 0x000000000076a6b5 in mysql_derived_create (thd=0x1fef680, lex=0x1ff1838, derived=0x7fffbc0437b8) at /home/psergey/dev2/mysql-5.6-ga/sql/sql_derived.cc:358
#4 0x0000000000769eab in mysql_handle_single_derived (lex=0x1ff1838, derived=0x7fffbc0437b8, processor=0x76a4c6 <mysql_derived_create(THD*, LEX*, TABLE_LIST*)>) at /home/psergey/dev2/mysql-5.6-ga/sql/sql_derived.cc:115
#5 0x0000000000859836 in TABLE_LIST::handle_derived (this=0x7fffbc0437b8, lex=0x1ff1838, processor=0x76a4c6 <mysql_derived_create(THD*, LEX*, TABLE_LIST*)>) at /home/psergey/dev2/mysql-5.6-ga/sql/table.cc:6243
#6 0x000000000079065a in st_select_lex::handle_derived (this=0x1ff1f38, lex=0x1ff1838, processor=0x76a4c6 <mysql_derived_create(THD*, LEX*, TABLE_LIST*)>) at /home/psergey/dev2/mysql-5.6-ga/sql/sql_lex.cc:3762
#7 0x00000000007c6d59 in JOIN::prepare_result (this=0x7fffbc05bfa8, columns_list=0x7ffff4203db0) at /home/psergey/dev2/mysql-5.6-ga/sql/sql_select.cc:816
#8 0x000000000076d615 in JOIN::exec (this=0x7fffbc05bfa8) at /home/psergey/dev2/mysql-5.6-ga/sql/sql_executor.cc:116

The problem in MariaDB is that it calls ha_myisam::multi_range_read_info() before calling mysql_derived_create.

Show

Sergei Petrunia added a comment - 2013-06-03 20:31 mysql assigns ha_myisam->table here: #0 handler::ha_open (this=0x7fffbc05ed20, table_arg=0x7fffbc05d970, name=0x7fffbc05e8f0 "/tmp/#sql_77a4_0", mode=2, test_if_locked=516) at /home/psergey/dev2/mysql-5.6-ga/sql/handler.cc:2434 #1 0x0000000000815e3e in open_tmp_table (table=0x7fffbc05d970) at /home/psergey/dev2/mysql-5.6-ga/sql/sql_tmp_table.cc:1599 #2 0x00000000008167ce in instantiate_tmp_table (table=0x7fffbc05d970, keyinfo=0x7fffbc05ebf0, start_recinfo=0x7fffbc05e6b0, recinfo=0x7fffbc044e70, options=2416188160, big_tables=0 '\000', trace=0x1ff1818) at /home/psergey/dev2/mysql-5.6-ga/sql/sql_tmp_table.cc:1828 #3 0x000000000076a6b5 in mysql_derived_create (thd=0x1fef680, lex=0x1ff1838, derived=0x7fffbc0437b8) at /home/psergey/dev2/mysql-5.6-ga/sql/sql_derived.cc:358 #4 0x0000000000769eab in mysql_handle_single_derived (lex=0x1ff1838, derived=0x7fffbc0437b8, processor=0x76a4c6 <mysql_derived_create(THD*, LEX*, TABLE_LIST*)>) at /home/psergey/dev2/mysql-5.6-ga/sql/sql_derived.cc:115 #5 0x0000000000859836 in TABLE_LIST::handle_derived (this=0x7fffbc0437b8, lex=0x1ff1838, processor=0x76a4c6 <mysql_derived_create(THD*, LEX*, TABLE_LIST*)>) at /home/psergey/dev2/mysql-5.6-ga/sql/table.cc:6243 #6 0x000000000079065a in st_select_lex::handle_derived (this=0x1ff1f38, lex=0x1ff1838, processor=0x76a4c6 <mysql_derived_create(THD*, LEX*, TABLE_LIST*)>) at /home/psergey/dev2/mysql-5.6-ga/sql/sql_lex.cc:3762 #7 0x00000000007c6d59 in JOIN::prepare_result (this=0x7fffbc05bfa8, columns_list=0x7ffff4203db0) at /home/psergey/dev2/mysql-5.6-ga/sql/sql_select.cc:816 #8 0x000000000076d615 in JOIN::exec (this=0x7fffbc05bfa8) at /home/psergey/dev2/mysql-5.6-ga/sql/sql_executor.cc:116 The problem in MariaDB is that it calls ha_myisam::multi_range_read_info() before calling mysql_derived_create.

Hide

Permalink

Sergei Petrunia added a comment - 2013-06-04 18:14

It crashes with MRR=off also.

Show

Sergei Petrunia added a comment - 2013-06-04 18:14 It crashes with MRR=off also.

Hide

Permalink

Sergei Petrunia added a comment - 2013-06-04 18:23

And crashes on 5.3, also

Show

Sergei Petrunia added a comment - 2013-06-04 18:23 And crashes on 5.3, also

Hide

Permalink

Sergei Petrunia added a comment - 2013-06-04 18:26

I believe, the problem is not related to MRR.
I believe, the problem is related to derived table handling code.

De-assigning from me.

Show

Sergei Petrunia added a comment - 2013-06-04 18:26 I believe, the problem is not related to MRR. I believe, the problem is related to derived table handling code. De-assigning from me.

Hide

Permalink

Elena Stepanova added a comment - 2013-06-12 17:12

See also ~~MDEV-4643~~ (a different test case, same stack trace)

Show

Elena Stepanova added a comment - 2013-06-12 17:12 See also MDEV-4643 (a different test case, same stack trace)

People

Assignee:

Sergei Golubchik

Reporter:

Danny Sadinoff

Votes:

0 Vote for this issue

Watchers:

5 Start watching this issue

Dates

Created:

2013-06-03 14:30

Updated:

2013-07-08 12:08

Resolved:

2013-07-08 12:08

Time Tracking

Estimated:

Not Specified

Remaining:

Logged:

Agile

View on Board