OceanBase V4.2特性解析：用 Show Trace 快速定位数据库性能瓶颈

在数据库日常运维中，当遇到慢SQL问题时，若无法迅速查明原因，将极大地影响用户的使用感受，甚至可能引发业务或服务的中断。相较于单机数据库，分布式数据库系统因其涉及多个节点和多组件的协同工作，集群规模可能达到至数十甚至上百台服务器，使得用户请求的处理链路变得更为复杂。因此，快速高效地诊断和定位问题变得更具挑战性。

OceanBase 4.2 在诊断能力方面有了显著提升，包括实现对 SQL 请求的可视化全链路追踪，能够帮助用户快速追踪并定位具体问题发生在哪个执行阶段、哪台机器以及哪个模块，并提供具体的相关执行信息，为用户提供简单、高效的运维体验。​​​​​​​

Show Trace的关键能力有哪些？

事务 + SQL 维度的Show Trace

OceanBase 提供了面向用户的事务 + SQL 维度的Show Trace能力。通常，业务部门更关心一笔业务的服务总耗时。例如，在 OLTP 系统中，一笔业务服务一般由一个或多个事务组成，因此，把事务作为追踪单位会更贴合用户的实际业务。一个事务形成一个Trace，并对事务中每条 SQL 请求记录从 OBClient到OBProxy 再到 OBServer 的全链路执行信息。用户可以通过一个 Trace 快速找到该事务执行了哪些语句，以及这些语句从客户端视角看到的执行情况。

在实际业务中，一旦用户发现有慢的 SQL 请求，或者存在某个慢的事务，可以从慢 SQL 的整个执行链路中快速定位是哪个执行阶段慢。又或者在某个事务中，如果发现一个 SQL 结束到另一个 SQL 再发起之间的时间较长，则可请业务同学查看业务逻辑侧可能存在的问题。

图1 事务中SQL调用过程图

支持分布式环境下的Show Trace

OceanBase 支持分布式环境下的Show Trace能力。首先，OceanBase 作为一个分布式系统，当 OBProxy 接收到一个客户端请求后，有可能会将其路由到 OBServer 集群中任意一台 OBbServer 上。同时，该请求涉及的数据可能分布在不同的 OBServer 中。具体到 SQL 执行阶段，执行引擎会向不同的 OBServer 发送执行子任务，当 OBServer 数量很多时，这些 SQL 请求和 Task 具体是在哪个 Server上执行？Server 内具体各模块执行的耗时情况是怎样的？都会困扰运维人员。

Show Trace实现了 SQL 请求在分布式场景下，涉及多 Server 时完整执行链路的追踪。用户能够直观地看到是哪个 OBServer 上接收请求，哪个 OBServer 上执行远程 task，每个 task 的调度情况，以及执行耗时等信息。

图2 分布式请求执行过程图

提供便捷的业务系统关联能力

在实际业务中，不少用户都会建立自己的监控及诊断系统。当数据库发生请求调用慢或报错时，用户可能需要系统快速关联到数据库对应的某个 SQL 诊断，进一步缩短从发现问题到解决问题的耗时。Show Trace可以为用户提供便捷的业务系统关联能力，用户通过 JDBC 接口/SQL 接口，能够在业务数据库连接上设置调用请求对应的 app trace id, 该 app trace id 会记录到 OceanBase 全链路追踪对应的信息中, 并在Show Trace中展示出来。

当用户发现某个 app trace id 对应的请求或服务数据库调用有报错时, 可以使用该 app trace id 在全链路诊断系统中快速搜索到对应的 app trace id 关联的数据库 Trace，然后直接查看该请求在数据库链路中各阶段耗时情况及报错点，快速确定触发问题的组件。

多种Show Trace信息展示方式

用户通过 OceanBase 运维平台（OCP），可以通过不同维度快速检索到有问题的请求，比如按耗时检索, 按指定 Trace id 或者SQL ID检索等, 并且直观的看到请求从客户端到数据库内部全链路各组件的执行信息, 方便快速定位出问题的阶段。

图3 OCP平台展示效果图

此外，用户还可以通过 OceanBase 开发者中心（ODC），执行语句后，查看执行详情，即可以详细地看到本次请求执行的状态。这样，我们可以直观地看到请求从客户端到数据库内部的执行情况，快速看到当前的瓶颈点在何处。

