[MDEV-4610] SQL query crashes MariaDB with derived_with_keys Created: 2013-06-03  Updated: 2013-07-08  Resolved: 2013-07-08

Status: Closed
Project: MariaDB Server
Component/s: None
Affects Version/s: 10.0.3, 5.5.31, 5.3.12
Fix Version/s: 10.0.4, 5.5.32, 5.3.13

Type: Bug Priority: Major
Reporter: Danny Sadinoff Assignee: Sergei Golubchik
Resolution: Fixed Votes: 0
Labels: None
Environment:

ubuntu 12.04 LTS
centos 6

Issue Links:
Duplicate
is duplicated by MDEV-4643 MariaDB crashes consistently when try... Closed

 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.



 Comments   
Comment by Sergei Petrunia [ 2013-06-03 ]

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.

Comment by Sergei Petrunia [ 2013-06-03 ]

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

Comment by Sergei Petrunia [ 2013-06-03 ]

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

Comment by Sergei Petrunia [ 2013-06-03 ]

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.

Comment by Sergei Petrunia [ 2013-06-03 ]

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.

Comment by Sergei Petrunia [ 2013-06-04 ]

It crashes with MRR=off also.

Comment by Sergei Petrunia [ 2013-06-04 ]

And crashes on 5.3, also

Comment by Sergei Petrunia [ 2013-06-04 ]

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

De-assigning from me.

Comment by Elena Stepanova [ 2013-06-12 ]

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

Generated at Thu Feb 08 06:57:43 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.