[MDEV-297] SHOW EXPLAIN: Server gets stuck until timeout occurs while executing SHOW INDEX and SHOW EXPLAIN in parallel Created: 2012-05-25  Updated: 2012-06-07  Resolved: 2012-06-07

Status: Closed
Project: MariaDB Server
Component/s: None
Affects Version/s: None
Fix Version/s: 10.0.0

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Sergei Petrunia
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-165 MWL#182: Explain running statements: ... Closed

 Description   

The essential part of the flow is that one thread runs SHOW INDEX FROM table, and another thread executes SHOW EXPLAIN for the first thread. At some point both threads stop, wait for 30 seconds after which SHOW EXPLAIN aborts with timeout, and the flow resumes.

The number of rows in the table is not important, reproducible with 1 as well as 1000 rows. The number of indexes is reasonable (~5 in the test data).

Below is the stack trace at the time when the server is stuck (this is all thread bt, this time I ran the test without InnoDB and with aria checkpoint interval = 0 to get rid of non-essential threads, but the problem is reproducible regardless of this):

 
 
Thread 5 (Thread 0xae9efb70 (LWP 25352)):
 
#0  0xffffe430 in __kernel_vsyscall ()
 
#1  0xb7817331 in do_sigwait () from /lib/libpthread.so.0
 
#2  0xb78173c3 in sigwait () from /lib/libpthread.so.0
 
#3  0x0819a08f in signal_hand (arg=0x0) at sql/mysqld.cc:3009
 
#4  0xb780eb25 in start_thread () from /lib/libpthread.so.0
 
#5  0xb75de38e in clone () from /lib/libc.so.6
 
 
 
Thread 4 (Thread 0xae9a7b70 (LWP 25354)):
 
#0  0xffffe430 in __kernel_vsyscall ()
 
#1  0xb781612b in read () from /lib/libpthread.so.0
 
#2  0x088c36bd in vio_read (vio=0x96be240, buf=0x96ade10 "\a", size=4)
 
    at vio/viosocket.c:67
 
#3  0x081a4247 in my_real_read (net=0x9606670, complen=0xae9a7288)
 
    at sql/net_serv.cc:840
 
#4  0x081a47be in my_net_read (net=0x9606670) at sql/net_serv.cc:1026
 
#5  0x08238a83 in do_command (thd=0x9606488) at sql/sql_parse.cc:741
 
#6  0x083245f9 in do_handle_one_connection (thd_arg=0x9606488)
 
    at sql/sql_connect.cc:1253
 
#7  0x08324144 in handle_one_connection (arg=0x9606488)
 
    at sql/sql_connect.cc:1168
 
#8  0xb780eb25 in start_thread () from /lib/libpthread.so.0
 
#9  0xb75de38e in clone () from /lib/libc.so.6
 
 
 
Thread 3 (Thread 0xae917b70 (LWP 25368)):
 
#0  0xffffe430 in __kernel_vsyscall ()
 
#1  0xb7815cc9 in __lll_lock_wait () from /lib/libpthread.so.0
 
#2  0xb78111f3 in _L_lock_974 () from /lib/libpthread.so.0
 
#3  0xb781114f in pthread_mutex_lock () from /lib/libpthread.so.0
 
#4  0x0888c5fe in safe_mutex_lock (mp=0x96c289c, my_flags=0, 
    file=0x88dd984 "sql/sql_base.cc", line=1615)
 
    at mysys/thr_mutex.c:297
 
#5  0x081dea65 in inline_mysql_mutex_lock (that=0x96c289c, 
    src_file=0x88dd984 "sql/sql_base.cc", src_line=1615)
 
    at include/mysql/psi/mysql_thread.h:618
 
#6  0x081e1b02 in close_thread_table (thd=0x96c1b78, table_ptr=0x96c1be0)
 
    at sql/sql_base.cc:1615
 
#7  0x081e13bc in close_open_tables (thd=0x96c1b78)
 
    at sql/sql_base.cc:1371
 
#8  0x081e18b0 in close_thread_tables (thd=0x96c1b78)
 
    at sql/sql_base.cc:1580
 
#9  0x082ad8e0 in fill_schema_table_by_open (thd=0x96c1b78, is_show_fields_or_keys=true, 
    table=0x97482f0, schema_table=0x8bde0b0, orig_db_name=0xae915f9c, orig_table_name=0xae915f94, 
    open_tables_state_backup=0xae915f44, can_deadlock=false)
 
    at sql/sql_show.cc:3713
 
#10 0x082ae5eb in get_all_tables (thd=0x96c1b78, tables=0x96e9ec8, cond=0x0)
 
    at sql/sql_show.cc:4214
 
#11 0x082ba9fb in do_fill_table (thd=0x96c1b78, table_list=0x96e9ec8, join_table=0x96f1960)
 
    at sql/sql_show.cc:7503
 
#12 0x082bad8b in get_schema_tables_result (join=0x96f0dc0, executed_place=PROCESSED_BY_JOIN_EXEC)
 
    at sql/sql_show.cc:7610
 
#13 0x0826d464 in JOIN::exec_inner (this=0x96f0dc0)
 
    at sql/sql_select.cc:2355
 
#14 0x0826cb87 in JOIN::exec (this=0x96f0dc0)
 
    at sql/sql_select.cc:2201
 
#15 0x0826f9c4 in mysql_select (thd=0x96c1b78, rref_pointer_array=0x96c37b4, tables=0x96e9ec8, 
    wild_num=0, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, having=0x0, proc_param=0x0, 
    select_options=2684619520, result=0x96eac00, unit=0x96c31c0, select_lex=0x96c3670)
 
    at sql/sql_select.cc:3093
 