图4 ODC效果展示图

最后，用户可以在 OceanBase 新版本的交互场景使用Show Trace能力，用户在命令行中手动执行某一个语句后，如果想分析该语句的执行调用链路情况，以及链路中各阶段耗时情况，以便进行性能分析或调优，可以使用 Show Trace 功能便捷地找到性能瓶颈点。如下所示，我们可以通过直接使用Show Trace命令，看到两个分布式并行执行任务(px_task) 的执行情况。另一方面，也可以通过 Show Trace 的JSON展示版来显示更多明细信息。获取到明细信息后，我们用obdiag工具展示show trace信息。

OceanBase(admin@test)>select/*+parallel(2)*/ count(*) from t1;
 +----------+
 | count(*) |
 +----------+
 |        5 |
 +----------+
 1 row in set (0.005 sec)
 
 OceanBase(admin@test)>show trace;
 +-------------------------------------------+----------------------------+------------+
 | Operation                                 | StartTime                  | ElapseTime |
 +-------------------------------------------+----------------------------+------------+
 | obclient                                  | 2023-03-01 17:51:30.143537 | 4.667 ms   |
 | └─ ob_proxy                               | 2023-03-01 17:51:30.143716 | 4.301 ms   |
 |    └─ com_query_process                   | 2023-03-01 17:51:30.145119 | 2.527 ms   |
 |       └─ mpquery_single_stmt              | 2023-03-01 17:51:30.145123 | 2.513 ms   |
 |          ├─ sql_compile                   | 2023-03-01 17:51:30.145133 | 0.107 ms   |
 |          │  └─ pc_get_plan                | 2023-03-01 17:51:30.145135 | 0.061 ms   |
 |          └─ sql_execute                   | 2023-03-01 17:51:30.145252 | 2.350 ms   |
 |             ├─ open                       | 2023-03-01 17:51:30.145252 | 0.073 ms   |
 |             ├─ response_result            | 2023-03-01 17:51:30.145339 | 2.186 ms   |
 |             │  ├─ px_schedule             | 2023-03-01 17:51:30.145342 | 1.245 ms   |
 |             │  │  ├─ px_task              | 2023-03-01 17:51:30.146391 | 1.113 ms   |
 |             │  │  │  ├─ get_das_id        | 2023-03-01 17:51:30.146979 | 0.001 ms   |
 |             │  │  │  ├─ do_local_das_task | 2023-03-01 17:51:30.147012 | 0.050 ms   |
 |             │  │  │  └─ close_das_task    | 2023-03-01 17:51:30.147237 | 0.014 ms   |
 |             │  │  └─ px_task              | 2023-03-01 17:51:30.146399 | 0.868 ms   |
 |             │  │     ├─ get_das_id        | 2023-03-01 17:51:30.147002 | 0.001 ms   |
 |             │  │     ├─ do_local_das_task | 2023-03-01 17:51:30.147036 | 0.041 ms   |
 |             │  │     └─ close_das_task    | 2023-03-01 17:51:30.147183 | 0.011 ms   |
 |             │  └─ px_schedule             | 2023-03-01 17:51:30.147437 | 0.001 ms   |
 |             └─ close                      | 2023-03-01 17:51:30.147536 | 0.049 ms   |
 |                └─ end_transaction         | 2023-03-01 17:51:30.147571 | 0.002 ms   |
 +-------------------------------------------+----------------------------+------------+  

Show Trace快学快用

在OceanBase 4.0 提供了全链路追踪能力后，运维人员的操作会有什么变化呢？

运维人员现在可以有两种方式来使用Show Trace。

方式一：展示简略信息。

现在，用户如果发现业务请求变慢，可以重新运行一次该SQL，然后使用Show Trace命令，将其span打印出来，如图5所示。

方式二：展示详细信息。

