Versions Compared

Key

  • This line was added.
  • This line was removed.
  • Formatting was changed.
Comment: Published by Scroll Versions from space ML1 and version 9.2

...

Getting EXPLAIN output via profiling

Setting profiling = 1 also records the query plan used to execute EXPLAIN:

Code Block
> SELECT  Concat(LEFT(REPLACE(query.statement, "\n", " "), 50), "...") AS statement, 
          query.program_id, 
          plan.operation, 
          plan.est_cost, 
          plan.est_rows  
from     (select distinct statement.statement, 
          invocation.program_id  
          FROM            system.profiled_statements statement  
          JOIN            system.profiled_invocations invocation  
          ON              invocation.nodeid = statement.nodeid  
          AND             invocation.session_id = statement.session_id  
          AND             invocation.event_id = statement.event_id  
          WHERE           statement.session_id = @@session_id  
          AND             statement.statement LIKE "% test.example JOIN test.example %") query  
JOIN     system.profiled_plans plan 
USING    (program_id)  
ORDER BY query.statement, 
         query.program_id, 
         plan.plan_order;

...

  • This feature is intended for use only at the session level.
  • Setting profiling = 1 can lead to longer runtimes due to the overhead of additional statistics collection. 

...

Let's focus on the query with the JOIN and look more closely at some runtime statistics:

...

Getting EXPLAIN Output

Instead of running EXPLAIN, you can also run the following query to get the EXPLAIN output for a given query.

...

During execution of a profiled invocation, we keep separate stats for every fragment of the query on every CPU used during execution. These measurements are available both during and after execution, via the profiling virtual relation.

system.profiling

system.profiling is profiling is a mapping from (node, CPU, session, transaction, invocation, query fragment) key to corresponding stats counts.

Code Block
> SELECT nodeid, 
         cpu, 
         session_id, 
         xid, 
         iid, 
         fragment, 
         operation_id, 
         replica, 
         fragment_executions, 
         forwards, 
         cpu_runtime_ns, 
         bm_fixes, 
         rows_read, 
         rows_output  
from     system.profiling  
WHERE    iid = 6277791923705589764  
ORDER BY nodeid, 
         cpu, 
         session_id, 
         xid, 
         iid, 
         fragment, 
         operation_id, 
         replica;
 
+--------+-----+------------+---------------------+---------------------+----------+--------------+---------+---------------------+----------+----------------+----------+-----------+-------------+ 
| nodeid | cpu | session_id | xid                 | iid                 | fragment | operation_id | replica | fragment_executions | forwards | cpu_runtime_ns | bm_fixes | rows_read | rows_output | 
+--------+-----+------------+---------------------+---------------------+----------+--------------+---------+---------------------+----------+----------------+----------+-----------+-------------+ 
|      1 |   3 |    3246082 | 6277791923697008644 | 6277791923705589764 |        1 |         NULL |    NULL |                   1 |        1 |              1 |        2 |         1 |           0 |
|      1 |   4 |    3246082 | 6277791923697008644 | 6277791923705589764 |        2 |         NULL |    NULL |                   1 |        0 |              0 |        2 |         1 |           0 |
|      2 |   1 |    3246082 | 6277791923697008644 | 6277791923705589764 |        0 |         NULL |    NULL |                   0 |        0 |              0 |        0 |         0 |           0 |
|      2 |   1 |    3246082 | 6277791923697008644 | 6277791923705589764 |        1 |         NULL |    NULL |                   1 |        1 |              1 |        2 |         1 |           0 |
|      2 |   2 |    3246082 | 6277791923697008644 | 6277791923705589764 |        0 |         NULL |    NULL |                   0 |        0 |              0 |        0 |         0 |           0 |
|      2 |   2 |    3246082 | 6277791923697008644 | 6277791923705589764 |        2 |         NULL |    NULL |                   1 |        0 |              0 |        2 |         1 |           0 |
|      2 |   7 |    3246082 | 6277791923697008644 | 6277791923705589764 |        0 |         NULL |    NULL |                   1 |        3 |              2 |        0 |         0 |           3 |
|      3 |   3 |    3246082 | 6277791923697008644 | 6277791923705589764 |        1 |         NULL |    NULL |                   1 |        1 |              1 |        2 |         1 |           0 |
|      3 |   4 |    3246082 | 6277791923697008644 | 6277791923705589764 |        2 |         NULL |    NULL |                   1 |        0 |              0 |        2 |         1 |           0 |
+--------+-----+------------+---------------------+---------------------+----------+--------------+---------+---------------------+----------+----------------+----------+-----------+-------------+ 
9 rows in set (0.00 sec)

