Assertion `table->file->stats.records > 0 || error' failed join_read_const_table on concurrent SELECT and DROP/ADD INDEX

Bug #1007967 reported by Elena Stepanova
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
MariaDB
Fix Released
High
Michael Widenius

Bug Description

Version: '5.5.24-MariaDB-debug-log'
mysqld: sql/sql_select.cc:16432: int join_read_const_table(JOIN_TAB*, POSITION*): Assertion `table->file->stats.records > 0 || error' failed.

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (0x28024f8): SELECT t1.f FROM A AS t1 LEFT JOIN B AS t2 ON 0 WHERE t1.f != 5
Connection ID (thread ID): 7
Status: NOT_KILLED

Below is stack trace for all threads (this time the test was run with skip-innodb and aria-checkpoint-interval=0 to reduce the number of involved threads, although neither is needed to reproduce the problem).

Thread 6 (Thread 21247):
#0 0x00007fbe19602709 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x0000000001162be3 in safe_cond_timedwait (cond=0x26e46b8, mp=0x26e4610, abstime=0x7fbe0f7bf9a0,
    file=0x12389e0 "include/mysql/psi/mysql_thread.h", line=1012)
    at mysys/thr_mutex.c:550
#2 0x0000000000842603 in inline_mysql_cond_timedwait (that=0x26e46b8, mutex=0x26e4610, abstime=0x7fbe0f7bf9a0,
    src_file=0x1238be0 "sql/mdl.cc", src_line=1160)
    at include/mysql/psi/mysql_thread.h:1012
#3 0x00000000008444f0 in MDL_wait::timed_wait (this=0x26e4610, thd=0x26e4520, abs_timeout=0x7fbe0f7bf9a0,
    set_status_on_timeout=false, wait_state_name=0x1238b00 "Waiting for table metadata lock")
    at sql/mdl.cc:1160
#4 0x0000000000846705 in MDL_context::acquire_lock (this=0x26e4610, mdl_request=0x7fbe0f7bfa40,
    lock_wait_timeout=31536000) at sql/mdl.cc:1999
#5 0x00000000008472e4 in MDL_context::upgrade_shared_lock_to_exclusive (this=0x26e4610, mdl_ticket=0x7fbe0000efd0,
    lock_wait_timeout=31536000) at sql/mdl.cc:2179
#6 0x0000000000605866 in wait_while_table_is_used (thd=0x26e4520, table=0x7fbe00000ff0,
    function=HA_EXTRA_PREPARE_FOR_RENAME) at sql/sql_base.cc:2338
#7 0x00000000007a33b4 in mysql_alter_table (thd=0x26e4520, new_db=0x26f2708 "test", new_name=0x26f2108 "A",
    create_info=0x7fbe0f7c1d70, table_list=0x26f2140, alter_info=0x7fbe0f7c1e70, order_num=0, order=0x0, ignore=false,
    require_online=false) at sql/sql_table.cc:6868
#8 0x0000000000bc0117 in Alter_table_statement::execute (this=0x26f27c8, thd=0x26e4520)
    at sql/sql_alter.cc:106
#9 0x00000000006ad465 in mysql_execute_command (thd=0x26e4520) at sql/sql_parse.cc:4454
#10 0x00000000006b22c1 in mysql_parse (thd=0x26e4520, rawbuf=0x26f2058 "ALTER TABLE A ADD INDEX (f)", length=27,
    parser_state=0x7fbe0f7c2660) at sql/sql_parse.cc:5731
#11 0x000000000069dd4a in dispatch_command (command=COM_QUERY, thd=0x26e4520,
    packet=0x26edd21 "ALTER TABLE A ADD INDEX (f) ", packet_length=28) at sql/sql_parse.cc:1055
#12 0x000000000069c87a in do_command (thd=0x26e4520) at sql/sql_parse.cc:794
#13 0x0000000000834a05 in do_handle_one_connection (thd_arg=0x26e4520) at sql/sql_connect.cc:1253
#14 0x0000000000834212 in handle_one_connection (arg=0x26e4520) at sql/sql_connect.cc:1168
#15 0x00007fbe195fda4f in start_thread () from /lib64/libpthread.so.0
#16 0x00007fbe1839282d in clone () from /lib64/libc.so.6
#17 0x0000000000000000 in ?? ()

Thread 5 (Thread 21236):
#0 0x00007fbe1960538d in read () from /lib64/libpthread.so.0
#1 0x00000000011c2ee5 in vio_read (vio=0x26c7ad0, buf=0x26c7d40 "\a", size=4)
    at vio/viosocket.c:72
#2 0x00000000005970be in my_real_read (net=0x25d7f78, complen=0x7fbe0f80ad50)
    at sql/net_serv.cc:840
