[MDEV-272] SHOW EXPLAIN: Running SHOW EXPLAIN in parallel with a query makes the query thread die Created: 2012-05-15  Updated: 2012-05-16  Resolved: 2012-05-16

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   

In the provided scenario SHOW EXPLAIN is run repeatedly for a thread with a simple SELECT which is supposed to return many rows. Normally (without concurrent SHOW EXPLAIN) the query is finished in less than a second.
First attempts of concurrent SHOW EXPLAIN say that the target thread is not yet running a query (expectedly); then it shows the query plan a number of times; then at some point it stops for about a minute, and after that reports that the target thread does not exist. SELECT instead of the normal output ends with error 2013 (Lost connection to MySQL server during query).

Stack trace from the minute when both threads seem to be stuck (it does not change during this minute):

Thread 5 (Thread 0x7f00abd88710 (LWP 4520)):
 
#0  0x00007f00aca74709 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
#1  0x0000000000c66a43 in safe_cond_timedwait (cond=0x1327d20, mp=0x1327c80, 
    abstime=0x7f00abd87e00, file=0xe738c0 "ma_servicethread.c", line=101) at thr_mutex.c:552
 
#2  0x0000000000a9b672 in my_service_thread_sleep (control=0x12ffe20, sleep_time=29000000000)
 
    at ma_servicethread.c:100
 
#3  0x0000000000a3bed4 in ma_checkpoint_background (arg=0x1e) at ma_checkpoint.c:707
 
#4  0x00007f00aca6fa4f in start_thread () from /lib64/libpthread.so.0
 
#5  0x00007f00abe5982d in clone () from /lib64/libc.so.6
 
#6  0x0000000000000000 in ?? ()
 
 
 
Thread 4 (Thread 0x7f00a331a710 (LWP 4521)):
 
#0  0x00007f00aca77ff7 in do_sigwait () from /lib64/libpthread.so.0
 
#1  0x00007f00aca78077 in sigwait () from /lib64/libpthread.so.0
 
#2  0x00000000006e3b2e in signal_hand (arg=0x0) at mysqld.cc:2847
 
#3  0x00007f00aca6fa4f in start_thread () from /lib64/libpthread.so.0
 
#4  0x00007f00abe5982d in clone () from /lib64/libc.so.6
 
#5  0x0000000000000000 in ?? ()
 
 
 
Thread 3 (Thread 0x7f00a32d2710 (LWP 4529)):
 
#0  0x00007f00aca74709 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
 
#1  0x0000000000c66a43 in safe_cond_timedwait (cond=0x7f00a32d0af8, mp=0x7f00a32d0a58, 
    abstime=0x7f00a32d0b40, file=0xe4f180 "my_apc.cc", line=172) at thr_mutex.c:552
 
#2  0x000000000095b0a5 in Apc_target::make_apc_call (this=0x1cd9120, func=
 
    0x6ccb0e <Show_explain_request::get_explain_data(void*)>, func_arg=0x7f00a32d0ba0, 
    timeout_sec=30, timed_out=0x7f00a32d0c0f) at my_apc.cc:172
 
#3  0x00000000008b47a5 in mysqld_show_explain (thd=0x1c2ea98, thread_id=3) at sql_show.cc:2119
 
#4  0x00000000006faaa3 in mysql_execute_command (thd=0x1c2ea98) at sql_parse.cc:3488
 
#5  0x0000000000702cb4 in mysql_parse (thd=0x1c2ea98, rawbuf=0x1cb32d0 "SHOW EXPLAIN FOR 3", 
    length=18, found_semicolon=0x7f00a32d1c98) at sql_parse.cc:6179
 
#6  0x00000000006f49ce in dispatch_command (command=COM_QUERY, thd=0x1c2ea98, packet=0x1ca9e69 "", 
    packet_length=18) at sql_parse.cc:1229
 
#7  0x00000000006f3d02 in do_command (thd=0x1c2ea98) at sql_parse.cc:924
 
#8  0x00000000006f0b46 in handle_one_connection (arg=0x1c2ea98) at sql_connect.cc:1218
 
#9  0x00007f00aca6fa4f in start_thread () from /lib64/libpthread.so.0
 
#10 0x00007f00abe5982d in clone () from /lib64/libc.so.6
 
#11 0x0000000000000000 in ?? ()
 
 
 
Thread 2 (Thread 0x7f00a328a710 (LWP 4530)):
 
#0  0x00007f00aca7732d in write () from /lib64/libpthread.so.0
 
#1  0x0000000000c32ff5 in vio_write (vio=0x1cca3c8, buf=0x1cde3d8 "\373\373\373\373\373\r", 
    size=384) at viosocket.c:114
 
#2  0x00000000006d4b53 in net_real_write (net=0x1cd6f18, 
    packet=0x1cda558 "\373\373\373\373\373\373\373\373\r", len=16384) at net_serv.cc:620
 
#3  0x00000000006d4746 in net_write_buff (net=0x1cd6f18, 
    packet=0x1ce0a78 "\004\067\067\065\065\373\373\373\373\373\373\373\373t1\002f8\002f8\f?", 
    len=13) at net_serv.cc:516
 
#4  0x00000000006d4384 in my_net_write (net=0x1cd6f18, 
    packet=0x1ce0a78 "\004\067\067\065\065\373\373\373\373\373\373\373\373t1\002f8\002f8\f?", 
    len=13) at net_serv.cc:401
 
#5  0x00000000006d7d9e in Protocol::write (this=0x1cd7208) at protocol.cc:834
 
#6  0x00000000006c8f62 in select_send::send_data (this=0x1ce5368, items=...) at sql_class.cc:2044
 
#7  0x000000000079cbb0 in end_send (join=0x1ce5388, join_tab=0x1d420c0, end_of_records=false)
 
    at sql_select.cc:16792
 