当然，对于一些复杂的问题，单靠查看span的状态是定位不出问题所在的。因此，我们也可以展示出这个Query的详细执行信息，例如:
 
 OceanBase(SYS@SYS)>select * from t where c1=1;
 Empty set (0.001 sec)
 
 OceanBase(SYS@SYS)>show trace format='json'\G
 *************************** 1. row ***************************
 SHOW_TRACE_JSON: [{"logs":null,"tags":[{"sess_id":3221487638},{"action_name":""},{"module_name":""},{"client_info":""},{"receive_ts":1682407095822071},{"log_trace_id":"YA9257F000001-0005FA206441ADD9-0-0"}],"elapse":419,"end_ts":"2023-04-25 15:18:15.822547","parent":"0005fa23-ed50-66bb-9e0a-700e959f21ff","span_id":"0005fa23-ed50-6730-0748-1e63c6a2a636","start_ts":"2023-04-25 15:18:15.822128","trace_id":"0005fa23-ed50-66bb-caca-b2a1132f8eae","span_name":"com_query_process","tenant_id":1002,"rec_svr_ip":"127.0.0.1","rec_svr_port":43301},{"logs":null,"tags":null,"elapse":396,"end_ts":"2023-04-25 15:18:15.822532","parent":"0005fa23-ed50-6730-0748-1e63c6a2a636","span_id":"0005fa23-ed50-6738-75c5-5292251b8159","start_ts":"2023-04-25 15:18:15.822136","trace_id":"0005fa23-ed50-66bb-caca-b2a1132f8eae","span_name":"mpquery_single_stmt","tenant_id":1002,"rec_svr_ip":"127.0.0.1","rec_svr_port":43301},{"logs":null,"tags":[{"sql_text":"select * from t where c1=1"},{"sql_id":"A07D4B0B800C20F31180D2E0F3F73BFE"},{"database_id":201006},{"plan_hash":288002381100833637},{"hit_plan":true}],"elapse":112,"end_ts":"2023-04-25 15:18:15.822261","parent":"0005fa23-ed50-6738-75c5-5292251b8159","span_id":"0005fa23-ed50-6745-22f3-e1a1a5ee9745","start_ts":"2023-04-25 15:18:15.822149","trace_id":"0005fa23-ed50-66bb-caca-b2a1132f8eae","span_name":"sql_compile","tenant_id":1002,"rec_svr_ip":"127.0.0.1","rec_svr_port":43301},{"logs":null,"tags":null,"elapse":45,"end_ts":"2023-04-25 15:18:15.822197","parent":"0005fa23-ed50-6745-22f3-e1a1a5ee9745","span_id":"0005fa23-ed50-6748-4017-1c4d2fbacb63","start_ts":"2023-04-25 15:18:15.822152","trace_id":"0005fa23-ed50-66bb-caca-b2a1132f8eae","span_name":"pc_get_plan","tenant_id":1002,"rec_svr_ip":"127.0.0.1","rec_svr_port":43301},{"logs":null,"tags":null,"elapse":213,"end_ts":"2023-04-25 15:18:15.822490","parent":"0005fa23-ed50-6738-75c5-5292251b8159","span_id":"0005fa23-ed50-67c5-73cc-f89ef6db2fd9","start_ts":"2023-04-25 15:18:15.822277","trace_id":"0005fa23-ed50-66bb-caca-b2a1132f8eae","span_name":"sql_execute","tenant_id":1002,"rec_svr_ip":"127.0.0.1","rec_svr_port":43301},{"logs":null,"tags":null,"elapse":26,"end_ts":"2023-04-25 15:18:15.822303","parent":"0005fa23-ed50-67c5-73cc-f89ef6db2fd9","span_id":"0005fa23-ed50-67c5-cfcb-14906e4d8a27","start_ts":"2023-04-25 15:18:15.822277","trace_id":"0005fa23-ed50-66bb-caca-b2a1132f8eae","span_name":"open","tenant_id":1002,"rec_svr_ip":"127.0.0.1","rec_svr_port":43301},{"logs":null,"tags":null,"elapse":103,"end_ts":"2023-04-25 15:18:15.822420","parent":"0005fa23-ed50-67c5-73cc-f89ef6db2fd9","span_id":"0005fa23-ed50-67ed-720e-a5cda0d41ebe","start_ts":"2023-04-25 15:18:15.822317","trace_id":"0005fa23-ed50-66bb-caca-b2a1132f8eae","span_name":"response_result","tenant_id":1002,"rec_svr_ip":"127.0.0.1","rec_svr_port":43301},{"logs":null,"tags":null,"elapse":48,"end_ts":"2023-04-25 15:18:15.822373","parent":"0005fa23-ed50-67ed-720e-a5cda0d41ebe","span_id":"0005fa23-ed50-67f5-3e19-76474bad2e23","start_ts":"2023-04-25 15:18:15.822325","trace_id":"0005fa23-ed50-66bb-caca-b2a1132f8eae","span_name":"do_local_das_task","tenant_id":1002,"rec_svr_ip":"127.0.0.1","rec_svr_port":43301},{"logs":null,"tags":null,"elapse":45,"end_ts":"2023-04-25 15:18:15.822478","parent":"0005fa23-ed50-67c5-73cc-f89ef6db2fd9","span_id":"0005fa23-ed50-6861-929b-21bacd1577b8","start_ts":"2023-04-25 15:18:15.822433","trace_id":"0005fa23-ed50-66bb-caca-b2a1132f8eae","span_name":"close","tenant_id":1002,"rec_svr_ip":"127.0.0.1","rec_svr_port":43301},{"logs":null,"tags":null,"elapse":9,"end_ts":"2023-04-25 15:18:15.822443","parent":"0005fa23-ed50-6861-929b-21bacd1577b8","span_id":"0005fa23-ed50-6862-3659-7b0b257c849c","start_ts":"2023-04-25 15:18:15.822434","trace_id":"0005fa23-ed50-66bb-caca-b2a1132f8eae","span_name":"close_das_task","tenant_id":1002,"rec_svr_ip":"127.0.0.1","rec_svr_port":43301},{"logs":null,"tags":[{"trans_id":0}],"elapse":3,"end_ts":"2023-04-25 15:18:15.822464","parent":"0005fa23-ed50-6861-929b-21bacd1577b8","span_id":"0005fa23-ed50-687d-e820-9144206234b6","start_ts":"2023-04-25 15:18:15.822461","trace_id":"0005fa23-ed50-66bb-caca-b2a1132f8eae","span_name":"end_transaction","tenant_id":1002,"rec_svr_ip":"127.0.0.1","rec_svr_port":43301}]

