一键全链路诊断日志分析 - 敏捷诊断工具 V2.6.0

本文适用于独立部署 obdiag 的场景，使用 obdiag analyze flt_trace 命令可对 OceanBase 的全链路日志进行分析，给出全链路诊断报告。

如果是 obd 部署的集群，可直接通过 obd 侧诊断命令组对所选集群进行信息收集，详细命令可参考诊断工具命令组。

全链路诊断是什么：OceanBase 数据库是分布式数据库，因此调用链路复杂，当出现超时问题的时，往往无法快速定位是OceanBase 内部组件或是网络的问题，运维人员只能根据经验和 observer 日志进行分析。OB内核在4.0新增了trace.log日志，可以用于分析全链路诊断。全链路有两条路径，一条是从应用通过客户端（JDBC 或 OCI 等）下发请求给 ODP（代理服务器）访问 OBServer，访问结果返回给应用；另一条是从应用通过客户端（JDBC 或 OCI 等）直接访问 OBServer，访问结果返回给应用。全链路诊断是对全链路所有组件进行问题定位的诊断。

obdiag全链路诊断做了什么：

┌────────┐       ┌─────────────────────────────┐       ┌────────────────────────────┐
│ 服务器1 │------>│ 搜索并过滤flt_trace_id相关日志 │------>│ 回传过滤后的日志到obdiag的节点 │---┐
└────────┘       └─────────────────────────────┘       └────────────────────────────┘   │
┌────────┐       ┌─────────────────────────────┐       ┌────────────────────────────┐   │    ┌────────────────────────────────┐
│ 服务器2 │------>│ 搜索并过滤flt_trace_id相关日志 │------>│ 回传过滤后的日志到obdiag的节点 │---┼--->│ 按照父子关系聚合各节点日志输出链路树 │
└────────┘       └─────────────────────────────┘       └────────────────────────────┘   │    └────────────────────────────────┘
┌────────┐       ┌─────────────────────────────┐       ┌────────────────────────────┐   │
│ 服务器N │------>│ 搜索并过滤flt_trace_id相关日志 │------>│ 回传过滤后的日志到obdiag的节点 │---┘
└────────┘       └─────────────────────────────┘       └────────────────────────────┘

使用说明

obdiag analyze flt_trace [options]

选项说明如下：

选项名	是否必选	数据类型	默认值	说明
--flt_trace_id	是	string	flt_trace_id	flt_trace_id 从 gv$ob_sql_audit 中查看 flt_trace_id 或者直接通过 trace.log 查找
--store_dir	否	string	默认为命令执行的当前路径	存储结果的本地路径。
--temp_dir	否	string	`/tmp`	远端节点在日志收集过程中产生的临时文件存储目录。
--files	否	string	默认为空	`--files` 是离线分析日志文件模式，一旦指定 `--files` 则进入离线分析日志模式
--top	否	string	5	展示在全链路诊断结果中耗时最长的 Top N 叶子节点
--recursion	否	string	8	最大递归的全链路诊断的层数
--output	否	string	60	打印到屏幕上的结果行数，全量结果会完整的存储到结果文件中
-c	否	string	`~/.obdiag/config.yml`	配置文件路径
--inner_config	否	string	默认为空	obdiag 自用的配置
--config	否	string	默认为空	需被 obdiag 诊断的集群的配置，固定样式：--config key1=value1 --config key2=value2

使用示例

方式一：无配置文件使用（开箱即用）

Step 1: 查找疑似慢的 SQL

在 gv$ob_sql_audit 中，如果有明确的 SQL 语句可以通过 query_sql 查到疑似慢 SQL 的 flt_trace_id，例如：

OceanBase(root@test)>select query_sql, flt_trace_id from oceanbase.gv$ob_sql_audit where query_sql like 'select @@version_comment limit 1';
+----------------------------------+--------------------------------------+
| query_sql                        | flt_trace_id                         |
+----------------------------------+--------------------------------------+
| select @@version_comment limit 1 | 00060aa3-d607-f5f2-328b-388e17f687cb |
+----------------------------------+--------------------------------------+
1 row in set (0.001 sec)

其中 flt_trace_id 为 00060aa3-d607-f5f2-328b-388e17f687cb。

或者你也可从 OBProxy、OceanBase 数据库的 trace.log 日志中找到 flt_trace_id：

head trace.log

[2023-12-07 22:20:07.242229] [489640][T1_L0_G0][T1][YF2A0BA2DA7E-00060BEC28627BEF-0-0] {"trace_id":"00060bec-275e-9832-e730-7c129f2182ac","name":"close_das_task","id":"00060bec-2a20-bf9e-56c9-724cb467f859","start_ts":1701958807240606,"end_ts":1701958807240607,"parent_id":"00060bec-2a20-bb5f-e03a-5da01aa3308b","is_follow":false}

