全链路追踪最佳实践 - OceanBase 最佳实践

全链路追踪最佳实践

更新时间：2026-07-28

适用产品：OceanBase 数据库

适用场景：诊断

全链路顾名思义就是：整个链路，从业务生成 SQL 到 SQL 从数据库执行完返回客户端一整套下来的链路。在分布式架构下，链路较长，问题的分析处理也变得复杂。

本文主要论述如何使用全链路追踪来定位问题，并通过分析问题，进行相应的处理。

在 OceanBase 4.0 之前，可以使用业务 SQL 请求的 trace_id 进行追踪，但是 OBProxy 和 OBServer 记录的不是应用或 SQL 设置的 trace_id，而是各自的内部 trace_id，还需要使用 SQL 语句的特征（比如，主键或者唯一键的值）进行辅助定位。

2.x、3.x 版本全链路追踪介绍

负载均衡层

SLB 问题排查方法

一个 SLB 负载均衡地址后端会挂载多个后端服务地址，快速定位是不是 SLB 这层出问题的办法是绕过 SLB 直连数据库服务器地址进行验证。

例如：A 为负载均衡地址，b、c、d 为后端服务器地址。

正常连接是：app-->A-->（b or c or d）

验证问题：app-->b、app-->c、app-->d 如果连接都没有问题，那说明肯定是负载均衡设备问题。

SLB 常见问题处理

SLB 配置不足

**问题现象：**可能有两类表现。

业务使用负载均衡地址连接 hang。
没有到达连接数上限但是应用报错无法创建连接。此类问题还有可能是 SQL 执行过慢，导致获取连接超时了。

**问题原因：**可能 SLB 配置不足，达到了瓶颈。

处理方法： 扩容。具体操作如下：登录负载均衡设备--> 查看 SLB 配置-->修改配置项增加配置。

**例如：**某客户出现 SLB 连接使用达到 100% 问题，通过流量监控可以发现问题时间点的连接数和流量。查看对应 SLB 配置，显示该 SLB 配置规格为最大支持 5000 连接数，实际上压测阶段已经超过 5000，资源明显不够，需要修改配置进行扩容。

SLB 网络存在问题

**问题现象：**通过负载均衡地址连接 hang 或者直接网络不通。

**问题原因：**可能是防火墙策略、网络路由问题等其他硬件问题。

**处理方法：**排查防火墙策略是否存在端口限制、网络路由是否存在问题，同时检查交换机设备模块是否存在丢包等问题。

流量负载不均衡问题

**问题现象：**不同后端服务流量不一致。

**问题原因：**SLB 负载均衡算法存在一定问题或者业务模型存在问题。

**处理方法：**对于算法问题可以动态调整 SLB 负载均衡算法（推荐最大权重和 hash 算法）找到比较合适的算法，或者联系技术支持人员进行协助处理。

OBProxy 层

OBProxy 只是全链路中的一个组件，在对 OBProxy 进行排查时，需要明确问题的场景，确定排查的方向。

OBProxy 日志是问题诊断的主要信息来源，善于利用 trace_id、session_id、错误码以及 SQL 语句等信息进行日志的搜索。
OCP 监控平台也提供了 OBProxy 的日志检索功能，对于有多个 OBPrxoy 节点的环境特别有用。

在全链路追踪中，对 OBProxy 进行排查首先要确定 OBProxy 实例的地址。在私有云场景，OBProxy 上面往往会有一个负载均衡，应用通常不直接连接 OBProxy 的地址，而是连接一个 VIP。此时，要确定 OBProxy 的地址可以采取以下方法：

在 OceanBase 数据库中通过 sql_audit 查看 client_ip，client_ip 即为 OBProxy 的地址。
查看 LB 的配置情况，确定应用连接对应的 OBProxy 的范围列表。

慢查询诊断

在 obproxy.log 中会记录更详细的 Slow query 和 Slow transaction 日志。我们可以使用 obproxy.log 来查询从 OBProxy 视角统计的 SQL 与交易执行时间，通过对比上游的应用耗时统计，以及下游的 OBServer 的 SQL 和交易的耗时统计，从而得知 SQL 或者交易执行是慢在哪个环节。

要使用的慢查询日志，需要配置相应的 OBProxy 配置项：

