Query the log of a previous SQL request by using the SQL Trace feature

OceanBase Database allows you to query the complete log of a previous SQL request by using the SQL Trace feature.

To facilitate log query, you can set a log generation level in advance to reduce the number of logs generated in different modules except for the SQL module. For more information about how to set a log generation level, see Set a log generation level.

Procedure:

1. Enable SQL Trace.

   You can enable SQL Trace by using one of the following methods:

   • Set the trace_log field in hints. This setting takes effect only for the current statement that carries the hint. For more information about hints, see Optimizer hints in OceanBase Database SQL Tuning Guide.

     obclient > SELECT /*+trace_log=on*/c1 FROM t1 LIMIT 2;
     

   • Set the session variable ob_enable_trace_log. This setting takes effect for all subsequent statements of the current session.

     obclient > SET ob_enable_trace_log='ON';
     

2. Obtain the trace_id value of the log of the required SQL request.

   After you enable SQL Trace and execute an SQL request, you can use the SHOW TRACE statement to obtain the trace_id value of the log of the SQL request.

   obclient> SHOW TRACE;
   +------------------------------+----------------------------------------------------------------------------+------+
   | Title                        | KeyValue                                                                   | Time |
   +------------------------------+----------------------------------------------------------------------------+------+
   | process begin                | in_queue_time:12, receive_ts:1623988240448815, enqueue_ts:1623988240448816 | 0    |
   | query begin                  | trace_id:YC1E64586A5D-0005C4C77E56FA98                                     | 2    |
   | parse begin                  | stmt:"select count(*) from t1", stmt_len:23                                | 49   |
   | pc get plan begin            |                                                                            | 7    |
   | pc get plan end              |                                                                            | 18   |
   | transform_with_outline begin |                                                                            | 2    |
   | transform_with_outline end   |                                                                            | 45   |
   | resolve begin                |                                                                            | 22   |
   | resolve end                  |                                                                            | 130  |
   | transform begin              |                                                                            | 40   |
   | transform end                |                                                                            | 138  |
   | optimizer begin              |                                                                            | 2    |
   | get location cache begin     |                                                                            | 96   |
   | get location cache end       |                                                                            | 108  |
   | optimizer end                |                                                                            | 272  |
   | cg begin                     |                                                                            | 0    |
   | cg end                       |                                                                            | 984  |
   | execution begin              | arg1:false, end_trans_cb:false                                             | 78   |
   | do open plan begin           | plan_id:197                                                                | 29   |
   | sql start stmt begin         |                                                                            | 1    |
   | sql start stmt end           |                                                                            | 1    |
   | execute plan begin           |                                                                            | 0    |
   | execute plan end             |                                                                            | 9    |
   | sql start participant begin  |                                                                            | 0    |
   | sql start participant end    |                                                                            | 1    |
   | do open plan end             |                                                                            | 0    |
   | table scan begin             |                                                                            | 11   |
   | table scan end               |                                                                            | 42   |
   | start_close_plan begin       |                                                                            | 1344 |
   | start_end_participant begin  |                                                                            | 13   |
   | start_end_participant end    |                                                                            | 1    |
   | start_close_plan end         |                                                                            | 1    |
   | start_auto_end_plan begin    |                                                                            | 2    |
   | start_auto_end_plan end      |                                                                            | 1    |
   | execution end                |                                                                            | 2    |
   | query end                    |                                                                            | 52   |
   | NULL                         | PHY_SCALAR_AGGREGATE                                                       |      |
   | t1                           |  PHY_TABLE_SCAN                                                            |      |
   +------------------------------+----------------------------------------------------------------------------+------+
   38 rows in set (0.01 sec)
   

   The Time field indicates the amount of time consumed by the current step, in microseconds. For example, the value of the Time field for pc get plan end is 18, in µs, which means OceanBase Database spends 18 μs obtaining the relevant execution plan from the plan cache.

3. Query the complete log of the SQL request in the log files by using trace_id.

   OceanBase Database assigns a trace_id value to each generated log. You can search for the trace_id value in the log files (observer.log, election.log, and rootservice.log) to obtain the complete log of the required SQL request.

   grep $trace_id observer.log
   

   Here is an example about how to obtain the log with a trace_id value of YB42AC1E87ED-0005C6866C3BAFB1-0-0:

   grep YB42AC1E87ED-0005C6866C3BAFB1-0-0 observer.log
   observer.log: [2021-07-15 14:05:11.218141] WARN  [SQL] execute_get_plan (ob_sql.cpp:3159) [119331][0][YB42AC1E87ED-0005C6866C3BAFB1-0-0] [lt=5] [dc=0] fail to get plan retry(ret=-5138)