前一阵儿用 obdiag 进行过一次 sysbench 压测前的压测巡检，详见这篇博客。前两天看靖顺用这个工具的 obdiag check 功能帮一个开源用户出问题的环境进行了一次巡检，扫出了好几个问题，例如用户手动在存 redo 日志文件的 clog 路径下增加了一些新文件等，处理无关文件后，又利用 obdiag analyze log 功能分析了一波儿日志，发现了问题的根因，最终依靠 obdiag 的各种功能协助用户恢复了环境。所以正好借着这个机会，试用一下通过 obdiag 进行信息收集和诊断分析的功能。

安装和配置的过程很简单，我这边没遇到问题，步骤详见官网链接，也可以看下上面提到的那篇博客，这里略过了。

一键信息收集

官网上写 obdiag gather 可以收集很多东西，详见官网链接，我挑着个人觉得比较有价值的简单试用了一下。

试用 obdiag 进行信息收集和问题诊断-1

收集日志信息

感觉用 OCP 去做日志收集，可以在白屏页面选择 ip、时间段、关键字啥的，会比 obdiag 黑屏的方式更舒服一些，这里就先跳过了，等 obdiag 以后有白屏界面了再用。

收集集群的主机信息

这个试用了一下，大概是在集群的各台主机上收集了 tsar --cpu 和 tsar --mem 等命令的执行结果。如果集群节点多的话，可以省一些事。

收集和分析 clog / slog 信息

靖顺说 4.x 版本的内核还没支持这两个，但是我挺好奇以后能收集和分析到什么程度。之前手动用 ob_admin 工具分析过一次，需要加一些选项，以后支持了，可以省下 ob_admin 这个工具的学习成本。

通过 ob_admin 分析 clog 详见这篇博客。

收集 sql_plan_monitor 信息

这是一个好功能，分析并行度高且计划复杂时性能问题的神器。以前好像是只有 OceanBase 内部的同学才能用，现在 obdiag 集成了这个工具，推荐使用！

用 obdiag 收集 sql plan monitor 信息之后，可以直观地看出具体慢在哪个算子上，然后还可以直观地看出这个算子（在开并行时）的各个线程的任务划分是否均匀，或者说是否因为数据全都倾斜到了其中某几个线程而导致的性能问题等等。

下面简单举一个超级简单的小例子，先进行一个并行度为三的聚合计算（注意：如果没有并行，需要加一个 /*+monitor */ 的 hint 才能收集 sql plan monitor 信息）

select /*+parallel(3) */ count(c1) from t1;
+-----------+
| COUNT(C1) |
+-----------+
| 110000000 |
+-----------+
1 row in set (4.37 sec)

select last_trace_id() from dual;
+------------------------------------+
| LAST_TRACE_ID()                    |
+------------------------------------+
| Y58480B7C052B-0005EB5FF9C060FC-0-0 |
+------------------------------------+
1 row in set (0.04 sec)

拿着 trace id 收集下 sql plan monitor 信息。