其中 00060bec-275e-9832-e730-7c129f2182ac 就是其 flt_trace_id。

Step 2: 执行全链路诊断命令

说明

本节命令中使用的详细配置介绍可参见 obdiag 配置。

$ obdiag analyze flt_trace --flt_trace_id 000605b1-28bb-c15f-8ba0-1206bcc08aa3 \
    --config obcluster.servers.nodes[0].ip=xx.xx.xx.1 \
    --config obcluster.servers.nodes[1].ip=xx.xx.xx.2 \
    --config obcluster.servers.nodes[2].ip=xx.xx.xx.3 \
    --config obcluster.servers.global.home_path=/home/admin/oceanbase \
    --config obproxy.servers.nodes[0].ip=xx.xx.xx.4 \
    --config obproxy.servers.nodes[1].ip=xx.xx.xx.5 \
    --config obproxy.servers.global.ssh_username=test \
    --config obproxy.servers.global.ssh_password=****** \
    --config obproxy.servers.global.home_path=/home/admin/obproxy


root node id: 000605b1-28bb-c15f-8ba0-1206bcc08aa3

TOP time-consuming leaf span:
+---+----------------------------------+-------------+---------------------+
| ID| Span Name                        | Elapsed Time|      NODE           |
+---+----------------------------------+-------------+---------------------+
| 18| px_task                          | 2.758 ms    | OBSERVER(xx.xx.xx.1)|
| 5 | pc_get_plan                      | 52 μs       | OBSERVER(xx.xx.xx.1)|
| 16| do_local_das_task                | 45 μs       | OBSERVER(xx.xx.xx.1)|     
| 10| do_local_das_task                | 17 μs       | OBSERVER(xx.xx.xx.1)|
| 17| close_das_task                   | 14 μs       | OBSERVER(xx.xx.xx.1)|     
+---+----------------------------------+-------------+---------------------+
Tags & Logs:
-------------------------------------
18 - px_task  Elapsed: 2.758 ms 
     NODE:OBSERVER(xx.xx.xx.1)
     tags: [{'group_id': 0}, {'qc_id': 1}, {'sqc_id': 0}, {'dfo_id': 1}, {'task_id': 1}]
5 - pc_get_plan  Elapsed: 52 μs 
    NODE:OBSERVER(xx.xx.xx.1)
16 - do_local_das_task  Elapsed: 45 μs 
     NODE:OBSERVER(xx.xx.xx.3)
10 - do_local_das_task  Elapsed: 17 μs 
     NODE:OBSERVER(xx.xx.xx.1)
17 - close_das_task  Elapsed: 14 μs 
     NODE:OBSERVER(xx.xx.xx.3)

Details:
+---+----------------------------------+-------------+---------------------+
| ID| Span Name                        | Elapsed Time|  NODE               |
+---+----------------------------------+-------------+---------------------+
| 1 | TRACE                            | -           | -                   |
| 2 | └─com_query_process              | 5.351 ms    | OBPROXY(xx.xx.xx.1) |
| 3 |   └─mpquery_single_stmt          | 5.333 ms    | OBSERVER(xx.xx.xx.1)|
| 4 |     ├─sql_compile                | 107 μs      | OBSERVER(xx.xx.xx.1)|
| 5 |     │ └─pc_get_plan              | 52 μs       | OBSERVER(xx.xx.xx.1)|
| 6 |     └─sql_execute                | 5.147 ms    | OBSERVER(xx.xx.xx.1)|
| 7 |       ├─open                     | 87 μs       | OBSERVER(xx.xx.xx.1)|
| 8 |       ├─response_result          | 4.945 ms    | OBSERVER(xx.xx.xx.1)|
| 9 |       │ ├─px_schedule            | 2.465 ms    | OBSERVER(xx.xx.xx.1)|
| 10|       │ │ ├─do_local_das_task    | 17 μs       | OBSERVER(xx.xx.xx.1)|
| 11|       │ │ ├─px_task              | 2.339 ms    | OBSERVER(xx.xx.xx.2)|
| 12|       │ │ │ ├─do_local_das_task  | 54 μs       | OBSERVER(xx.xx.xx.2)|
| 13|       │ │ │ └─close_das_task     | 22 μs       | OBSERVER(xx.xx.xx.2)|
| 14|       │ │ ├─do_local_das_task    | 11 μs       | OBSERVER(xx.xx.xx.1)|
| 15|       │ │ ├─px_task              | 2.834 ms    | OBSERVER(xx.xx.xx.3)|
| 16|       │ │ │ ├─do_local_das_task  | 45 μs       | OBSERVER(xx.xx.xx.3)|
| 17|       │ │ │ └─close_das_task     | 14 μs       | OBSERVER(xx.xx.xx.3)|
| 18|       │ │ └─px_task              | 2.758 ms    | OBSERVER(xx.xx.xx.1)|
| 19|       │ ├─px_schedule            | 1 μs        | OBSERVER(xx.xx.xx.1)|
| 20|       │ └─px_schedule            | 1 μs        | OBSERVER(xx.xx.xx.1)|
| ..|       ......                     | ...         |  ......             |
+---+----------------------------------+-------------+---------------------+