#16 0x08267464 in handle_select (thd=0x96c1b78, lex=0x96c315c, result=0x96eac00, 
    setup_tables_done_option=0) at sql/sql_select.cc:357
 
#17 0x08242e86 in execute_sqlcom_select (thd=0x96c1b78, all_tables=0x96e9ec8)
 
    at sql/sql_parse.cc:4643
 
#18 0x0823bcbb in mysql_execute_command (thd=0x96c1b78)
 
    at sql/sql_parse.cc:2185
 
#19 0x08245477 in mysql_parse (thd=0x96c1b78, rawbuf=0x96e8ea8 "SHOW INDEX FROM `AA`", length=20, 
    parser_state=0xae916de4) at sql/sql_parse.cc:5758
 
#20 0x08239788 in dispatch_command (command=COM_QUERY, thd=0x96c1b78, 
    packet=0x96c8299 "SHOW INDEX FROM `AA`", packet_length=20)
 
    at sql/sql_parse.cc:1056
 
#21 0x08238c4d in do_command (thd=0x96c1b78) at sql/sql_parse.cc:795
 
#22 0x083245f9 in do_handle_one_connection (thd_arg=0x96c1b78)
 
    at sql/sql_connect.cc:1253
 
#23 0x08324144 in handle_one_connection (arg=0x96c1b78)
 
    at sql/sql_connect.cc:1168
 
#24 0xb780eb25 in start_thread () from /lib/libpthread.so.0
 
#25 0xb75de38e in clone () from /lib/libc.so.6
 
 
 
Thread 2 (Thread 0xae95fb70 (LWP 25370)):
 
#0  0xffffe430 in __kernel_vsyscall ()
 
#1  0xb7813452 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib/libpthread.so.0
 
#2  0x0888cf57 in safe_cond_timedwait (cond=0xae95e74c, mp=0xae95e6ec, abstime=0xae95e788, 
    file=0x891e82c "sql/my_apc.cc", line=173)
 
    at mysys/thr_mutex.c:550
 
#3  0x083720ea in Apc_target::make_apc_call (this=0x96c30e0, 
    func=0x820aa72 <Show_explain_request::get_explain_data(void*)>, func_arg=0xae95e7f8, 
    timeout_sec=30, timed_out=0xae95e823) at sql/my_apc.cc:173
 
#4  0x082a9801 in mysqld_show_explain (thd=0x9712600, thread_id=7)
 
    at sql/sql_show.cc:2069
 
#5  0x0823e505 in mysql_execute_command (thd=0x9712600)
 
    at sql/sql_parse.cc:3154
 
#6  0x08245477 in mysql_parse (thd=0x9712600, rawbuf=0x96f8c60 "SHOW EXPLAIN FOR @con_id", 
    length=24, parser_state=0xae95ede4) at sql/sql_parse.cc:5758
 
#7  0x08239788 in dispatch_command (command=COM_QUERY, thd=0x9712600, packet=0x9740261 "", 
    packet_length=24) at sql/sql_parse.cc:1056
 
#8  0x08238c4d in do_command (thd=0x9712600) at sql/sql_parse.cc:795
 
#9  0x083245f9 in do_handle_one_connection (thd_arg=0x9712600)
 
    at sql/sql_connect.cc:1253
 
#10 0x08324144 in handle_one_connection (arg=0x9712600)
 
    at sql/sql_connect.cc:1168
 
#11 0xb780eb25 in start_thread () from /lib/libpthread.so.0
 
#12 0xb75de38e in clone () from /lib/libc.so.6
 
 
 
Thread 1 (Thread 0xb75096d0 (LWP 25350)):
 
#0  0xffffe430 in __kernel_vsyscall ()
 
#1  0xb75d367e in poll () from /lib/libc.so.6
 
#2  0x0819e04f in handle_connections_sockets () at sql/mysqld.cc:5496
 
#3  0x0819d3bf in mysqld_main (argc=47, argv=0x9552cb8)
 
    at sql/mysqld.cc:4949
 
#4  0x081957bb in main (argc=47, argv=0xbfdac314) at sql/main.cc:25

  1. RQG grammar (t.yy):

 
 
thread2_init:
 
  SET @con_id = CONNECTION_ID()-1;
 
 
 
query:
 
  SHOW INDEX FROM _table;
 
 
 
thread2:
 
  SHOW EXPLAIN FOR @con_id;

  1. Basic command line to run the test: 

    perl ./runall.pl \
    		 
    --queries=100M \
    		 
    --duration=300 \
    		 
    --grammar=t.yy \
    		 
    --engine=MyISAM \
    		 
    --threads=2 \
    		 
    --basedir=<your basedir> \
    		 
    --vardir=<your vardir>

However, with this you won't see when server stops, unless you set up some kind of external monitoring (watch general log, run show processlist periodically, etc.). To be able to see when it happens, you can run it with QueryTimeout reporter:

perl ./runall.pl \
 
--queries=100M \
 
--duration=300 \
 
--grammar=t.yy \
 
--engine=MyISAM \
 
--threads=2 \
 
--reporters=QueryTimeout \
 
--basedir=<your basedir> \
 
--vardir=<your vardir>

It will report the errors like this:

# 2012-05-25T18:40:17 Query: SHOW EXPLAIN FOR @con_id is taking more than 20 seconds. Killing query.
 
# 2012-05-25T18:40:17 Query: SHOW FULL PROCESSLIST is taking more than 20 seconds. Killing query.
 
DBD::mysql::db do failed: Query execution was interrupted at lib/GenTest/Reporter/QueryTimeout.pm line 75.
 
# 2012-05-25T18:40:47 Query: SHOW EXPLAIN FOR @con_id is taking more than 20 seconds. Killing query.

The downside of it is that it adds SHOW FULL PROCESSLIST to the flow, and the command also gets stuck when the problem occurs.


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