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 feature is disabled and can be controlled by session variables.

• Execute the following statement to enable SQL Trace:

  obclient> SET ob_enable_trace_log = 1;
  ``  
  
  
  

• Execute the following statement to disable SQL Trace:

  obclient> SET ob_enable_trace_log = 0;
  

Show Trace

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

Examples

1. Enable SQL Trace:

   obclient> SET ob_enable_trace_log = 1;
   Query OK, 0 rows affected
   

2. Execute the SQL query:

   obclient> CREATE TABLE t1(c1 INT,c2 INT,c3 INT);
   Query OK, 0 rows affected
   
   obclient> INSERT INTO t1 VALUES(1,1,1);
   Query OK, 1 rows affected
   
   obclient> INSERT INTO t1 VALUES(2,2,2);
   Query OK, 1 rows affected
   
   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    |
   | pc get plan end              | NULL                                                                       | 19   |
   | 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   |                                                                                                                                                      
   +------------------------------+---------------------------------------------------------------------------------------------+------+
   

The return result of the SHOW TRACE statement in the example includes the following columns:

• 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 execution information that is useful for troubleshooting:

  • trace_id can be a filter condition in sql_audit to quickly find the SQL execution information. You can also use trace_id to quickly find the relevant OBServer logs.
  • plan_id can be used in v$plan_cache_plan_explain to view the specific execution plan cached in the plan cache.
  • phy_plan_type indicates the type of the execution plan. Specifically, 1 indicates a local plan, 2 indicates a remote plan, and 3 indicates a distributed plan. It is useful for SQL diagnostics.

• The Time column shows the time elapsed from the last to the current stage point.

  If an SQL query is 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 need only 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.