trace log

OceanBase 数据库全链路追踪功能可以记录由客户端到 OBProxy 再到 OBServer 全链路各阶段的耗时及各组件诊断相关的 Trace 信息。其中 Trace Log 记录的最小单元是一个 Span, 每个 Span 可以记录某一个执行区间或模块从开始执行到结束执行的时间以及相关信息(使用 Tags)，来帮助运维人员理解数据库内部的处理逻辑以及定位问题所在。

Span 及 Tag 定义

Span 及 Tag 定义在 ob_trace_def.h 文件中, 分为 HIGH（Level 1）、MIDDLE（Level 2） 和 LOW（level 3） 三个级别，其中 HIGH 是默认设置级别，也就是默认会打印 Level 1 对应的 Span 和 Tag，如果需要打印其他级别的 Span 和 Tag，则需要通过控制命令将 Trace Level 值调高，Level 2 的 Span 可以给用户自己在分析问题时获得更多的 Span 信息，Level 3 Span 主要用于 OceanBase 数据库研发诊断问题时获得更详细的信息；如果设置的 Level 值为 N，则 Trace 会打印 Level <= N 的 Span 和 Tag。

Span 的定义如下：

#define HIGH_LEVEL_SPAN
DEF_SPAN(span_type, comment)
#undef HIGH_LEVEL_SPAN
    
#define MIDDLE_LEVEL_SPAN
DEF_SPAN(span_type, comment)
#undef MIDDLE_LEVEL_SPAN
    
#define LOW_LEVEL_SPAN
DEF_SPAN(span_type, comment)
#undef LOW_LEVEL_SPAN

Tag 的定义如下：

#define HIGH_LEVEL_TAG
DEF_SPAN(tag_type, comment)
#undef HIGH_LEVEL_TAG
    
#define MIDDLE_LEVEL_TAG
DEF_SPAN(tag_type, comment)
#undef MIDDLE_LEVEL_TAG
    
#define LOW_LEVEL_TAG
DEF_SPAN(tag_type, comment)
#undef LOW_LEVEL_TAG

相关 Span 介绍如下：

• com_query_entry：查询过程。

• 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：执行计划过程和结果。

• px_schedule：按照 PX 划分任务。

• px_task：执行 PX 子任务。

• close：关闭执行计划。

• cmd_execute：执行命令。

• cmd_open：启动一次追踪会话的控制命令。

• 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 事务。

相关 Tag 介绍如下：

• com_query_entry

  • log_trace_id：当前请求在 Log 中的 Trace ID。

  • err_code：当前请求的错误代码。

• sql_compile

  • sess_id：Session ID。

  • sql_text：SQL 文本。

  • sql_id：SQL ID。

  • hit_plan：执行计划命中执行计划缓存。

• px_task

  • task_id：并行任务的逻辑 ID。

  • dfo_id：数据流操作 ID。

  • sqc_id：子查询协调器 ID。

  • qc_id：查询协调器 ID。

  • group_id：资源组 ID。

• px_schedule

  • dfo_id：数据流操作 ID。

  • used_worker_cnt：正在使用的 px 工作线程的个数。

  • qc_id：查询协调器 ID。

• ps_close

  • ps_id：Preprocess Statement ID。

Trace Log 示例

运维人员可根据需要，通过使用 PL/SQL 程序包 DBMS_MONITOR 中相关方法，控制相关应用程序不同标识信息维度是否开启全链路追踪 Trace，以及该 Trace 的打点和相关信息打印到 Trace 日志的策略。日志打印会根据采样频率判断是否会被采样并记录到内存中，有一定的概率打印到 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)