[MDEV-5117] Explain for a query executed as a PS is not written into the slow log Created: 2013-10-09  Updated: 2013-10-15  Resolved: 2013-10-15

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

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

Issue Links:
Relates
relates to MDEV-407 Print EXPLAIN [ANALYZE] in the slow q... Closed

 Description   

I'm not sure if it should be, but even if not, it's good to have it for the record as "not a bug"

When a query, e.g. a SELECT, is executed via a PS, it's written into the slow log as a query, but explain is not there.

let $datadir = `select @@datadir`;
 
 
 
prepare stmt from "select sleep(1)";
 
set global slow_query_log = 1;
 
set long_query_time = 0.000001;
 
set log_slow_verbosity = 'explain';
 
 
 
execute stmt;
 
 
 
cat_file $datadir/../mysqld-slow.log;
 

Time                 Id Command    Argument
 
# Time: 131009 20:26:04
 
# User@Host: root[root] @ localhost []
 
# Thread_id: 3  Schema: test  QC_hit: No
 
# Query_time: 0.000262  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0
 
use test;
 
SET timestamp=1381335964;
 
set long_query_time = 0.000001;
 
# User@Host: root[root] @ localhost []
 
# Thread_id: 3  Schema: test  QC_hit: No
 
# Query_time: 0.000324  Lock_time: 0.000000  Rows_sent: 0  Rows_examined: 0
 
SET timestamp=1381335964;
 
set log_slow_verbosity = 'explain';
 
# Time: 131009 20:26:05
 
# User@Host: root[root] @ localhost []
 
# Thread_id: 3  Schema: test  QC_hit: No
 
# Query_time: 1.001381  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0
 
SET timestamp=1381335965;
 
select sleep(1);
 

bzr version-info
 
revision-id: psergey@askmonty.org-20131009090746-6zfqg47elbhnquac
 
revno: 3715
 
branch-nick: 10.0-base-explain-slowquerylog



 Comments   
Comment by Sergei Petrunia [ 2013-10-11 ]

This happens because EXECUTE command and the statement it is executing have
different LEX objects.

=== 1. EXECUTE creates its EXPLAIN data ===
Breakpoint 8, create_explain_query (lex=0xa615558, mem_root=0xa6168e0) at /home/psergey/dev2/10.0-base-explain-slowquerylog/sql/sql_explain.cc:917
(gdb) wher
#0 create_explain_query (lex=0xa615558, mem_root=0xa6168e0) at /home/psergey/dev2/10.0-base-explain-slowquerylog/sql/sql_explain.cc:917
#1 0x00000000006188f4 in mysql_execute_command (thd=0xa6120a0) at /home/psergey/dev2/10.0-base-explain-slowquerylog/sql/sql_parse.cc:2204
#2 0x0000000000622961 in mysql_parse (thd=0xa6120a0, rawbuf=0x7fff300077b8 "execute stmt", length=12, parser_state=0x7fff605ae680) at /home/psergey/dev2/10.0-base-explain-slowquerylog/sql/sql_parse.cc:6019

(gdb) p lex->explain
$81 = (Explain_query *) 0x7fff30007850
(gdb) p lex->explain->have_query_plan()
$82 = false
(gdb) p lex
$83 = (LEX *) 0xa615558

=== 2. The Statement creates its own EXPLAIN data ===
(note that it has its own LEX)
#0 create_explain_query (lex=0x7fff300350b0, mem_root=0xa6168e0) at /home/psergey/dev2/10.0-base-explain-slowquerylog/sql/sql_explain.cc:917
#1 0x00000000006188f4 in mysql_execute_command (thd=0xa6120a0) at /home/psergey/dev2/10.0-base-explain-slowquerylog/sql/sql_parse.cc:2204
#2 0x000000000063a26f in Prepared_statement::execute (this=0x7fff30015520, expanded_query=0x7fff605adc20, open_cursor=false) at /home/psergey/dev2/10.0-base-explain-slowquerylog/sql/sql_prepare.cc:3913
#3 0x00000000006393da in Prepared_statement::execute_loop (this=0x7fff30015520, expanded_query=0x7fff605adc20, open_cursor=false, packet=0x0, packet_end=0x0) at /home/psergey/dev2/10.0-base-explain-slowquerylog/sql/sql_prepare.cc:3572