For more details, please run cmd ' cat analyze_flt_result/000605b1-28bb-c15f-8ba0-1206bcc08aa3.txt '

查看详情：

$ cat analyze_flt_result/000605b1-28bb-c15f-8ba0-1206bcc08aa3.txt

root node id: 000605b1-28bb-c15f-8ba0-1206bcc08aa3

TOP time-consuming leaf span:
+---+----------------------------------+-------------+---------------------+
| ID| Span Name                        | Elapsed Time|      NODE           |
+---+----------------------------------+-------------+---------------------+
| 18| px_task                          | 2.758 ms    | OBSERVER(xx.xx.xx.1)|
| 5 | pc_get_plan                      | 52 μs       | OBSERVER(xx.xx.xx.1)|
| 16| do_local_das_task                | 45 μs       | OBSERVER(xx.xx.xx.1)|     
| 10| do_local_das_task                | 17 μs       | OBSERVER(xx.xx.xx.1)|
| 17| close_das_task                   | 14 μs       | OBSERVER(xx.xx.xx.1)|     
+---+----------------------------------+-------------+---------------------+
Tags & Logs:
-------------------------------------
18 - px_task  Elapsed: 2.758 ms 
     NODE:OBSERVER(xx.xx.xx.1)
     tags: [{'group_id': 0}, {'qc_id': 1}, {'sqc_id': 0}, {'dfo_id': 1}, {'task_id': 1}]
5 - pc_get_plan  Elapsed: 52 μs 
    NODE:OBSERVER(xx.xx.xx.1)
16 - do_local_das_task  Elapsed: 45 μs 
     NODE:OBSERVER(xx.xx.xx.3)
10 - do_local_das_task  Elapsed: 17 μs 
     NODE:OBSERVER(xx.xx.xx.1)
17 - close_das_task  Elapsed: 14 μs 
     NODE:OBSERVER(xx.xx.xx.3)


Details:

+---+----------------------------------+-------------+---------------------+
| ID| Span Name                        | Elapsed Time|  NODE               |
+---+----------------------------------+-------------+---------------------+
| 1 | TRACE                            | -           | -                   |
| 2 | └─com_query_process              | 5.351 ms    | OBPROXY(xx.xx.xx.1) |
| 3 |   └─mpquery_single_stmt          | 5.333 ms    | OBSERVER(xx.xx.xx.1)|
| 4 |     ├─sql_compile                | 107 μs      | OBSERVER(xx.xx.xx.1)|
| 5 |     │ └─pc_get_plan              | 52 μs       | OBSERVER(xx.xx.xx.1)|
| 6 |     └─sql_execute                | 5.147 ms    | OBSERVER(xx.xx.xx.1)|
| 7 |       ├─open                     | 87 μs       | OBSERVER(xx.xx.xx.1)|
| 8 |       ├─response_result          | 4.945 ms    | OBSERVER(xx.xx.xx.1)|
| 9 |       │ ├─px_schedule            | 2.465 ms    | OBSERVER(xx.xx.xx.1)|
| 10|       │ │ ├─do_local_das_task    | 17 μs       | OBSERVER(xx.xx.xx.1)|
| 11|       │ │ ├─px_task              | 2.339 ms    | OBSERVER(xx.xx.xx.2)|
| 12|       │ │ │ ├─do_local_das_task  | 54 μs       | OBSERVER(xx.xx.xx.2)|
| 13|       │ │ │ └─close_das_task     | 22 μs       | OBSERVER(xx.xx.xx.2)|
| 14|       │ │ ├─do_local_das_task    | 11 μs       | OBSERVER(xx.xx.xx.1)|
| 15|       │ │ ├─px_task              | 2.834 ms    | OBSERVER(xx.xx.xx.3)|
| 16|       │ │ │ ├─do_local_das_task  | 45 μs       | OBSERVER(xx.xx.xx.3)|
| 17|       │ │ │ └─close_das_task     | 14 μs       | OBSERVER(xx.xx.xx.3)|
| 18|       │ │ └─px_task              | 2.758 ms    | OBSERVER(xx.xx.xx.1)|
| 19|       │ ├─px_schedule            | 1 μs        | OBSERVER(xx.xx.xx.1)|
| 20|       │ └─px_schedule            | 1 μs        | OBSERVER(xx.xx.xx.1)|
| 21|       └─close                    | 70 μs       | OBSERVER(xx.xx.xx.1)|
| 22|         └─end_transaction        | 3 μs        | OBSERVER(xx.xx.xx.1)|
+---+----------------------------------+-------------+---------------------+
Tags & Logs:
-------------------------------------
1 -   
2 - com_query_process  Elapsed: 5.351 ms 
    NODE:OBPROXY(xx.xx.xx.1)
    tags: [{'sess_id': 3221487633}, {'action_name': ''}, {'module_name': ''}, {'client_info': ''}, {'receive_ts': 1695108311007659}, {'log_trace_id': 'YA9257F000001-000605B0441954BC-0-0'}]