slow_query_time_threshold：obproxy_slow.log 的打印阈值，慢查询同时打印到 obproxy.log 日志中。
query_digest_time_threshold：obproxy_digest.log 的打印阈值。
slow_transaction_time_threshold：obproxy.log 的慢事务打印阀值。

OBServer 层

SQL 执行失败如果发生在 OBServer 端，则 OBProxy 以及应用侧均会收到对于的 SQL 错误码，可以根据对应的错误码进行相应的分析处理。

在 OceanBase 数据库中进行问题诊断，根据问题类型的不同，可能会用到分布在不同位置的诊断信息。比如说，应用侧收到的错误码，OCP 监控平台的告警，OBServer 的运行日志，系统监控视图，以及操作系统日志等。

OceanBase 数据库的问题诊断要根据问题发生模块的不同而采用不同的真的方法，详细的诊断方法可参考官网内容问题排查。

4.x 版本全链路追踪介绍

OceanBase 4.x 版本新增全链路追踪 trace，运维人员通过对所有 trace 日志进行搜集分析后，可以追踪每个事务或每个 SQL 在整条链路中的执行耗时等相关信息，以此帮助运维人员定位整条访问链路的问题所在。更多信息可以参见官网链接：《全链路追踪》

4.x 版本使用全链路追踪定位问题示例

在进行 SQL 查询时，发现执行语句的时间过长，通过全链路追踪，来分析对应的原因。

开启 Show Trace 功能。

obclient [testdb]> set ob_enable_show_trace = 'on';

执行以下查询语句。

obclient [testdb]> select * from tp1 where c1 = 938599;

返回结果如下：

+--------+--------+
| c1     | c2     |
+--------+--------+
| 938599 | 518633 |
+--------+--------+
1 row in set (0.481 sec)

通过 Show Trace 语句查看该语句的执行调用链路情况以及链路中各阶段的耗时情况。

obclient [testdb]> Show Trace;

返回结果如下：

+-----------------------------------------------------------+----------------------------+------------+
| Operation                                                 | StartTime                  | ElapseTime |
+-----------------------------------------------------------+----------------------------+------------+
| obclient                                                  | 2023-11-05 19:02:40.723072 | 481.285 ms |
| └── com_query_process                                     | 2023-11-05 19:02:40.723219 | 481.069 ms |
|     └── mpquery_single_stmt                               | 2023-11-05 19:02:40.723225 | 481.057 ms |
|         ├── sql_compile                                   | 2023-11-05 19:02:40.723233 | 2.904 ms   |
|         │   ├── pc_get_plan                               | 2023-11-05 19:02:40.723236 | 0.008 ms   |
|         │   └── hard_parse                                | 2023-11-05 19:02:40.723269 | 2.861 ms   |
|         │       ├── parse                                 | 2023-11-05 19:02:40.723269 | 0.054 ms   |
|         │       ├── resolve                               | 2023-11-05 19:02:40.723338 | 0.187 ms   |
|         │       ├── rewrite                               | 2023-11-05 19:02:40.723556 | 0.342 ms   |
|         │       ├── optimize                              | 2023-11-05 19:02:40.723906 | 2.015 ms   |
|         │       │   ├── inner_execute_read                | 2023-11-05 19:02:40.724391 | 0.126 ms   |
|         │       │   │   ├── sql_compile                   | 2023-11-05 19:02:40.724400 | 0.043 ms   |
|         │       │   │   │   └── pc_get_plan               | 2023-11-05 19:02:40.724402 | 0.023 ms   |
|         │       │   │   ├── open                          | 2023-11-05 19:02:40.724450 | 0.018 ms   |
|         │       │   │   └── do_local_das_task             | 2023-11-05 19:02:40.724485 | 0.016 ms   |
|         │       │   └── close                             | 2023-11-05 19:02:40.724525 | 0.023 ms   |
|         │       │       ├── close_das_task                | 2023-11-05 19:02:40.724526 | 0.005 ms   |
|                 │       └── end_transaction               | 2023-11-05 19:02:40.724539 | 0.003 ms   |
|         │       ├── code_generate                         | 2023-11-05 19:02:40.725930 | 0.092 ms   |
|         │       └── pc_add_plan                           | 2023-11-05 19:02:40.726091 | 0.033 ms   |
|         └── sql_execute                                   | 2023-11-05 19:02:40.726143 | 478.105 ms |
|             ├── open                                      | 2023-11-05 19:02:40.726143 | 0.012 ms   |
|             ├── response_result                           | 2023-11-05 19:02:40.726160 | 477.975 ms |
|             │   └── do_local_das_task                     | 2023-11-05 19:02:40.726165 | 0.078 ms   |
|             └── close                                     | 2023-11-05 19:02:41.204164 | 0.076 ms   |
|                 ├── close_das_task                        | 2023-11-05 19:02:41.204166 | 0.037 ms   |
|                 └── end_transaction                       | 2023-11-05 19:02:41.204227 | 0.004 ms   |
+-----------------------------------------------------------+----------------------------+------------+
27 rows in set