#8  0x000000000079aaa1 in evaluate_join_record (join=0x1ce5388, join_tab=0x1d41da0, error=0)
 
    at sql_select.cc:15951
 
#9  0x000000000079a46d in sub_select (join=0x1ce5388, join_tab=0x1d41da0, end_of_records=false)
 
    at sql_select.cc:15793
 
#10 0x0000000000799a8e in do_select (join=0x1ce5388, fields=0x1cd99c0, table=0x0, procedure=0x0)
 
    at sql_select.cc:15414
 
#11 0x000000000077aa4e in JOIN::exec_inner (this=0x1ce5388) at sql_select.cc:2810
 
#12 0x0000000000777e31 in JOIN::exec (this=0x1ce5388) at sql_select.cc:2125
 
#13 0x000000000077b2e7 in mysql_select (thd=0x1cd6e08, rref_pointer_array=0x1cd9b10, 
    tables=0x1ce4ec0, wild_num=1, fields=..., conds=0x0, og_num=0, order=0x0, group=0x0, 
    having=0x0, proc_param=0x0, select_options=2147764736, result=0x1ce5368, unit=0x1cd93b0, 
    select_lex=0x1cd98b8) at sql_select.cc:3031
 
#14 0x0000000000771d62 in handle_select (thd=0x1cd6e08, lex=0x1cd9310, result=0x1ce5368, 
    setup_tables_done_option=0) at sql_select.cc:332
 
#15 0x00000000007002d9 in execute_sqlcom_select (thd=0x1cd6e08, all_tables=0x1ce4ec0)
 
    at sql_parse.cc:5178
 
#16 0x00000000006f721f in mysql_execute_command (thd=0x1cd6e08) at sql_parse.cc:2285
 
#17 0x0000000000702cb4 in mysql_parse (thd=0x1cd6e08, rawbuf=0x1ce4ce0 "SELECT * FROM t1", 
    length=16, found_semicolon=0x7f00a3289c98) at sql_parse.cc:6179
 
#18 0x00000000006f49ce in dispatch_command (command=COM_QUERY, thd=0x1cd6e08, 
    packet=0x1cda559 "\373\373\373\373\373\373\373\r", packet_length=16) at sql_parse.cc:1229
 
#19 0x00000000006f3d02 in do_command (thd=0x1cd6e08) at sql_parse.cc:924
 
#20 0x00000000006f0b46 in handle_one_connection (arg=0x1cd6e08) at sql_connect.cc:1218
 
#21 0x00007f00aca6fa4f in start_thread () from /lib64/libpthread.so.0
 
#22 0x00007f00abe5982d in clone () from /lib64/libc.so.6
 
#23 0x0000000000000000 in ?? ()
 
 
 
Thread 1 (Thread 0x7f00ad8db720 (LWP 4518)):
 
#0  0x00007f00abe52e13 in select () from /lib64/libc.so.6
 
#1  0x00000000006e7761 in handle_connections_sockets (arg=0x0) at mysqld.cc:5276
 
#2  0x00000000006e69e3 in main (argc=10, argv=0x7fffe6978948) at mysqld.cc:4746

bzr version-info

revision-id: psergey@askmonty.org-20120515115650-kqeip9cgxltgzx75
 
date: 2012-05-15 15:56:50 +0400
 
revno: 3511

Test case:

--connect (con1,localhost,root,,)
 
 
 
CREATE TABLE t1 (
 
 pk INT NOT NULL AUTO_INCREMENT PRIMARY KEY,
 
 f1 VARCHAR(10) DEFAULT NULL,
 
 f2 BIGINT DEFAULT NULL,
 
 f3 SMALLINT DEFAULT NULL,
 
 f4 VARCHAR(10) DEFAULT NULL,
 
 f5 VARCHAR(64) DEFAULT NULL,
 
 f6 VARCHAR(64) DEFAULT NULL,
 
 f7 BIGINT DEFAULT NULL,
 
 f8 SMALLINT DEFAULT NULL
 
) ENGINE=MyISAM;
 
 
 
INSERT INTO t1 (pk) VALUES (NULL),(NULL),(NULL),(NULL),(NULL);
 
INSERT INTO t1 (pk) SELECT NULL FROM t1 t1a, t1 t1b;
 
INSERT INTO t1 (pk) SELECT NULL FROM t1 t1a, t1 t1b, t1 t1c;
 
 
 
--let $con_id = `SELECT CONNECTION_ID()`
 
--send SELECT * FROM t1
 
 
 
--connection default
 
--let $run = 1000
 
--disable_abort_on_error
 
while ($run)
 
{
 
   --eval SHOW EXPLAIN FOR $con_id
 
   --dec $run
 
}
 
--enable_abort_on_error
 
 
 
--connection con1
 
--disable_result_log
 
--reap
 
 
 
DROP TABLE t1;



 Comments   
Comment by Sergei Petrunia [ 2012-05-16 ]

This is not a bug. The testcase:

  • sends a SELECT query via one connection
  • then, repeatedly runs SHOW EXPLAIN, while neglecting to read SELECT's output.
    Eventually, the SELECT thread freezes in write() call when writing to client.
    When the target thread is frozen, SHOW EXPLAIN doesn't work.

After some time, the connection is killed. That's why SELECT gets "lost connection during query", while SHOW EXPLAIN commands get "No such connection".

As a result: made SHOW EXPLAIN explicitly return Timeout error (instead of "Target is not running an EXPLAINable command).

Comment by Sergei Petrunia [ 2012-05-16 ]

as expected:
Changing the query from
SELECT * FROM t1
into something that produces fewer output, like
SELECT max(f7) FROM t1
makes the problem go away

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