#3 0x0000000000597af6 in my_net_read (net=0x25d7f78) at sql/net_serv.cc:1026
#4 0x000000000069c565 in do_command (thd=0x25d7c70) at sql/sql_parse.cc:740
#5 0x0000000000834a05 in do_handle_one_connection (thd_arg=0x25d7c70) at sql/sql_connect.cc:1253
#6 0x0000000000834212 in handle_one_connection (arg=0x25d7c70) at sql/sql_connect.cc:1168
#7 0x00007fbe195fda4f in start_thread () from /lib64/libpthread.so.0
#8 0x00007fbe1839282d in clone () from /lib64/libc.so.6
#9 0x0000000000000000 in ?? ()

Thread 4 (Thread 21233):
#0 0x00007fbe183896b3 in poll () from /lib64/libc.so.6
#1 0x000000000058c9b9 in handle_connections_sockets () at sql/mysqld.cc:5498
#2 0x000000000058b5d8 in mysqld_main (argc=47, argv=0x24e1a50) at sql/mysqld.cc:4951
#3 0x000000000057d6d6 in main (argc=47, argv=0x7fffc29edcd8) at sql/main.cc:25

Thread 3 (Thread 21249):
#0 0x00007fbe19602709 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
#1 0x0000000001162be3 in safe_cond_timedwait (cond=0x272dc68, mp=0x272dbc0, abstime=0x7fbe0f7779a0,
    file=0x12389e0 "include/mysql/psi/mysql_thread.h", line=1012)
    at mysys/thr_mutex.c:550
#2 0x0000000000842603 in inline_mysql_cond_timedwait (that=0x272dc68, mutex=0x272dbc0, abstime=0x7fbe0f7779a0,
    src_file=0x1238be0 "sql/mdl.cc", src_line=1160)
    at include/mysql/psi/mysql_thread.h:1012
#3 0x00000000008444f0 in MDL_wait::timed_wait (this=0x272dbc0, thd=0x272dad0, abs_timeout=0x7fbe0f7779a0,
    set_status_on_timeout=false, wait_state_name=0x1238b00 "Waiting for table metadata lock")
    at sql/mdl.cc:1160
#4 0x0000000000846705 in MDL_context::acquire_lock (this=0x272dbc0, mdl_request=0x7fbe0f777a40,
    lock_wait_timeout=31536000) at sql/mdl.cc:1999
#5 0x00000000008472e4 in MDL_context::upgrade_shared_lock_to_exclusive (this=0x272dbc0, mdl_ticket=0x7fbe0801b9b0,
    lock_wait_timeout=31536000) at sql/mdl.cc:2179
#6 0x0000000000605866 in wait_while_table_is_used (thd=0x272dad0, table=0x7fbe08012970,
    function=HA_EXTRA_PREPARE_FOR_RENAME) at sql/sql_base.cc:2338
#7 0x00000000007a33b4 in mysql_alter_table (thd=0x272dad0, new_db=0x27fd0f8 "test", new_name=0x27fcaf8 "B",
    create_info=0x7fbe0f779d70, table_list=0x27fcb30, alter_info=0x7fbe0f779e70, order_num=0, order=0x0, ignore=false,
    require_online=false) at sql/sql_table.cc:6868
#8 0x0000000000bc0117 in Alter_table_statement::execute (this=0x27fd1b8, thd=0x272dad0)
    at sql/sql_alter.cc:106
#9 0x00000000006ad465 in mysql_execute_command (thd=0x272dad0) at sql/sql_parse.cc:4454
#10 0x00000000006b22c1 in mysql_parse (thd=0x272dad0, rawbuf=0x27fca48 "ALTER TABLE B ADD INDEX (f)", length=27,
    parser_state=0x7fbe0f77a660) at sql/sql_parse.cc:5731
#11 0x000000000069dd4a in dispatch_command (command=COM_QUERY, thd=0x272dad0,
    packet=0x27a6b01 " ALTER TABLE B ADD INDEX (f)", packet_length=28) at sql/sql_parse.cc:1055
#12 0x000000000069c87a in do_command (thd=0x272dad0) at sql/sql_parse.cc:794
#13 0x0000000000834a05 in do_handle_one_connection (thd_arg=0x272dad0) at sql/sql_connect.cc:1253
#14 0x0000000000834212 in handle_one_connection (arg=0x272dad0) at sql/sql_connect.cc:1168
#15 0x00007fbe195fda4f in start_thread () from /lib64/libpthread.so.0
#16 0x00007fbe1839282d in clone () from /lib64/libc.so.6
#17 0x0000000000000000 in ?? ()

Thread 2 (Thread 21235):
#0 0x00007fbe19605ff7 in do_sigwait () from /lib64/libpthread.so.0
#1 0x00007fbe19606077 in sigwait () from /lib64/libpthread.so.0
#2 0x0000000000585f1f in signal_hand (arg=0x0) at sql/mysqld.cc:3012
#3 0x00007fbe195fda4f in start_thread () from /lib64/libpthread.so.0
#4 0x00007fbe1839282d in clone () from /lib64/libc.so.6
#5 0x0000000000000000 in ?? ()

