[MDEV-5117] Explain for a query executed as a PS is not written into the slow log - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Minor
Resolution: Fixed
Affects Version/s: None
Fix Version/s: 10.0.5
Component/s: None
Labels:
None

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

Attachments

Issue Links

relates to

MDEV-407 Print EXPLAIN [ANALYZE] in the slow query log

Closed

Activity

Ascending order - Click to sort in descending order

Elena Stepanova created issue - 2013-10-09 19:28

Elena Stepanova made changes - 2013-10-09 19:28

Field	Original Value	New Value
Link		This issue relates to TODO-544 [ TODO-544 ]

Elena Stepanova made changes - 2013-10-09 19:28

Link

This issue relates to ~~MDEV-407~~ [ ~~MDEV-407~~ ]

Sergei Petrunia added a comment - 2013-10-11 00:04

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

Sergei Petrunia added a comment - 2013-10-11 00:04 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

Sergei Petrunia added a comment - 2013-10-11 00:09

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

Full_scan: Yes Full_join: No Tmp_table: No Tmp_table_on_disk: No
Filesort: No Filesort_on_disk: No Merge_passes: 0

are still printed into slow log for EXECUTE.

Sergei Petrunia added a comment - 2013-10-11 00:09 Note: log_slow_verbosity = 'query_plan' doesn't have such problem. Details like Full_scan: Yes Full_join: No Tmp_table: No Tmp_table_on_disk: No Filesort: No Filesort_on_disk: No Merge_passes: 0 are still printed into slow log for EXECUTE.

Sergei Petrunia made changes - 2013-10-15 16:21

Resolution		Fixed [ 1 ]
Status	Open [ 1 ]	Closed [ 6 ]

Sergei Golubchik made changes - 2014-06-13 15:06

Workflow

defaullt [ 29243 ]

MariaDB v2 [ 44469 ]

Rasmus Johansson (Inactive) made changes - 2015-05-18 17:50

Workflow

MariaDB v2 [ 44469 ]

MariaDB v3 [ 61577 ]

Sergei Golubchik made changes - 2021-12-06 21:39

Workflow

MariaDB v3 [ 61577 ]

MariaDB v4 [ 147110 ]

People

Assignee:: Sergei Petrunia

Reporter:: Elena Stepanova

Votes:: 0 Vote for this issue

Watchers:: 3 Start watching this issue

Dates

Created:: 2013-10-09 19:28

Updated:: 2013-10-15 16:21

Resolved:: 2013-10-15 16:21

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server

Details

Description

Attachments

Issue Links

Activity

People

Dates

Git Integration