当确定耗时高的请求后，接下来我们需要诊断具体是哪里出了问题。此时，用户可以在 OCP 中将得到的json数据输入trace visualizer，展示出每个部分的详细耗时，如图5所示。

图5 Show trace信息详细版展示图6 Show trace信息详细版展示

Show Trace FAQ

Q1: 机制上，Show Trace 和全链路诊断的异同点，Trace 数据保存在哪里？ 

A：Show Trace和全链路诊断，在Trace诊断信息的组织上是一脉相承的，都是将每个诊断信息作为一个span，标明当前span id和 parent span id，然后以树的形式组织起来。但是，他们在数据存储上却有一些差异，主要在于Show Trace的数据完全存储在内存中，是即时的，只会保存最近的诊断信息，而全链路的数据存储在磁盘中，是历史的，会保存执行过的信息。

Q2: 没有 Proxy 的时候，OCP 里能不能用Show Trace功能？

A：Proxy不是使用Show Trace能力的必要条件。是否存在Proxy，在Show Trace上显示的差异主要在：如果Proxy存在，那么Show Trace的树状结构就会有Proxy的信息；如果不存在，那么Show Trace的树状结构就不会有Proxy的信息。

Q3: 从 OCP 的哪个地方进去，能看到Show Trace功能？

A：根据指定 Trace id 或者SQL ID检索，然后查看链路详情，即可看到Show Trace功能。

Q4: obclient/objdbc/obproxy 的版本有没有要求？要什么版本?

A：obclient 220及以上版本；objdbc 2.4.0及以上版本；obproxy 4x以上版本。

写在最后

Show Trace是生产场景中常用的分析数据库性能的一大利器，可以帮助用户简单高效地定位查询性能瓶颈。本文介绍了Oceanbase v4.2新增的Show Trace能力特性，从语法使用、使用场景等角度来详细解析了该特性的使用方法，并分享了底层实现原理和一些使用场景，希望能够帮助大家更“丝滑”地使用到这个特性，帮助大家诊断性能，也欢迎大家在评论区分享优化建议、使用体验等。