[MDEV-407] Print EXPLAIN [ANALYZE] in the slow query log Created: 2012-07-20  Updated: 2014-06-25  Resolved: 2013-11-12

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

Type: Task Priority: Major
Reporter: Sergei Petrunia Assignee: Sergei Petrunia
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Blocks
is blocked by MDEV-3798 Add EXPLAIN for UPDATE/DELETE (mwl #51) Closed
Relates
relates to MDEV-5045 Server crashes in QPF_query::print_ex... Closed
relates to MDEV-5060 Server crashes on EXPLAIN EXTENDED or... Closed
relates to MDEV-5067 Valgrind warnings (Invalid read) in Q... Closed
relates to MDEV-5106 Server crashes in Explain_union::prin... Closed
relates to MDEV-5117 Explain for a query executed as a PS ... Closed
relates to MDEV-5118 Explain output for SHOW EXPLAIN in th... Open
relates to MDEV-5125 Test sys_vars.log_slow_verbosity_basi... Closed
relates to MDEV-6388 ANALYZE $stmt output in the slow quer... Closed
relates to MDEV-406 ANALYZE $stmt Closed

 Description   

SHOW EXPLAIN allows to produce EXPLAIN during the query execution. We are now able to save it in the slow query log.

The user interface is as follows:

"explain" is a new flag in log-slow-verbosity argument:

[mysqld]
 
...
 
log-slow-verbosity=query_plan,explain

The output is printed into slow query log like this:

# User@Host: root[root] @ localhost []
 
# Thread_id: 2  Schema: j4  QC_hit: No
 
# Query_time: 0.000629  Lock_time: 0.000202  Rows_sent: 3  Rows_examined: 3
 
# Full_scan: Yes  Full_join: No  Tmp_table: No  Tmp_table_on_disk: No
 
# Filesort: No  Filesort_on_disk: No  Merge_passes: 0
 
## <explain>
 
##   id select_type     table   type    possible_keys   key     key_len ref     rows    Extra
 
##   1  SIMPLE  t1      ALL     NULL    NULL    NULL    NULL    3       Using where
 
## </explain>
 
SET timestamp=1381828772;
 
select * from t1 where a between 1 and 3333;



 Comments   
Comment by Sergei Petrunia [ 2013-09-18 ]

Stack trace of where currently "query plan" information is written into the query log:

#0 MYSQL_QUERY_LOG::write
#1 0x00000000008a87b9 in Log_to_file_event_handler::log_slow
#2 0x00000000008a91c5 in LOGGER::slow_log_print
#3 0x00000000008b4b9f in slow_log_print
#4 0x00000000006168d9 in log_slow_statement
#5 0x0000000000616594 in dispatch_command
#6 0x000000000061460f in do_command

Comment by Sergei Petrunia [ 2013-09-19 ]

The first patch is at lp:~maria-captains/maria/10.0-base-explain-slowquerylog

Comment by Sergei Petrunia [ 2013-09-20 ]

Currently, EXPLAIN is only printed into the slow query log file. If the slow query log is directed to the table ( --log-output=TABLE --slow-query-log), then the EXPLAIN is not captured. This is the same as with log-slow-verbosity=query_plan.

Comment by Sergei Petrunia [ 2013-11-12 ]

Changed formatting based on the input from the mailing list.

Comment by Sergei Petrunia [ 2013-11-12 ]

The code is in 10.0-base and 10.0 trees.

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