运维首页 > 数据运维 > OceanBase诊断调优 (六) ——全链路诊断日志看不懂？obdiag来帮你!

OceanBase诊断调优 (六) ——全链路诊断日志看不懂？obdiag来帮你!

2024年 5月 7日 71.7k 0

最近总结一些诊断OCeanBase的一些经验，出一个【OceanBase诊断调优】专题，也欢迎大家贡献自己的诊断OceanBase的方法。

1. 前言

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

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

OceanBase诊断调优 (六) ——全链路诊断日志看不懂？obdiag来帮你!-1

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  全链路诊断时序图

OceanBase诊断调优 (六) ——全链路诊断日志看不懂？obdiag来帮你!-2

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 是 string flt_trace_id flt_trace_id从gv$ob_sql_audit中查看flt_trace_id或者直接通过trace.log查找
--store_dir 否 string 默认为命令执行的当前路径 存储结果的本地路径。
--files 否 string 默认为空 --files 是离线分析日志文件模式，一旦指定 --files 则进入离线分析日志模式
--top 否 string 5 展示在全链路诊断结果中耗时最长的Top N叶子节点
--recursion 否 string 8 最大递归的全链路诊断的层数
--output 否 string 60 打印到屏幕上的结果行数，全量结果会完整的存储到结果文件中
-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. 附录

  • obdiag 下载地址： https://www.oceanbase.com/softwarecenter
  • obdiag 官方文档： https://www.oceanbase.com/docs/obdiag-cn
  • obdiag github地址： https://github.com/oceanbase/oceanbase-diagnostic-tool
醒在深海的猫
数据运维
0 0

相关文章

Oracle如何使用授予和撤销权限的语法和示例
Awesome Project: 探索 MatrixOrigin 云原生分布式数据库
下载丨66页PDF，云和恩墨技术通讯（2024年7月刊）
社区版oceanbase安装
Oracle 导出CSV工具-sqluldr2
ETL数据集成丨快速将MySQL数据迁移至Doris数据库

发布评论

醒在深海的猫

这个人很懒，什么都没有留下～

文章8517 评论0