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 on 2012-06-02
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>

Michael Widenius (monty) wrote :

Fixed and pushed into MariaDB 5.5 tree

Changed in maria:
status: New → Fix Committed
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  Edit
Everyone can see this information.

Other bug subscribers