test=# explain select count from one_k where ones < 10;
QUERY PLAN
-------------------------------------------------------------
Aggregate (cost=17.53..17.54 rows=1 width=0)
-> Seq Scan on one_k (cost=0.00..17.50 rows=11 width=0)
Filter: (ones < 10)
(3 rows)

test=# explain analyze select count from one_k where ones < 10;
QUERY PLAN
--------------------------------------------------------------------------------------------------------
Aggregate (cost=17.53..17.54 rows=1 width=0) (actual time=1.449..1.451 rows=1 loops=1)
-> Seq Scan on one_k (cost=0.00..17.50 rows=11 width=0) (actual time=0.037..1.406 rows=10 loops=1)
Filter: (ones < 10)
Total runtime: 1.560 ms
(4 rows)

^^ Example from PostgreSQL

When we have SHOW EXPLAIN, the natural way to save JOIN's plan is to produce a part of EXPLAIN output that describes the join.
The problem is, JOINs are optimized/executed in arbitrary order, and we want EXPLAIN ANALYZE to output to list joins in the same order EXPLAIN would list them (or at least in similar order, with "parents before children" etc).

This means, we need to save what JOIN::print_explain has produced, and then replay it back.

The code has Protocol_local, however

• that code was added by Kostja when he was backporting something from Online Backup code, and "SP OUT parameters"
• currently the code is not used ( running a testsuite with DBUG_ASSERT(0) in Protocol_local::Protocol_local doesn't produce anythting)
• When I read the code, I see Protocol_local::store_XXX() methods, which seem to store various types in internal buffers in a certain data format. However, I dont see any code that would try to read the stored data back!

Another possible option is to use select_result_explain_buffer from the pre-review SHOW EXPLAIN code. However, that buffer relies on class Protocol to serialize the data

.. which is ok, because the real select output is suppressed, so EXPLAIN ANALYZE can use thd->protocol for its own purposes.

Additional notes from discussion with igor:

It would be nice to show the amounts of time spent accessing the tables.

• P_S code has the functionality to do it.
• Reusing P_S code is not straightforward
  • In P_S, each table has one counter. We need one counter per table use (this is also referred to as "Self-join problem")
  • What if ANALYZE EXPLAIN is run while P_S is disabled? (or the needed instruments are disabled?) It could switch the instruments ON for the duration of the query but this could be an unpleasant surprise for those who are doing system-wide collection.

So,

• it's better to know table access times
• however, tracking this will add a cost.

I would also argue that the most frequent case is the one where we have log_slow_verbosity=explain. In this case, we don't want to add overhead to every query. At the same time, we want EXPLAIN ANALYZE output in the slow query log. This means, we need a way to run EXPLAIN ANALYZE without overhead.

Notes from discussion with serg and elenst.

Instead of "EXPLAIN ANALYZE $CMD" syntax, we will use "ANALYZE $cmd". "ANALYZE $cmd" will run the command (e.g. ANALYZE UPDATE will do the updates (checked: PG's EXPLAIN ANALYZE DELETE" will do deletes)), but produce output of "EXPLAIN $cmd", amended with information about actual execution.

Notes from discussion with igor: It would be nice to count the number of disk io caused by each table. (counting time is even nicer but may cause overhead).

Tasks

1. Get ANALYZE working for tabular EXPLAIN format
1.1 Adjust the SQL parser
1.2 Add new columns (r_rows, r_filtered)
1.2 Make UPDATE/DELETE collect and print ANALYZE data
1.3 Make SELECT collect and print ANALYZE

After the above, we will have ANALYZE counterpart for the information that we've had in the tabular form of EXPLAIN output.

2. Extras in the tabular form
2.1 One item so far: "Using index condition (X%)"

3. Support ANALYZE FORMAT=JSON and print more data
3.1 Support ANALYZE FORMAT=JSON
3.2 Add more execution data
3.2.1 Join buffer reads
3.2.2 BKA buffer refills
3.2.3 Disk page reads
3.4.4 etc

Got basic things to work.

The design is as follows:

• Query plan (aka EXPLAIN data structures) include counters.
• Execution code increments them
• After the query is finished, we can print them.

Hit a problem (the example I am looking at is one with subquery, but one could probably hit it without it also).

Currently, [SHOW] EXPLAIN code does:

join->optimize()

join->save_explain_plan()   // (1)

join->exec()

join->save_explain_plan()   // (2)

The need to for call (2) was that because JOIN::exec() mades some last-minute changes to the query plan. I've tried to pull them out and put into JOIN::optimize() when working on SHOW EXPLAIN, but hit a problem that these changes are all over JOIN::exec().

For SHOW EXPLAIN, we could store these last-minute choices with the call (2).

Howeve, call (2) has disastrous consequences for ANALYZE. It overwrites the query plan and destroys the counter values.

So, I removed the call (2). I went through the known last-minute changes in the query plan (made by ORDER/GROUP BY optimizer), and added a call which saves just the changed info.

Running tests after that has shown that there is another gotcha - INFORMATION_SCHEMA. For some reason, a part of I_S optimizations is made very late, right in JOIN::exec(). When we're running EXPLAIN, it goes into JOIN::exec, goes into ##get_all_tables()##, and then that function has " if (lex->describe)

# in the middle of it.

Apparently, there is no way to get the right query plan early in the current code.

Possible options:

• move a part of get_all_tables() into JOIN::optimize.
• put another "modify the query plan" call into get_all_tables().

get_all_tables() is poorly written. It runs make_cond_for_info_schema(). That is, if we have a query like

select 

  col1,  

  (select ... from I_S.columns 

  where non_frm_cond AND frm_cond AND correlation_cond) 

from

  big_table

then each subquery execution will call get_all_tables which will call make_cond_for_info_schema, and in the end we will allocate O(#rows(big_table)) of Item_cond_and objects. Saw it myself in debugger.

As MySQL 5.6:

• they did some work with moving ORDER BY out of JOIN::exec() and into JOIN::optimize() AFAIU
• however, they didn't move I_S optimization. They have JOIN::explain() which is an EXPLAIN-counterpart of JOIN::exec().

Another issue I'm facing after I've removed the second save_explain_data() call
is this:

 EXPLAIN EXTENDED DELETE v1 FROM t2, v1 WHERE t2.x = v1.a;

 id     select_type     table   type    possible_keys   key     key_len ref     rows    filtered        Extra

 1      SIMPLE  t2      ALL     NULL    NULL    NULL    NULL    4       100.00  Using where

-1      SIMPLE  t1      eq_ref  PRIMARY PRIMARY 4       test.t2.x       1       100.00

+1      SIMPLE  v1      eq_ref  PRIMARY PRIMARY 4       test.t2.x       1       100.00

VIEW's name is displayed instead of table name. It happens only on EXPLAIN
DELETE (SELECTs are ok).

Debugging how it worked in 10.0 with the second save_explain_data() call, I see that it worked in an unacceptable way:

* JOIN::prepare() is run for the parent select

* JOIN::optimize() is run for the parent select (the child is merged)

* query plan is saved.  table->pos_in_table_list->alias == "v1"

* JOIN::exec() is called for the parent select

  * it calls select_describe()

    * which calls mysql_explain_union() for children

      * which runs JOIN::prepare, optimize, etc. for the view (select_number=2)

        this has an effect of putting back table->pos_in_table_list

        to point to "t1" but apparently it's not an acceptable solution.

Checking why EXPLAIN DELETE is affected and EXPLAIN SELECT is not...

It turns out, there is a special kind of early merge, DT_MERGE_FOR_INSERT, which is also used for multi-table DELETEs. The view is merged here:

  #0  mysql_derived_merge_for_insert (

  #1  0x00000000006320bb in mysql_handle_derived (lex=0x7fffd1b66cb0, phases=16) at /home/psergey/dev-git/10.1-explain-analyze/sql/sql_derived.cc:118

  #2  0x00000000009b0c24 in mysql_multi_delete_prepare (

  #3  0x000000000065d267 in mysql_execute_command (

  #4  0x0000000000664fe7 in mysql_parse (

and when regular SELECT handling tries to merge it, it's already merged.

A distinguishing case: view's TABLE_LIST has t->merged_for_insert=TRUE.

Fixed the problem with I_S by splitting get_all_tables() into the optimizer part and executor part.

Fixed the problem with order_by.test (it was a trivial bug).
Discussed "EXPLAIN UPDATE shows VIEW names" problem with Sanja

Merged with 10.1

As for "EXPLAIN UPDATE shows VIEW names":

• In EXPLAIN output, tables from views show their aliases inside the VIEWs (as expected).

In MySQL 5.6, they don't have table->pos_in_table_list->alias == v1. instead, they have table->pos_in_table_list->alias=t1. Grepping the source code for DT_MERGE_FOR_INSERT (or for DT_MERGE or related terms) finds nothing, so I assume they have re-worked derived table merge algorithm and so do not have this "special kind of merge" problem.

Functionality intended for 10.1.0 has been pushed.