通过上述回显结果，可以分析得出，导致 SQL 语句执行慢的原因是 sql_execute 占用了大量的时间，从而导致查询耗时增加。

查询表 tp1 的结构并分析。

obclient [testdb]> desc tp1;

返回结果如下：

+-------+------------+------+-----+---------+-------+
| Field | Type       | Null | Key | Default | Extra |
+-------+------------+------+-----+---------+-------+
| c1    | bigint(20) | YES  | MUL | NULL    |       |
| c2    | bigint(20) | YES  |     | NULL    |       |
+-------+------------+------+-----+---------+-------+
2 rows in set

通过查询表 tp1 的结构，发现查询字段 c1 上没有创建索引，导致在第 5 步查询时，走的全表扫描，从而使 SQL 语句执行缓慢，因此为表中 c1 字段创建索引。

为测试表创建索引。

obclient [testdb]> create index z on tp1(c1) global;

重新执行上述查询语句。

obclient [testdb]> select * from tp1 where c1 = 938599;

返回结果如下：

+--------+--------+
| c1     | c2     |
+--------+--------+
| 938599 | 518633 |
+--------+--------+
1 row in set (0.006 sec)

通过 Show Trace 语句查看该语句的执行调用链路情况以及链路中各阶段的耗时情况，此时发现查询效率明显提升。

obclient [testdb]> show trace;

返回结果如下：

+-----------------------------------------------+----------------------------+------------+
| Operation                                     | StartTime                  | ElapseTime |
+-----------------------------------------------+----------------------------+------------+
| obclient                                      | 2023-11-05 19:04:02.473941 | 5.719 ms   |
| └── com_query_process                         | 2023-11-05 19:04:02.474078 | 5.517 ms   |
|     └── mpquery_single_stmt                   | 2023-11-05 19:04:02.474082 | 5.507 ms   |
|         ├── sql_compile                       | 2023-11-05 19:04:02.474092 | 4.549 ms   |
|         │   ├── pc_get_plan                   | 2023-11-05 19:04:02.474095 | 0.055 ms   |
|         │   └── hard_parse                    | 2023-11-05 19:04:02.474174 | 4.458 ms   |
|         │       ├── parse                     | 2023-11-05 19:04:02.474175 | 0.056 ms   |
|         │       ├── resolve                   | 2023-11-05 19:04:02.474244 | 0.193 ms   |
|         │       ├── rewrite                   | 2023-11-05 19:04:02.474512 | 0.321 ms   |
|         │       ├── optimize                  | 2023-11-05 19:04:02.474842 | 3.562 ms   |
|         │       ├── code_generate             | 2023-11-05 19:04:02.478417 | 0.094 ms   |
|         │       └── pc_add_plan               | 2023-11-05 19:04:02.478588 | 0.038 ms   |
|         └── sql_execute                       | 2023-11-05 19:04:02.478649 | 0.908 ms   |
|             ├── open                          | 2023-11-05 19:04:02.478650 | 0.019 ms   |
|             ├── response_result               | 2023-11-05 19:04:02.478674 | 0.819 ms   |
|             │   └── do_local_das_task         | 2023-11-05 19:04:02.478687 | 0.364 ms   |
|             └── close                         | 2023-11-05 19:04:02.479500 | 0.051 ms   |
|                 ├── close_das_task            | 2023-11-05 19:04:02.479501 | 0.021 ms   |
|                 └── end_transaction           | 2023-11-05 19:04:02.479541 | 0.003 ms   |
+-----------------------------------------------+----------------------------+------------+
19 rows in set (0.004 sec)

通过上述回显结果与第 3 步的内容对比得出，此时的 sql_execute 的耗时由 478.105 ms 降到了 0.908 ms，很大程度的提高了查询的效率。