3 - mpquery_single_stmt  Elapsed: 5.333 ms 
    NODE:OBSERVER(xx.xx.xx.1)
4 - sql_compile  Elapsed: 107 μs 
    NODE:OBSERVER(xx.xx.xx.1)
    tags: [{'sql_text': 'select /*+parallel(2)*/ count(1) from t1 tt1, t1 tt2'}, {'sql_id': '797B7202BA69D4C2C77C12BFADDC19DC'}, {'database_id': 201001}, {'plan_hash': 150629045171310866}, {'hit_plan': True}]
5 - pc_get_plan  Elapsed: 52 μs 
    NODE:OBSERVER(xx.xx.xx.1)
6 - sql_execute  Elapsed: 5.147 ms 
    NODE:OBSERVER(xx.xx.xx.1)
7 - open  Elapsed: 87 μs 
    NODE:OBSERVER(xx.xx.xx.1)
8 - response_result  Elapsed: 4.945 ms 
    NODE:OBSERVER(xx.xx.xx.1)
9 - px_schedule  Elapsed: 2.465 ms 
    NODE:OBSERVER(xx.xx.xx.1)
    tags: [{'used_worker_cnt': 0}, {'qc_id': 1}, {'dfo_id': 2147483647}, {'used_worker_cnt': 0}, {'qc_id': 1}, {'dfo_id': 1}]
10 - do_local_das_task  Elapsed: 17 μs 
     NODE:OBSERVER(xx.xx.xx.1)
11 - px_task  Elapsed: 2.339 ms 
     NODE:OBSERVER(xx.xx.xx.2)
     tags: [{'group_id': 0}, {'qc_id': 1}, {'sqc_id': 0}, {'dfo_id': 0}, {'task_id': 0}]
12 - do_local_das_task  Elapsed: 54 μs 
     NODE:OBSERVER(xx.xx.xx.2)
13 - close_das_task  Elapsed: 22 μs 
     NODE:OBSERVER(xx.xx.xx.2)
14 - do_local_das_task  Elapsed: 11 μs 
     NODE:OBSERVER(xx.xx.xx.1)
15 - px_task  Elapsed: 2.834 ms 
     NODE:OBSERVER(xx.xx.xx.3)
     tags: [{'group_id': 0}, {'qc_id': 1}, {'sqc_id': 0}, {'dfo_id': 1}, {'task_id': 0}]
16 - do_local_das_task  Elapsed: 45 μs 
     NODE:OBSERVER(xx.xx.xx.3)
17 - close_das_task  Elapsed: 14 μs 
     NODE:OBSERVER(xx.xx.xx.3)
18 - px_task  Elapsed: 2.758 ms 
     NODE:OBSERVER(xx.xx.xx.1)
     tags: [{'group_id': 0}, {'qc_id': 1}, {'sqc_id': 0}, {'dfo_id': 1}, {'task_id': 1}]
19 - px_schedule  Elapsed: 1 μs 
     NODE:OBSERVER(xx.xx.xx.1)
20 - px_schedule  Elapsed: 1 μs 
     NODE:OBSERVER(xx.xx.xx.1)
21 - close  Elapsed: 70 μs 
     NODE:OBSERVER(xx.xx.xx.1)
22 - end_transaction  Elapsed: 3 μs 
     NODE:OBSERVER(xx.xx.xx.1)
     tags: [{'trans_id': 0}]

方式二：有配置文件使用

Step 1: 查找疑似慢的sql

在 gv$ob_sql_audit 中，如果有明确的 SQL 语句可以通过 query_sql 查到疑似慢 SQL 的 flt_trace_id。

Step 2: 设置被诊断集群配置

需要确保已经在 obdiag 配置文件 config.yml 中配置好需要收集节点的登录信息。相关的详细配置介绍，参见 obdiag 配置。

obdiag config -hxx.xx.xx.xx -uroot@sys -p***** -P2881

Step 3: 执行全链路诊断命令

obdiag analyze flt_trace --flt_trace_id <FLT_TRACE_ID>