基于 Trace 功能查找上一次 SQL 请求日志

OceanBase 数据库支持基于 Trace 功能快速获取上一次 SQL 请求的完整日志。

为了便于查找目标 SQL 请求日志，您可提前通过设置日志打印级别来减少 SQL 模块之外的日志的打印。有关日志打印级别的相关设置请参见 设置日志打印级别。

具体操作步骤如下：

1. 开启 Trace 功能。

   可通过如下两种方式来开启 Trace 功能：

   • 通过设置 Session 变量 ob_enable_show_trace 来开启 Trace 功能。这种方式对本 Session 的后续所有语句生效。

      obclient [test]> SET ob_enable_show_trace=ON;
     

   • 通过设置 Hint 中的 trace_log 字段来开启 Trace 功能。这种方式只对携带 Hint 的当前语句生效。更多 Hint 语句相关的介绍，请参见 Optimizer Hint。

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

2. 使用 SHOW TRACE 查看 SQL 的执行信息。

   开启 Trace 功能并执行 SQL 请求后，通过 SHOW TRACE 语句可获取上一次 SQL 语句的详细执行跟踪信息。

   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)
   

   ElapseTime 字段表示当前该步骤花费的时间，单位是毫秒。例如： pc_get_plan 的 ElapseTime 字段显示为 0.025 ms，表示 OceanBase 数据库从 Plan Cache 中获取一条执行计划花费了 0.025 ms。 常见相关 Operation 介绍如下，更多 Operation 类型请参见 全链路追踪流程 中的 span。

   • com_query_process：查询过程。

   • mpquery_single_stmt：单个语句的访问路径。

   • sql_compile：编译 SQL。

   • pc_get_plan：获取执行计划。

   • hard_parse： 硬解析。

   • parse：软解析。

   • resolve：解析语法树的语义并生成语句。

   • rewrite：重写 SQL。

   • optimize：进行基于成本的优化并生成执行计划日志。

   • code_generate：根据执行计划日志生成物理执行计划。

   • pc_add_plan：将生成的执行计划加入 plan cache。

   • sql_execute：执行物理执行计划。

   • open：打开执行计划。

   • response_result：执行计划过程和结果。

   • get_das_id：获取 das 任务 ID。

   • do_local_das_task：执行本地 das 任务。

   • px_schedule：按照 px 划分任务。

   • px_task：执行 px 子任务。

   • close：关闭执行计划。

   • close_das_task：关闭 das 任务。

   • end_transaction：结束事务。

   • cmd_execute：执行命令。

   • cmd_open：开启 cmd 计划。

   • ps_prepare：preprocess statement 的预处理。

   • ps_execute：preprocess statement 的执行。

   • ps_close：关闭 preprocess statement。

   • pl_entry：存储过程处理。

   • pl_compile：编译存储过程对象。

   • pc_get_pl_object：从 plan cache 获取存储过程对象。

   • pc_add_pl_object：把存储过程对象存储在 plan cache。

   • pl_execute：执行存储过程。

   • pl_spi_query：执行存储过程中的 spi 语句。

   • pl_spi_prepare：存储过程预处理阶段。

   • pl_spi_execute：执行存储过程中的 spi 语句。

   • inner_prepare：内部 SQL 的预处理阶段。

   • inner_execute：内部 SQL 的执行阶段。

   • inner_execute_read：读内部 SQL。

   • inner_execute_write：写内部 SQL。

   • inner_commit：提交内部 SQL 事务。

   • inner_rollback：回滚内部 SQL 事务。

3. 通过 trace_id 在日志文件查询上一次 SQL 请求的完整日志。

   OceanBase 数据库日志打印时均会携带 trace_id，通过在日志文件（ observer.log、election.log 和 rootservice.log ）中搜索对应的 trace_id，可以获取上一次 SQL 请求的完整日志。

   1. 通过 last_trace_id() 获取 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. 登录对应 OBServer 节点，进入到日志文件所在目录。

      cd /home/admin/oceanbase/log
      

   3. 获取 trace_id 所对应的日志，执行 grep $trace_id observer.log 命令，例如：获取 trace_id 为 YB42AC1E87CC-0005F6BFDB3E2199-0-0 的日志。

      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}