Thread 1 (Thread 21251):
#0 0x00007fbe196035ec in pthread_kill () from /lib64/libpthread.so.0
#1 0x00000000011574fa in my_write_core (sig=6) at mysys/stacktrace.c:457
#2 0x0000000000958413 in handle_fatal_signal (sig=6) at sql/signal_handler.cc:279
#3 <signal handler called>
#4 0x00007fbe182f49e5 in raise () from /lib64/libc.so.6
#5 0x00007fbe182f5ee6 in abort () from /lib64/libc.so.6
#6 0x00007fbe182ed235 in __assert_fail () from /lib64/libc.so.6
#7 0x000000000072f2d8 in join_read_const_table (tab=0x2726bf8, pos=0x2727220)
    at sql/sql_select.cc:16432
#8 0x00000000006fd421 in make_join_statistics (join=0x2803e80, tables_list=..., conds=0x2803c50, keyuse_array=0x2804150)
    at sql/sql_select.cc:3336
#9 0x00000000006f18cd in JOIN::optimize (this=0x2803e80) at sql/sql_select.cc:1195
#10 0x00000000006fbbc1 in mysql_select (thd=0x27feac0, rref_pointer_array=0x2801768, tables=0x2802750, wild_num=0,
    fields=..., conds=0x2803c50, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, select_options=2147748608,
    result=0x2803e60, unit=0x2800e38, select_lex=0x2801510) at sql/sql_select.cc:3000
#11 0x00000000006ed66e in handle_select (thd=0x27feac0, lex=0x2800d88, result=0x2803e60, setup_tables_done_option=0)
    at sql/sql_select.cc:311
#12 0x00000000006ae1da in execute_sqlcom_select (thd=0x27feac0, all_tables=0x2802750)
    at sql/sql_parse.cc:4616
#13 0x00000000006a21c8 in mysql_execute_command (thd=0x27feac0) at sql/sql_parse.cc:2184
#14 0x00000000006b22c1 in mysql_parse (thd=0x27feac0,
    rawbuf=0x28024f8 "SELECT t1.f FROM A AS t1 LEFT JOIN B AS t2 ON 0 WHERE t1.f != 5", length=63,
    parser_state=0x7fbe0f732660) at sql/sql_parse.cc:5731
#15 0x000000000069dd4a in dispatch_command (command=COM_QUERY, thd=0x27feac0,
    packet=0x26f7321 "SELECT t1.f FROM A AS t1 LEFT JOIN B AS t2 ON 0 WHERE t1.f != 5", packet_length=63)
    at sql/sql_parse.cc:1055
#16 0x000000000069c87a in do_command (thd=0x27feac0) at sql/sql_parse.cc:794
#17 0x0000000000834a05 in do_handle_one_connection (thd_arg=0x27feac0) at sql/sql_connect.cc:1253
#18 0x0000000000834212 in handle_one_connection (arg=0x27feac0) at sql/sql_connect.cc:1168
#19 0x00007fbe195fda4f in start_thread () from /lib64/libpthread.so.0
#20 0x00007fbe1839282d in clone () from /lib64/libc.so.6

maria-5.5
bzr version-info
revision-id: <email address hidden>
date: 2012-05-30 20:20:54 +0200
revno: 3425

With the provided RQG grammar, depending on the machine and luck, sometimes it takes several seconds, sometimes almost 10 minutes to get the failure, but I ran it numerous times, tried on 3 machines, and it always happened, sooner or later.
In all cases I built server as
cmake . -DCMAKE_BUILD_TYPE=Debug
no other parameters.

Could not reproduce on maria-5.3.

# RQG grammar (1.yy):

thread1_init:

CREATE TABLE A (f INT) ENGINE=Aria; CREATE TABLE B (f INT) ENGINE=Aria; INSERT INTO B VALUES (6),(9),(7),(8),(7),(7),(2),(1),(9),(2);

thread1:
  ALTER TABLE A ADD INDEX (f) ; DROP INDEX f ON A ;

thread2:
  DROP INDEX f ON B ; ALTER TABLE B ADD INDEX (f) ;

query:
  SELECT t1.f FROM A AS t1 LEFT JOIN table AS t2 ON 0 WHERE t1.f != _digit ;

table:
  A | B ;

# End of RQG grammar

# Run as

perl runall.pl \
--threads=3 \
--duration=600 \
--queries=100M \
--grammar=1.yy \
--skip-gendata \
--basedir=<your basedir> \
--vardir=<your vardir>

Tags: aria assertion
Revision history for this message
Michael Widenius (monty) wrote :

Fixed and pushed into MariaDB 5.5 tree

Changed in maria:
status: New → Fix Committed
Revision history for this message
Elena Stepanova (elenst) wrote :

Fix released in 5.5.25

Changed in maria:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.