Querying systemQuerying system.profiling will profiling will often require a GROUP BY clauseGROUP BY clause, depending on the dimensions used.

...

In addition to performance measurements, we also keep a history of all profiled invocations in the session. This history includes the statement, plan, and query program for the invocation. The following four vrels are available for use.

profiled_invocations

system.profiled_invocations holds invocations holds a history of every profiled invocation. You will likely join to this table whenever querying multiple profiling vrels.

...

Code Block
> SELECT *   
FROM   system.profiled_statements 
WHERE  session_id = @@session_id 
ORDER  BY event_id; 

+--------+------------+----------+------------------------------------------------------------------------------+---------------------+------------+----------+
| nodeid | session_id | event_id | statement                                                                    | started             | elapsed_ms | finished |
+--------+------------+----------+------------------------------------------------------------------------------+---------------------+------------+----------+
|      2 |    3246082 |        5 | SELECT * FROM test.example                                                   | 2016-04-25 22:07:49 |          8 |        1 |
|      2 |    3246082 |        6 | SELECT COUNT(*) FROM test.example                                            | 2016-04-25 22:07:49 |          2 |        1 |
|      2 |    3246082 |        7 | SELECT COUNT(e) FROM test.example JOIN test.example e2 USING (e) WHERE e > 1 | 2016-04-25 22:07:49 |          4 |        1 |
|      2 |    3246082 |        8 | SET SESSION profiling = 0                                                    | 2016-04-25 22:07:53 |          0 |        1 |
+--------+------------+----------+------------------------------------------------------------------------------+---------------------+------------+----------+
4 rows in set (0.00 sec)

event_id is id is the event ID used by SBR.

...

We also save the plan of each profiled invocation by program ID, so that you don't have to run EXPLAIN for run EXPLAIN for each query. Unlike the other profiling history tables, system system.profiled_plans has multiple rows per history item, one for each row in EXPLAINin EXPLAIN. This makes it easier to join to systemto system.profiling.

Code Block
> SELECT * 
FROM   system.profiled_plans 
WHERE  session_id = @@session_id 
ORDER  BY program_id, 
          plan_order; 

+--------+------------+---------------------+------------+--------------+---------------------------------------------------------------+----------+----------+
| nodeid | session_id | program_id          | plan_order | operation_id | operation                                                     | est_cost | est_rows |
+--------+------------+---------------------+------------+--------------+---------------------------------------------------------------+----------+----------+
|      2 |    3246082 | 6264986681145192450 |          0 |            4 | compute expr0 := param(1)                                     | 0.02     | 0.10     |
|      2 |    3246082 | 6264986681145192450 |          1 |            3 |   row_limit LIMIT := param(0)                                 | 0.02     | 0.10     |
|      2 |    3246082 | 6264986681145192450 |          2 |            2 |     dual                                                      | 0.02     | 1.00     |
|      2 |    3246082 | 6277618985999765506 |          0 |            5 | stream_combine                                                | 13.31    | 1.01     |
|      2 |    3246082 | 6277618985999765506 |          1 |            4 |   index_scan 1 := example.__idx_example__PRIMARY              | 4.07     | 0.34     |
|      2 |    3246082 | 6277618986012650498 |          0 |            8 | row_count "expr1"                                             | 13.43    | 1.00     |
|      2 |    3246082 | 6277618986012650498 |          1 |            7 |   stream_combine                                              | 13.32    | 1.01     |
|      2 |    3246082 | 6277618986012650498 |          2 |            6 |     compute expr0 := param(0)                                 | 4.07     | 0.34     |
|      2 |    3246082 | 6277618986012650498 |          3 |            5 |       index_scan 1 := example.__idx_example__PRIMARY          | 4.07     | 0.34     |
|      2 |    3246082 | 6277618986029830146 |          0 |           17 | row_count "expr0"                                             | 17.88    | 1.00     |
|      2 |    3246082 | 6277618986029830146 |          1 |           16 |   nljoin                                                      | 17.78    | 1.02     |
|      2 |    3246082 | 6277618986029830146 |          2 |           15 |     stream_combine                                            | 13.31    | 1.01     |
|      2 |    3246082 | 6277618986029830146 |          3 |           14 |       index_scan 2 := example.__idx_example__PRIMARY          | 4.07     | 0.34     |
|      2 |    3246082 | 6277618986029830146 |          4 |            9 |     filter (1.e > param(0))                                   | 4.43     | 1.01     |
|      2 |    3246082 | 6277618986029830146 |          5 |            8 |       index_scan 1 := example.__idx_example__PRIMARY, e = 2.e | 4.41     | 1.00     |
+--------+------------+---------------------+------------+--------------+---------------------------------------------------------------+----------+----------+
15 rows in set (0.00 sec)