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.

The procedure is as follows:

1. Enable SQL Trace.

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

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

      obclient [test]> SET ob_enable_show_trace=ON;
     

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

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

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 [test]> SHOW TRACE;
   +-------------------------------------------+----------------------------+------------+
   | Operation                                 | StartTime                  | ElapseTime |
   +-------------------------------------------+----------------------------+------------+
   | com_query_process                         | 2023-03-22 14:30:27.552259 | 0.405 ms   |
   | └── mpquery_single_stmt             | 2023-03-22 14:30:27.552266 | 0.386 ms   |
   |     ├── sql_compile                 | 2023-03-22 14:30:27.552283 | 0.083 ms   |
   |     │   └── pc_get_plan           | 2023-03-22 14:30:27.552286 | 0.025 ms   |
   |     └── sql_execute                 | 2023-03-22 14:30:27.552379 | 0.242 ms   |
   |         ├── open                    | 2023-03-22 14:30:27.552380 | 0.024 ms   |
   |         ├── response_result         | 2023-03-22 14:30:27.552417 | 0.140 ms   |
   |         │   ├── get_das_id        | 2023-03-22 14:30:27.552421 | 0.000 ms   |
   |         │   └── do_local_das_task | 2023-03-22 14:30:27.552435 | 0.049 ms   |
   |         └── close                   | 2023-03-22 14:30:27.552570 | 0.039 ms   |
   |             ├── close_das_task      | 2023-03-22 14:30:27.552571 | 0.012 ms   |
   |             └── end_transaction     | 2023-03-22 14:30:27.552596 | 0.003 ms   |
   +-------------------------------------------+----------------------------+------------+
   12 rows in set (0.006 sec)
   

   The ElapseTime field indicates the time currently consumed for this step, in milliseconds. For example, if the ElapseTime field of the pc_get_plan step is 0.025 ms, it indicates that OceanBase Database takes 0.025 ms to obtain an execution plan from the plan cache. The following part describes common operations. For more information about operation types, see the Spans section in End-to-end process.

   • com_query_process: the query process.

   • mpquery_single_stmt: the access path of a single statement.

   • sql_compile: specifies to compile an SQL statement.

   • pc_get_plan: specifies to obtain an execution plan.

   • hard_parse: hard parsing.

   • parse: soft parsing.

   • resolve: specifies to parse the semantics of the syntax tree and generate a statement.

   • rewrite: specifies to rewrite an SQL statement.

   • optimize: specifies to perform cost-based optimization and generate execution plan logs.

   • code_generate: specifies to generate a physical execution plan based on the execution plan logs.

   • pc_add_plan: specifies to add the generated execution plan to the plan cache.

   • sql_execute: specifies to execute the physical execution plan.

   • open: specifies to open the execution plan.

   • response_result: the procedure and result of the execution plan.

   • get_das_id: specifies to obtain the ID of the DAS task.

   • do_local_das_task: specifies to execute the local DAS task.

   • px_schedule: specifies to schedule tasks based on parallel execution (PX).

   • px_task: specifies to execute PX subtasks.

   • close: specifies to close the execution plan.

   • close_das_task: specifies to close the DAS task.

   • end_transaction: specifies to end the transaction.

   • cmd_execute: specifies to execute the command.

   • cmd_open: specifies to enable the cmd plan.

   • ps_prepare: specifies to prepare the preprocess statement.

   • ps_execute: specifies to execute the preprocess statement.

   • ps_close: specifies to close the preprocess statement.

   • pl_entry: specifies to process the stored procedure.

   • pl_compile: specifies to compile the stored procedure object.

   • pc_get_pl_object: specifies to obtain the stored procedure object from the plan cache.

   • pc_add_pl_object: specifies to store the stored procedure object in the plan cache.

   • pl_execute: specifies to execute the stored procedure.

   • pl_spi_query: specifies to execute the SPI statement in the stored procedure.

   • pl_spi_prepare: the preprocessing phase of stored procedures.

   • pl_spi_execute: specifies to execute the SPI statement in the stored procedure.

   • inner_prepare: the preprocessing phase of internal SQL statements.

   • inner_execute: the execution phase of internal SQL statements.

   • inner_execute_read: specifies to read internal SQL requests.

   • inner_execute_write: specifies to write internal SQL requests.

   • inner_commit: specifies to commit an internal SQL transaction.

   • inner_rollback: specifies to roll back an internal SQL transaction.

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.

   1. Obtain the trace_id value by using last_trace_id().

      obclient [test]> SELECT last_trace_id() FROM DUAL;
      +-----------------------------------+
      | last_trace_id()                   |
      +-----------------------------------+
      | YB42AC1E87CC-0005F6BFDB3E2199-0-0 |
      +-----------------------------------+
      1 row in set (0.000 sec)
      

   2. Log on to the corresponding OBServer node and go to the directory where the log file is located.

      cd /home/admin/oceanbase/log
      

   3. Obtain the logs corresponding to the trace_id value and run the grep $trace_id observer.log command. For example, to obtain the log whose trace_id is YB42AC1E87CC-0005F6BFDB3E2199-0-0, run the following command:

      grep YB42AC1E87CC-0005F6BFDB3E2199-0-0  observer.log
      [2023-03-22 14:30:33.124342] [38419][T1_L0_G0][T1][YB42AC1E87CC-0005F6BFDB3E2199-0-0] {"trace_id":"0005f777-4c14-595f-508c-6681b3dac7c9","name":"pc_get_plan","id":"0005f777-4c14-59f1-5c54-a90e3ff82e85","start_ts":1679466633124337,"end_ts":1679466633124340,"parent_id":"0005f777-4c14-59ef-de27-961b48ecfdfd","is_follow":false}