(gdb) p lex->explain
$84 = (Explain_query *) 0x7fff30007920
(gdb) p lex
$85 = (st_lex_local *) 0x7fff300350b0

=== 3. The Statement deletes its EXPLAIN data ===
Breakpoint 6, delete_explain_query (lex=0x7fff300350b0) at /home/psergey/dev2/10.0-base-explain-slowquerylog/sql/sql_explain.cc:910
(gdb) wher
#0 delete_explain_query (lex=0x7fff300350b0) at /home/psergey/dev2/10.0-base-explain-slowquerylog/sql/sql_explain.cc:910
#1 0x000000000063a323 in Prepared_statement::execute (this=0x7fff30015520, expanded_query=0x7fff605adc20, open_cursor=false) at /home/psergey/dev2/10.0-base-explain-slowquerylog/sql/sql_prepare.cc:3935
#2 0x00000000006393da in Prepared_statement::execute_loop (this=0x7fff30015520, expanded_query=0x7fff605adc20, open_cursor=false, packet=0x0, packet_end=0x0) at /home/psergey/dev2/10.0-base-explain-slowquerylog/sql/sql_prepare.cc:3572
#3 0x00000000006375a9 in mysql_sql_stmt_execute (thd=0xa6120a0) at /home/psergey/dev2/10.0-base-explain-slowquerylog/sql/sql_prepare.cc:2738
#4 0x0000000000618c96 in mysql_execute_command (thd=0xa6120a0) at /home/psergey/dev2/10.0-base-explain-slowquerylog/sql/sql_parse.cc:2305

=== 4. EXECUTE command is in log_slow_statement. It has its EXPLAIN, but it's empty ===
(gdb) wher
#0 log_slow_statement (thd=0xa6120a0) at /home/psergey/dev2/10.0-base-explain-slowquerylog/sql/sql_parse.cc:1546
#1 0x0000000000617464 in dispatch_command (command=COM_QUERY, thd=0xa6120a0, packet=0xa616d51 "", packet_length=12) at /home/psergey/dev2/10.0-base-explain-slowquerylog/sql/sql_parse.cc:1495
#2 0x00000000006154df in do_command (thd=0xa6120a0) at /home/psergey/dev2/10.0-base-explain-slowquerylog/sql/sql_parse.cc:812
#3 0x00000000007276a2 in do_handle_one_connection (thd_arg=0xa6120a0) at /home/psergey/dev2/10.0-base-explain-slowquerylog/sql/sql_connect.cc:1266
#4 0x0000000000727410 in handle_one_connection (arg=0xa6120a0) at /home/psergey/dev2/10.0-base-explain-slowquerylog/sql/sql_connect.cc:1181
#5 0x0000003509c07d90 in start_thread (arg=0x7fff605af700) at pthread_create.c:309
#6 0x00000035098f0f5d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:115
(gdb) p thd
$87 = (THD *) 0xa6120a0
(gdb) p thd->lex
$88 = (LEX *) 0xa615558
(gdb) p thd->lex->explain
$89 = (Explain_query *) 0x7fff30007850
(gdb) p thd->lex->explain->have_query_plan()
$90 = false

Comment by Sergei Petrunia [ 2013-10-11 ]

Note: log_slow_verbosity = 'query_plan' doesn't have such problem. Details like

  1. Full_scan: Yes Full_join: No Tmp_table: No Tmp_table_on_disk: No
  2. Filesort: No Filesort_on_disk: No Merge_passes: 0

are still printed into slow log for EXECUTE.

Generated at Thu Feb 08 07:01:49 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.