Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-5117

Explain for a query executed as a PS is not written into the slow log

        Details

        • Type: Bug
        • Status: Closed
        • 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

            Gliffy Diagrams

              Attachments

                Issue Links

                relates to

                Task - A task that needs to be done. MDEV-407 Print EXPLAIN [ANALYZE] in the slow query log

                • Major - Major loss of function.
                • Closed

                  Activity

                  Ascending order - Click to sort in descending order
                  Hide
                  Permalink
                  psergey Sergei Petrunia added a comment -

                  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

                  Show
                  psergey Sergei Petrunia added a comment - 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
                  Hide
                  Permalink
                  psergey Sergei Petrunia added a comment -

                  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.

                  Show
                  psergey Sergei Petrunia added a comment - 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.

                    People

                    • Assignee:
                      psergey Sergei Petrunia
                      Reporter:
                      elenst Elena Stepanova
                    • Votes:
                      0 Vote for this issue
                      Watchers:
                      2 Start watching this issue

                      Dates

                      • Created:
                        Updated:
                        Resolved: