Skip to content

Commit a74535d

Browse files
liboyang0730liboyang0730
authored
Merge pull request #212 from oceanbase/xiaofeng_branch
社区版 ODP 问题排查手册
2 parents 09bf904 + dee3b10 commit a74535d

File tree

16 files changed

+1648
-0
lines changed

16 files changed

+1648
-0
lines changed

‎docs/user_manual/operation_and_maintenance/tool_emergency_handbook/odp_troubleshooting_guide/01_introduction.md‎

Lines changed: 516 additions & 0 deletions
Large diffs are not rendered by default.

‎docs/user_manual/operation_and_maintenance/tool_emergency_handbook/odp_troubleshooting_guide/02_show_trace.md‎

Lines changed: 201 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,201 @@
1+
---
2+
title: 排查 ODP 是否是性能瓶颈
3+
weight: 2
4+
---
5+
6+
> 当用户遇到 SQL 性能不符合预期问题时，一般首先需要通过全链路追踪（show trace）确认各阶段耗时占比，确认耗时长的阶段是什么。
7+
>
8+
> **<font color="red">这个小节就为大家介绍在 SQL 性能差时，如何通过 show trace 来为 ODP 洗脱罪名。如果大家已经能够熟练应用 show trace 对 SQL 性能问题进行初步分析，可以直接跳过本小节。</font>**
9+
10+
## 全链路追踪（show trace）
11+
12+
OceanBase 数据库的数据链路为 `APPServer <-> OBProxy <-> OBServer`。APPServer 通过数据库驱动连接 ODP 发送请求，由于 OceanBase 数据库的分布式架构，用户数据以多分区多副本的方式分布于多个 OBServer 节点上，ODP 将用户请求转发到最合适的 OBServer 节点执行，并将执行结果返回用户。每个 OBServer 节点也有路由转发的功能，如果发现请求不能在当前节点执行，则会转发请求到正确的 OBServer 节点。
13+
14+
当出现端到端的性能问题时（在数据库场景下，端到端表示在应用服务器上观察到 SQL 请求的 RT 很高），此时首先需要定位是数据库访问链路上哪个组件的问题，再排查组件内的具体问题。
15+
16+
![全链路追踪](/img/user_manual/operation_and_maintenance/tool_emergency_handbook/odp_troubleshooting_guide/02_show_trace/001.png)
17+
18+
全链路追踪覆盖了两条主要的数据流路径：
19+
20+
- 一条是请求从应用出发，通过客户端（比如 JDBC 或 OCI）传递至 ODP（代理服务器），然后由 ODP 转发至 OBServer 节点，最终结果返回给应用程序。
21+
22+
- 另一条则是请求直接从应用程序通过客户端发送至 OBServer 节点，然后结果直接返回。
23+
24+
### 示例
25+
26+
接下来用这两条路径，分别举个一简单的例子。
27+
28+
1. 通过 ODP 连接 OceanBase 数据库，创建表并插入数据。
29+
30+
```sql
31+
create table t1(c1 int);
32+
33+
insert into t1 values(123);
34+
```
35+
36+
2. 在当前 session 上开启全链路诊断的 show trace 功能。
37+
38+
```sql
39+
SET ob_enable_show_trace = ON;
40+
```
41+
42+
3. 执行一条简单的查询语句。
43+
44+
```sql
45+
SELECT c1 FROM t1 LIMIT 2;
46+
```
47+
48+
输出如下：
49+
50+
```shell
51+
+------+
52+
| c1 |
53+
+------+
54+
| 123 |
55+
+------+
56+
1 row in set
57+
```
58+
59+
4. 执行 show trace 语句。
60+
61+
```sql
62+
SHOW TRACE;
63+
```
64+
65+
输出如下：
66+
67+
```shell
68+
+-----------------------------------------------------------+----------------------------+------------+
69+
| Operation | StartTime | ElapseTime |
70+
+-----------------------------------------------------------+----------------------------+------------+
71+
| ob_proxy | 2024-03-20 15:07:46.419433 | 191.999 ms |
72+
| ├── ob_proxy_partition_location_lookup | 2024-03-20 15:07:46.419494 | 181.839 ms |
73+
| ├── ob_proxy_server_process_req | 2024-03-20 15:07:46.601697 | 9.138 ms |
74+
| └── com_query_process | 2024-03-20 15:07:46.601920 | 8.824 ms |
75+
| └── mpquery_single_stmt | 2024-03-20 15:07:46.601940 | 8.765 ms |
76+
| ├── sql_compile | 2024-03-20 15:07:46.601984 | 7.666 ms |
77+
| │ ├── pc_get_plan | 2024-03-20 15:07:46.602051 | 0.029 ms |
78+
| │ └── hard_parse | 2024-03-20 15:07:46.602195 | 7.423 ms |
79+
| │ ├── parse | 2024-03-20 15:07:46.602201 | 0.137 ms |
80+
| │ ├── resolve | 2024-03-20 15:07:46.602393 | 0.555 ms |
81+
| │ ├── rewrite | 2024-03-20 15:07:46.603104 | 1.055 ms |
82+
| │ ├── optimize | 2024-03-20 15:07:46.604194 | 4.298 ms |
83+
| │ │ ├── inner_execute_read | 2024-03-20 15:07:46.605959 | 0.825 ms |
84+
| │ │ │ ├── sql_compile | 2024-03-20 15:07:46.606078 | 0.321 ms |
85+
| │ │ │ │ └── pc_get_plan | 2024-03-20 15:07:46.606124 | 0.147 ms |
86+
| │ │ │ ├── open | 2024-03-20 15:07:46.606418 | 0.129 ms |
87+
| │ │ │ └── do_local_das_task | 2024-03-20 15:07:46.606606 | 0.095 ms |
88+
| │ │ └── close | 2024-03-20 15:07:46.606813 | 0.240 ms |
89+
| │ │ ├── close_das_task | 2024-03-20 15:07:46.606879 | 0.022 ms |
90+
| │ │ └── end_transaction | 2024-03-20 15:07:46.607009 | 0.023 ms |
91+
| │ ├── code_generate | 2024-03-20 15:07:46.608527 | 0.374 ms |
92+
| │ └── pc_add_plan | 2024-03-20 15:07:46.609375 | 0.207 ms |
93+
| └── sql_execute | 2024-03-20 15:07:46.609677 | 0.832 ms |
94+
| ├── open | 2024-03-20 15:07:46.609684 | 0.156 ms |
95+
| ├── response_result | 2024-03-20 15:07:46.609875 | 0.327 ms |
96+
| │ └── do_local_das_task | 2024-03-20 15:07:46.609905 | 0.136 ms |
97+
| └── close | 2024-03-20 15:07:46.610221 | 0.225 ms |
98+
| ├── close_das_task | 2024-03-20 15:07:46.610229 | 0.029 ms |
99+
| └── end_transaction | 2024-03-20 15:07:46.610410 | 0.019 ms |
100+
+-----------------------------------------------------------+----------------------------+------------+
101+
29 rows in set
102+
```
103+
104+
从上面这条 show trace 的结果里，大家可以分析出一些信息：
105+
106+
- 这条 SQL 一共花了 191.999 ms。
107+
108+
- SQL 的整体的耗时主要在 `ob_proxy_partition_location_lookup` 上，占了 181.839 ms，顾名思义，这一部分耗时是 ODP（即 proxy） 在寻找表 `t1` 的主副本的位置信息。但是因为这张表刚刚创建，ODP 里暂时还没有对应的位置信息的缓存（也就是 location cache），所以第一次花的时间会比较久，不过之后 ODP 里就会缓存下这张表的 location cache 信息。
109+
110+
- SQL 转发到合适的 OBServer 节点之后，在 `com_query_process` 的耗时 8.824 ms。
111+
112+
> 这里再简单介绍 show trace 中其他几个重要点位：
113+
>
114+
> - **ob_proxy**： ODP 的起始点位，记录从 ODP 收到 SQL 请求到给客户端完整反馈响应的时间。
115+
>
116+
> - **ob_proxy_server_process_req**：表示发完 SQL 请求，到第一次收到 OBServer 节点返回响应的时间，等于 OBServer 节点处理时间 + 返回的网络耗时。
117+
>
118+
> - **com_query_process**：OceanBase 数据库的总点位，记录 OBServer 节点从收到 SQL 请求到转发响应完毕所需的时间。
119+
120+
5. 在同一个 session 中再重新执行一遍 `SELECT c1 FROM t1 LIMIT 2;` 这条 SQL，执行 show trace 语句查看有什么变化。
121+
122+
```sql
123+
SHOW TRACE;
124+
```
125+
126+
输出如下：
127+
128+
```shell
129+
+-----------------------------------------------+----------------------------+------------+
130+
| Operation | StartTime | ElapseTime |
131+
+-----------------------------------------------+----------------------------+------------+
132+
| ob_proxy | 2024-03-20 15:34:14.879559 | 7.390 ms |
133+
| ├── ob_proxy_partition_location_lookup | 2024-03-20 15:34:14.879652 | 4.691 ms |
134+
| ├── ob_proxy_server_process_req | 2024-03-20 15:34:14.884785 | 1.514 ms |
135+
| └── com_query_process | 2024-03-20 15:34:14.884943 | 1.237 ms |
136+
| └── mpquery_single_stmt | 2024-03-20 15:34:14.884959 | 1.207 ms |
137+
| ├── sql_compile | 2024-03-20 15:34:14.884997 | 0.279 ms |
138+
| │ └── pc_get_plan | 2024-03-20 15:34:14.885042 | 0.071 ms |
139+
| └── sql_execute | 2024-03-20 15:34:14.885300 | 0.809 ms |
140+
| ├── open | 2024-03-20 15:34:14.885310 | 0.139 ms |
141+
| ├── response_result | 2024-03-20 15:34:14.885513 | 0.314 ms |
142+
| │ └── do_local_das_task | 2024-03-20 15:34:14.885548 | 0.114 ms |
143+
| └── close | 2024-03-20 15:34:14.885847 | 0.190 ms |
144+
| ├── close_das_task | 2024-03-20 15:34:14.885856 | 0.030 ms |
145+
| └── end_transaction | 2024-03-20 15:34:14.885997 | 0.019 ms |
146+
+-----------------------------------------------+----------------------------+------------+
147+
14 rows in set
148+
```
149+
150+
从上面这条 show trace 的结果里，大家可以分析出一些信息：
151+
152+
- 第二次执行这条 SQL，时间变快了很多，从 191.999 ms 缩短到了 7.390 ms。
153+
154+
- ODP 有了 location cache 信息，所以寻找路由信息和转发都变快了，从之前的 181.839 ms 缩减到了 4.691 ms。
155+
156+
- SQL 转发到合适的 OBServer 节点之后，在 `com_query_process` 的耗时从 8.824 ms 缩减到了 1.237 ms。这里多啰嗦两句，大家仔细看一下就会发现，SQL 分为编译阶段和执行阶段，编译阶段是优化器生成执行计划，执行阶段是执行引擎根据执行计划计算结果。第二次执行时，编译阶段的流程变短了，速度也变快了，大概是因为编译阶段在最开始的时候，先会去计划缓存里查询下有没有之前已经生成好并且缓存下来的计划（即上面的 `pc_get_plan`），如果有的话，就不需要重新生成计划了，所以省了一个完整解析 SQL 并生成计划（即上面的 `hard_parse`）的开销。
157+
158+
6. 再通过直连 OBServer 节点登录 OceanBase 数据库，再重新执行一遍 `SELECT c1 FROM t1 LIMIT 2;` 这条 SQL，执行 show trace 语句查看有什么变化。
159+
160+
```sql
161+
SHOW TRACE;
162+
```
163+
164+
输出如下：
165+
166+
```shell
167+
+-------------------------------------------+----------------------------+------------+
168+
| Operation | StartTime | ElapseTime |
169+
+-------------------------------------------+----------------------------+------------+
170+
| com_query_process | 2024-03-20 15:54:38.772699 | 1.746 ms |
171+
| └── mpquery_single_stmt | 2024-03-20 15:54:38.772771 | 1.647 ms |
172+
| ├── sql_compile | 2024-03-20 15:54:38.772835 | 0.356 ms |
173+
| │ └── pc_get_plan | 2024-03-20 15:54:38.772900 | 0.143 ms |
174+
| └── sql_execute | 2024-03-20 15:54:38.773209 | 1.052 ms |
175+
| ├── open | 2024-03-20 15:54:38.773232 | 0.150 ms |
176+
| ├── response_result | 2024-03-20 15:54:38.773413 | 0.421 ms |
177+
| │ └── do_local_das_task | 2024-03-20 15:54:38.773479 | 0.192 ms |
178+
| └── close | 2024-03-20 15:54:38.773857 | 0.379 ms |
179+
| ├── close_das_task | 2024-03-20 15:54:38.773913 | 0.069 ms |
180+
| └── end_transaction | 2024-03-20 15:54:38.774139 | 0.058 ms |
181+
+-------------------------------------------+----------------------------+------------+
182+
11 rows in set
183+
```
184+
185+
从上面这条 show trace 的结果里，大家可以分析出一些信息：
186+
187+
- 直连 OBServer 节点，没了 ODP，所以也就没了和 proxy 相关的开销。
188+
189+
- 这条 SQL 的计划，之前已经进了这台 OBServer 节点的计划缓存里，所以在多次执行时，编译阶段都不需要再走一遍完整的硬解析流程。
190+
191+
**<font color="red"> 分析结束后，大家记得执行如下命令关闭 session 级别 show trace，避免对后续 SQL 的性能产生影响。 </font>**
192+
```
193+
set ob_enable_show_trace='off';
194+
```
195+
196+
### 总结
197+
最后简单总结一下：对于性能不符合预期的一条 SQL，通过全链路追踪，可以看到耗时在什么阶段：是耗时在 ODP（proxy）转发阶段？还是耗时在计划生成阶段？亦或是耗时在执行阶段？在各个阶段中，我们还可以看到更加细节的耗时数据（上面那条 SQL 实在太简单，又利用到了计划缓存，所以看上去细节不多），然后我们就可以针对具体慢的地方做进一步的分析。
198+
199+
如果慢在 ODP 转发阶段，可以怀疑是不是 ODP 和 OBServer 节点之间的网络出现故障了，或者是不是 ODP 还没缓存位置信息等问题。
200+
201+
如果慢在 SQL 执行阶段，就可以怀疑是不是创建的索引不够优等问题，并进行相应的 SQL 调优，详见本教程的[《SQL 性能诊断和调优》小节](https://oceanbase.github.io/docs/user_manual/operation_and_maintenance/scenario_best_practices/chapter_03_htap/performance_tuning)。

0 commit comments

Comments
 (0)