暂无图片
暂无图片
暂无图片
暂无图片
暂无图片
首页 / 《OceanBase诊断系列》——全链路诊断日志看不懂？obdiag来帮你!!!

《OceanBase诊断系列》——全链路诊断日志看不懂？obdiag来帮你!!!

OceanBase社区传送门 2023-12-19
224

1. 前言

OceanBase 数据库是分布式数据库，因此调用链路复杂，当出现超时问题的时，往往无法快速定位是OceanBase 内部组件或是网络的问题，运维人员只能根据经验和 observer 日志进行分析。OB内核在4.0新增了trace.log日志，可以用于分析全链路诊断。

全链路有两条路径，一条是从应用通过客户端（JDBC 或 OCI 等）下发请求给 ODP（代理服务器）访问 OBServer，访问结果返回给应用；另一条是从应用通过客户端（JDBC 或 OCI 等）直接访问 OBServer，访问结果返回给应用。全链路诊断是对全链路所有组件进行问题定位的诊断。

Trace 文件会独立记录到 OBProxy 和 OBServer 不同进程所在机器，考虑到数据库客户端使用是在业务服务端，OceanBase 数据库 OBClient 端的全链路 Trace 信息并没有记录到业务服务器上，而是传输到 OBProxy 记录。

用户可以通过客户端访问 OceanBase 数据库，客户端的请求经由 OBProxy 分发到 OBServer 或直接访问 OBServer，在此过程中，运维人员可根据运维需要，通过使用 PL/SQL 程序包 DBMS_MONITOR 中相关方法，控制相关应用程序根据不同标识信息维度判断是否开启全链路诊断 trace，以及该 trace 的相关信息打印到 trace 日志。trace 日志会根据访问路径的情况判断日志打印，经由 ODP 访问数据库的，则会记录相关日志到 OBProxy 和 OBServer 对应的日志文件中；直接访问 OBServer ，则仅记录日志到 OBServer 对应的日志文件中。OBProxy 的 trace 日志文件为 obproxy_trace.log， OBServer 的 trace 日志文件为 trace.log。 trace 日志文件每个大小为 256M，日志写满 256M 后，会开始写新的 trace.log，之前的文件会被归档，归档的文件数量由相关归档参数控制，超出部分会被删除。运维人员通过对所有 trace 日志进行搜集分析后，可以追踪每个事务或每个 SQL 在整条链路中的执行耗时等相关信息，以此帮助运维人员定位整条访问链路的问题所在。

分布在各个节点上的trace.log怎么才能更友好的分析便是obdiag analyze flt_trace能帮你做的事情。


2. obdiag 全链路诊断设计

2.1  全链路诊断处理流程

主体架构还是依托于obdiag的集中式采集模式，当用户发起obdiag 的全链路诊断的时候需要去各个节点上进行trace.log的采集，将采集回来的数据集中进行分析处理。

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

2.2  全链路诊断时序图

1702958044


3. obdiag全链路诊断实践

各组件支持全链路追踪功能的版本：OB-Server >= 4.0.0.0，OB-Proxy >=4.0.0，OB-JDBC >=2.4.0。obdiag >= 1.5.0。

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: 设置配置文件

参考链接

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

obdiag analyze flt_trace [options]
复制

选项说明如下：

选项名是否必选数据类型默认值说明
--flt_trace_id是stringflt_trace_idflt_trace_id从gv$ob_sql_audit中查看flt_trace_id或者直接通过trace.log查找
--store_dir否string默认为命令执行的当前路径存储结果的本地路径。
--files否string默认为空--files 是离线分析日志文件模式，一旦指定 --files 则进入离线分析日志模式
--top否string5展示在全链路诊断结果中耗时最长的Top N叶子节点
--recursion否string8最大递归的全链路诊断的层数
--output否string60打印到屏幕上的结果行数，全量结果会完整的存储到结果文件中
-c否string~/.obdiag/config.yml配置文件路径

样例：

obdiag analyze flt_trace --flt_trace_id 000605b1-28bb-c15f-8ba0-1206bcc08aa3

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}]

复制


4. 附录

oceanbase
「喜欢这篇文章，您的关注和赞赏是给作者最好的鼓励」
关注作者
【版权声明】本文为墨天轮用户原创内容，转载时必须标注文章的来源（墨天轮），文章链接，文章作者等基本信息，否则作者和墨天轮有权追究责任。如果您发现墨天轮中有涉嫌抄袭或者侵权的内容，欢迎发送邮件至：contact@modb.pro进行举报，并提供相关证据，一经查实，墨天轮将立刻删除相关内容。

评论

相关阅读

2025年4月中国数据库流行度排行榜：OB高分复登顶，崖山稳驭撼十强
墨天轮编辑部
894次阅读
2025-04-09 15:33:27
2025年3月国产数据库大事记
墨天轮编辑部
608次阅读
2025-04-03 15:21:16
OceanBase赋能百丽核心系统上线，护航双11流量洪峰
OceanBase数据库
218次阅读
2025-03-20 20:34:04
OceanBase 单机版发布，针对中小规模业务场景
通讯员
210次阅读
2025-03-28 12:01:19
OceanBase CEO杨冰：2025年分布式数据库将迎来本地部署和国产升级的全面爆发
通讯员
172次阅读
2025-04-03 09:35:26
OceanBase亮相「党政信息化产品技术选型供需对接会」，助力党政关键业务系统升级
OceanBase
160次阅读
2025-03-27 09:55:58
TP与AP共生之道：OceanBase 4.3.5 HTAP混合负载实战
shunwahⓂ️
128次阅读
2025-03-27 15:04:42
OceanBase首届合作伙伴峰会：携手伙伴共赢云和AI时代
OceanBase数据库
113次阅读
2025-03-26 15:29:59
定档！2025 OceanBase开发者大会，5月17日广州见！
OceanBase数据库
105次阅读
2025-04-09 16:48:47
OceanBase单机版上线｜构建分布式到单机场景的全栈解决方案
OceanBase数据库
102次阅读
2025-03-30 17:08:58