[xiaofeng.lby@obvos-dev-d3 /home/xiaofeng.lby/.obdiag/
obdiag gather plan_monitor --trace_id Y58480B7C052B-0005EB5FF9C060FC-0-0

收集的信息是一个 html 文件，直接点开就能看到详细结果。

试用 obdiag 进行信息收集和问题诊断-2

因为上面那条 sql 简单，所以计划也简单，大概就是两阶段算 count，第一阶段三号算子用三个线程各算各的 count，第二阶段把各个线程的 count 结果汇总到零号算子再算一次 count 的 sum 就完了。下面这张 sql plan monitor 的图上，每个算子用了几个线程，吐了多少行，都看的很清楚，不再细说。

试用 obdiag 进行信息收集和问题诊断-3

要额外再说一句的是，看 sql plan monitor 里面 PHY_GRANULE_ITERATOR 后面的黄色块的 granule 数量。有多个 granule 时，先是三个线程一人一个，然后线程做完了自己手头的这个，就会去抢占池子里剩下的。这里把鼠标放在黄色块上就能看到，一共被分成了 12 个 granule。如果暂时还不了解 granule 的概念，那就请到这篇博客里全局搜索一下 granule 这个关键字。

通过下图里 rescan 列的信息，可以看到三个线程分别处理了 1 + 2、1 + 3、1 + 4 个 granule 的数据。1 就是各线程先分到的一个，2、3、4 就它们后来又在池子里抢占到的。

试用 obdiag 进行信息收集和问题诊断-4

这个例子里因为数据量实在太小，所以 granule 的分配勉强还算是均衡的。

如果你在 sql plan monitor 里看到数据量超大，分配了一大堆线程，但是只有一小部分线程在干活儿，大部分线程都在偷懒，那就直接拿着这个 sql plan monitor 的结果去社区问答区找技术支持同学分析为啥会产生数据倾斜的问题吧。

如果大家能通过 obdiag 收集到的 sql plan monitor 信息发现 OceanBase 存在类似于刚刚提到的严重数据倾斜问题的话，可以拿着这篇博客去问答区找技术支持同学获取一个兹拉坦提供的 OceanBase 小礼品，长期有效。

一键诊断分析

分析集群日志

简单试用了一下，命令很简单，直接详见官网链接吧。

感觉这个和通过关键字和 trace id 在 OCP 上收集日志的区别就是：当用户不知道遇到的问题应该搜什么关键字，也不清楚出错的 trace id 是啥，它能帮你把日志里所有值得怀疑的信息都捞出来并进行整理，然后展示到你面前。

obdiag 应该是挑了一些它认为值得的关注的报错进行整理和展示，对刚开始使用 OceanBase 的新用户十分友好，推荐使用！

全链路诊断

这个命令也很简单，可以看到一条慢 SQL 在整个链路上具体在哪个节点上执行什么步骤的时候慢了。

例如（抄自官网文档）：

$ 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 '

这个 Details 就能看到一条 SQL 一共花了 5.351 ms，在 observer 上花了 5.333 ms，在 proxy 上花了 5.351 - 5.333 = 很少 ms，所以肯定不是慢在 proxy 和 observer 的网络上。

再往下看，sql_execute 一共花了 5.147 ms，其中 px_schedule 先花了 2.465 ms，然后三个并行任务 px_task 每个都花了 2.x ms。

上面这个全链路诊断的结果没发现啥明显的问题，但是如果发现某一个 px_task 花的时间明显比其他的几个 px_task 长的话，就可以用之前提到的 sql plan monitor 工具进行进一步的分析，看看是不是任务分配不均啥的。

这里找了个本身就有问题的 SQL，拿这条 SQL 的全链路诊断结果给大家看下（抄自觉慧的这篇博客）：

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 命令，看不到 obdiag 里 TOP time-consuming leaf span 之类的东西，大家凑合看。

可以看到 SQL 在 observer 上执行花了 2.527 ms，但是 proxy 从拿到请求到返回结果花了 4.301 ms。基本就能猜出这条 SQL 慢的原因大概是 proxy 和 observer 之间出现了一些网络问题，然后就可以再进一步去检查是否存在网络问题了。

obdiag 可以对 SQL 请求进行一个可视化的全链路追踪，能够帮助用户快速追踪并定位问题具体发生在哪个阶段、哪台机器以及哪个模块，推荐使用！

对 obdiag 的问题

obdiag 的标准升级步骤是啥？官网（2024.01.18）上暂时还没看到。我现在每次都是直接删了老版本重装的新版本，不过好在重装也只需要执行一两条命令。

对 obdiag 的期待

obdiag 全链路诊断的结果里，除了 Elapsed Time，建议多展示一个 Start Time，这个信息其实也挺有用的，可以参考下 show trace 的结果。
建议对 4.x 版本的 observer 也支持一下收集和分析 clog / slog 信息的功能，不想再多折腾一个 ob_admin 工具了。
建议把 obdiag 做成一个白屏化的工具，复制黏贴各种命令总归还是要比直接拿鼠标点一点要麻烦不少。

试用 obdiag 进行信息收集和问题诊断

一键信息收集

收集日志信息

收集集群的主机信息

收集和分析 clog / slog 信息

收集 sql_plan_monitor 信息

一键诊断分析

分析集群日志

全链路诊断

对 obdiag 的问题

对 obdiag 的期待

相关文章

发布评论取消回复

三掌柜

百度搜索：蓝易云 – CentOS7编译生成openssl和openssh RPM包教程

【Rocky 9】Step by Step 安装 Rocky Linux 9.2 系统

蔚来汽车 x TiDB丨单表超 20 亿条数据，从 MySQL 到 TiDB 的迁移思考与实践

试用 obdiag 进行信息收集和问题诊断

一键信息收集

收集日志信息

收集集群的主机信息

收集和分析 clog / slog 信息

收集 sql_plan_monitor 信息

一键诊断分析

分析集群日志

全链路诊断

对 obdiag 的问题

对 obdiag 的期待

相关文章

发布评论 取消回复

三掌柜

百度搜索：蓝易云 – CentOS7编译生成openssl和openssh RPM包教程

【Rocky 9】Step by Step 安装 Rocky Linux 9.2 系统

蔚来汽车 x TiDB丨单表超 20 亿条数据，从 MySQL 到 TiDB 的迁移思考与实践

发布评论取消回复