SQL Trace

SQL Trace interactively provides execution information about the previous SQL query, including the time consumed at each stage.

Enable/disable SQL Trace

By default, the SQL Trace function is disabled and can be controlled by session variables.

• Execute this statement to enable SQL Trace:

  obclient>SET ob_enable_trace_log = 1;
  

• Execute this statement to disable SQL Trace:

  obclient>SET ob_enable_trace_log = 0;
  

Show Trace

To diagnose an SQL query, enable the SQL Trace function, execute the SQL query, and run SHOW TRACE to view the execution information, which is displayed in a table. The following table describes each column of the output information:

Example

1. Enable SQL Trace:

   obclient> SET ob_enable_trace_log = 1;
   

2. Execute the SQL query:

   obclient> CREATE TABLE t1(c1 INT,c2 INT,c3 INT);
   Query OK, 0 rows affected (0.02 sec)
   
   obclient> INSERT INTO t1 VALUES(1,1,1);
   Query OK, 1 rows affected (0.02 sec)
   
   obclient> INSERT INTO t1 VALUES(2,2,2);
   Query OK, 1 rows affected (0.02 sec)
   
   obclient>SELECT * FROM t1 WHERE c1 = 1;
   
   +----+------+------+
   | c1 | c2   | c3   |
   +----+------+------+
   |  1 |    1 |    1 |
   +----+------+------+
   

3. Show Trace:

   obclient> SHOW TRACE;
   +------------------------------+---------------------------------------------------------------------------------------------------+
   
   | TITLE | KEYVALUE | TIME |
   +------------------------------+----------------------------------------------------------------------------+------+
   | process begin                | in_queue_time:17, receive_ts:1612420489580707, enqueue_ts:1612420489580709 | 0    |
   | query begin                  | trace_id:YB42AC1E87E6-0005B8AB2D57844F                                     | 1    |
   | parse begin                  | stmt:"set ob_enable_trace_log = 1", stmt_len:27                            | 62   |
   | pc get plan begin            | NULL                                                                       | 9    |
   | start_auto_end_plan end      | NULL                                                                       | 1    |
   | transform_with_outline begin | NULL                                                                       | 1    |
   | transform_with_outline end   | NULL                                                                       | 31   |
   | resolve begin                | NULL                                                                       | 21   |
   | resolve end                  | NULL                                                                       | 33   |
   | execution begin              | arg1:false, end_trans_cb:false                                             | 14   |
   | start_auto_end_plan begin    | NULL                                                                       | 39   |
   | start_auto_end_plan end      | NULL                                                                       | 1    |
   | execution end                | NULL                                                                       | 11   |
   | query end                    | NULL                                                                       | 39   |                                                                                                                                                      
   +------------------------------+---------------------------------------------------------------------------------------------+------+
   

   Description of the result of SHOW TRACE in the example:

   • The TITLE column contains information about all stages of the SQL execution process and the actual execution path. The result shows four stages, Resolve, Transform, Optimizer, and Code Generate. This indicates that the optimizer regenerates a plan for the SQL query and the query did not hit the plan cache.
   • The KEYVALUE column contains some execution information that is useful for troubleshooting:

   • The TIME column shows the time consumption of execution from the last to the current stage point.

     For example, the value 206 μs after resolve end indicates the time consumption from resolve begin to resolve end. Where an SQL query is found to be slow in execution, you can check the Time column and quickly locate the sluggish stage for further analysis. In this example, the generation of the plan takes most of the time. So, you just need to analyze the reason for the cache miss, which may be that the SQL query is executed for the first time after the plan is eliminated, or that the SQL query is not supported by the plan cache.