Skip to content

Commit 1538836

Browse files
zimulalazimulala
authored
*: add slow log control variables (tidb_slow_log_rules, tidb_slow_log_max_per_sec) and hint WRITE_SLOW_LOG (#21009)
1 parent c88dc62 commit 1538836

File tree

2 files changed

+135
-29
lines changed

2 files changed

+135
-29
lines changed

‎identify-slow-queries.md‎

Lines changed: 109 additions & 29 deletions
Original file line numberDiff line numberDiff line change
@@ -59,7 +59,7 @@ Slow Query 基础信息：
5959
* `Compile_time`：表示这个语句在查询优化阶段花费的时间。
6060
* `Optimize_time`：表示这个语句在优化查询计划阶段花费的时间。
6161
* `Wait_TS`：表示这个语句在等待获取事务 TS 阶段花费的时间。
62-
* `Query`：表示 SQL 语句。慢日志里面不会打印 `Query`，但映射到内存表后，对应的字段叫 `Query`。
62+
* `Query`：表示 SQL 语句。慢查询日志里面不会打印 `Query`，但映射到内存表后，对应的字段叫 `Query`。
6363
* `Digest`：表示 SQL 语句的指纹。
6464
* `Txn_start_ts`：表示事务的开始时间戳，也是事务的唯一 ID，可以用这个值在 TiDB 日志中查找事务相关的其他日志。
6565
* `Is_internal`：表示是否为 TiDB 内部的 SQL 语句。`true` 表示 TiDB 系统内部执行的 SQL 语句，`false` 表示用户执行的 SQL 语句。
@@ -173,29 +173,109 @@ Slow Query 基础信息：
173173
- `Storage_from_kv`：从 v9.0.0 开始引入，表示该语句是否从 TiKV 读取数据。
174174
- `Storage_from_mpp`：从 v9.0.0 开始引入，表示该语句是否从 TiFlash 读取数据。
175175

176-
## 相关系统变量
176+
## 相关 Hint
177+
178+
从 v9.0.0 开始，你可以使用 `WRITE_SLOW_LOG` Hint。该 Hint 用于强制 TiDB 将特定 SQL 的执行信息输出至慢查询日志，无论其执行时长是否达到阈值。这有助于捕获 SQL 执行过程中的详细元数据，如执行计划和资源消耗。例如，在出现偶发性能抖动问题时，某些 SQL 仅在特定条件下（如数据量突增或索引失效）才会变慢，而平时执行速度很快，因此难以通过默认的慢查询阈值捕获。这种情况下，可以预先在业务 SQL 中添加 `WRITE_SLOW_LOG` Hint，确保在问题复现的瞬间，系统能完整记录下该次 SQL 执行的详细信息。
177179

178-
* [tidb_slow_log_threshold](/system-variables.md#tidb_slow_log_threshold)：设置慢日志的阈值，执行时间超过阈值的 SQL 语句将被记录到慢日志中。默认值是 300 ms。
179-
* [tidb_query_log_max_len](/system-variables.md#tidb_query_log_max_len)：设置慢日志记录 SQL 语句的最大长度。默认值是 4096 byte。
180-
* [tidb_redact_log](/system-variables.md#tidb_redact_log)：设置慢日志记录 SQL 时是否将用户数据脱敏用 `?` 代替。默认值是 `0`，即关闭该功能。
181-
* [tidb_enable_collect_execution_info](/system-variables.md#tidb_enable_collect_execution_info)：设置是否记录执行计划中各个算子的物理执行信息，默认值是 `1`。该功能对性能的影响约为 3%。开启该项后查看 `Plan` 的示例如下：
180+
- 该 Hint 不受任何阈值或触发规则限制，即无论该 SQL 查询是否达到慢查询日志打印阈值，都会打印慢查询日志。
181+
- 目前只支持强制开启打印慢查询日志，暂不支持通过 `WRITE_SLOW_LOG(FALSE)` 强制关闭打印慢查询日志。
182+
183+
使用示例：
182184

183185
```sql
184-
> select tidb_decode_plan('jAOIMAk1XzE3CTAJMQlmdW5jczpjb3VudChDb2x1bW4jNyktPkMJC/BMNQkxCXRpbWU6MTAuOTMxNTA1bXMsIGxvb3BzOjIJMzcyIEJ5dGVzCU4vQQoxCTMyXzE4CTAJMQlpbmRleDpTdHJlYW1BZ2dfOQkxCXQRSAwyNzY4LkgALCwgcnBjIG51bTogMQkMEXMQODg0MzUFK0hwcm9jIGtleXM6MjUwMDcJMjA2HXsIMgk1BWM2zwAAMRnIADcVyAAxHcEQNQlOL0EBBPBbCjMJMTNfMTYJMQkzMTI4MS44NTc4MTk5MDUyMTcJdGFibGU6dCwgaW5kZXg6aWR4KGEpLCByYW5nZTpbLWluZiw1MDAwMCksIGtlZXAgb3JkZXI6ZmFsc2UJMjUBrgnQVnsA');
185-
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
186-
| tidb_decode_plan('jAOIMAk1XzE3CTAJMQlmdW5jczpjb3VudChDb2x1bW4jNyktPkMJC/BMNQkxCXRpbWU6MTAuOTMxNTA1bXMsIGxvb3BzOjIJMzcyIEJ5dGVzCU4vQQoxCTMyXzE4CTAJMQlpbmRleDpTdHJlYW1BZ2dfOQkxCXQRSAwyNzY4LkgALCwgcnBjIG51bTogMQkMEXMQODg0MzUFK0hwcm9jIGtleXM6MjUwMDcJMjA2HXsIMg |
187-
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
188-
| id task estRows operator info actRows execution info memory disk |
189-
| StreamAgg_17 root 1 funcs:count(Column#7)->Column#5 1 time:10.931505ms, loops:2 372 Bytes N/A |
190-
| └─IndexReader_18 root 1 index:StreamAgg_9 1 time:10.927685ms, loops:2, rpc num: 1, rpc time:10.884355ms, proc keys:25007 206 Bytes N/A |
191-
| └─StreamAgg_9 cop 1 funcs:count(1)->Column#7 1 time:11ms, loops:25 N/A N/A |
192-
| └─IndexScan_16 cop 31281.857819905217 table:t, index:idx(a), range:[-inf,50000), keep order:false 25007 time:11ms, loops:25 N/A N/A |
193-
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
186+
SELECT /*+ WRITE_SLOW_LOG */ count(*) FROM t t1, t t2 WHERE t1.a = t2.b;
194187
```
195188

196-
在性能测试中可以关闭自动收集算子的执行信息：
189+
## 相关系统变量
197190

198-
{{< copyable "sql" >}}
191+
* [`tidb_slow_log_threshold`](/system-variables.md#tidb_slow_log_threshold)：用于设置慢查询日志的阈值，执行时间超过阈值的 SQL 语句将被记录到慢查询日志中。默认值是 300 ms。
192+
* [`tidb_slow_log_rules`](/system-variables.md#tidb_slow_log_rules-从-v900-版本开始引入)：用于定义慢查询日志的触发规则，支持多维度指标组合条件，以实现更加灵活和精细化的日志记录控制。该变量在 v9.0.0 版本中引入，逐步替代传统的单一阈值控制方式，即替代 `tidb_slow_log_threshold` 的使用。该变量支持将以下字段作为筛选条件，设置输出慢查询日志的条件。详情请参考[字段含义说明](#字段含义说明)。
193+
- 支持的筛选字段：
194+
* Slow Query 基础信息：
195+
* `Query_time`、`Parse_time`、`Compile_time`、`Optimize_time`、`Wait_TS`、`Rewrite_time`
196+
* `Digest`、`Plan_digest`、`Is_internal`、`Succ`
197+
* `Exec_retry_count`、`Backoff_time`、`Write_sql_response_total`
198+
* 事务执行相关的字段：
199+
* `Prewrite_time`、`Commit_time`、`Write_keys`、`Write_size`、`Prewrite_region`
200+
* SQL 执行的用户相关的字段：
201+
* `Conn_ID`、`DB`、`Session_alias`
202+
* TiKV Coprocessor Task 相关的字段：
203+
* `Process_time`、`Total_keys`、`Process_keys`、`Num_cop_tasks`
204+
* 内存使用相关的字段：
205+
* `Mem_max`
206+
* 硬盘使用相关的字段：
207+
* `Disk_max`
208+
* 资源管控相关的字段：
209+
* `Resource_group`
210+
* 网络传输相关的字段：
211+
* `KV_total`、`PD_total`
212+
* `Unpacked_bytes_sent_tikv_total`、`Unpacked_bytes_received_tikv_total`
213+
* `Unpacked_bytes_sent_tikv_cross_zone`、`Unpacked_bytes_received_tikv_cross_zone`
214+
* `Unpacked_bytes_sent_tiflash_total`、`Unpacked_bytes_received_tiflash_total`
215+
* `Unpacked_bytes_sent_tiflash_cross_zone`、`Unpacked_bytes_received_tiflash_cross_zone`
216+
* 如果未设置 `tidb_slow_log_rules`：
217+
* 慢查询日志触发仍依赖 `tidb_slow_log_threshold`。注：`query_time` 阈值的含义同该变量，均表示 SQL 执行时长阈值，以保持向后兼容。
218+
* 如果已设置 `tidb_slow_log_rules`：
219+
* 配置的规则优先生效，`tidb_slow_log_threshold` 将被忽略。
220+
* 若希望规则中仍使用 SQL 执行时间作为输出慢日志的条件之一，可在设置规则时使用`query_time` 并设置阈值。
221+
* 规则匹配逻辑（多条规则之间采用 OR 关系）：
222+
* SESSION 作用域规则：优先匹配，如果匹配成功，则打印慢查询日志。
223+
* GLOBAL 作用域规则：仅在 SESSION 作用域规则未匹配时考虑：
224+
* 若规则指定了 `ConnID` 并与当前会话的 `ConnID` 匹配，则使用该规则。
225+
* 若规则未指定 `ConnID`（全局通用规则），则使用该规则。
226+
* 使用 `SHOW VARIABLES`、`SELECT @@GLOBAL.tidb_slow_log_rules`、`SELECT @@SESSION.tidb_slow_log_rules` 显示该变量的行为与其他系统变量一致。
227+
* 使用示例：
228+
* 标准格式（SESSION 作用域）：
229+
230+
```sql
231+
SET SESSION tidb_slow_log_rules = 'Query_time: 500, Is_internal: false';
232+
```
233+
234+
* 错误格式（SESSION 作用域不支持 `ConnID`）：
235+
236+
```sql
237+
SET SESSION tidb_slow_log_rules = 'ConnID: 12, Query_time: 500, Is_internal: false';
238+
```
239+
240+
* 全局规则（适用于所有连接）：
241+
242+
```sql
243+
SET GLOBAL tidb_slow_log_rules = 'Query_time: 500, Is_internal: false';
244+
```
245+
246+
* 指定特定连接的全局规则（分别适用于 `ConnID:11` 和 `ConnID:11` 的两个连接）：
247+
248+
```sql
249+
SET GLOBAL tidb_slow_log_rules = 'ConnID: 11, Query_time: 500, Is_internal: false; ConnID: 12, Query_time: 600, Process_time: 300, DB: db1';
250+
```
251+
252+
> **Tip:**
253+
>
254+
> - `tidb_slow_log_rules` 用于替换单一阈值的方式，实现更灵活和精细化的慢查询日志控制，支持多维度指标组合条件。
255+
> - 在资源充足的测试环境（1 个 TiDB 节点，16 核 CPU、48 GiB 内存；3 个 TiKV 节点，每个 16 核 CPU、48 GiB 内存）中，多次 sysbench 测试结果表明：当多维慢查询日志规则在 30 分钟内生成数百万条慢查询日志时，对性能影响较小；但当日志量达到千万级时，TPS 会明显下降，延迟也会显著增加。在业务负载较高或 CPU、内存资源接近瓶颈的情况下，应谨慎配置 `tidb_slow_log_rules`，避免因规则过宽导致日志洪泛。建议结合使用 `tidb_slow_log_max_per_sec` 来限制日志打印速率，以降低对业务性能的影响。
256+
257+
* [`tidb_slow_log_max_per_sec`](/system-variables.md#tidb_slow_log_max_per_sec-从-v900-版本开始引入)：用于设置每秒打印慢查询日志数量的上限，默认值为 `0`。
258+
* 当值为 `0` 时，表示不限制每秒打印的慢查询日志数量。
259+
* 当值大于 `0` 时，TiDB 每秒最多打印指定数量的慢查询日志，超过部分将被丢弃，不会写入慢查询日志文件。
260+
* 建议在启用了 `tidb_slow_log_rules` 后配置该变量，以防止基于规则的慢查询日志触发过于频繁。
261+
* [`tidb_query_log_max_len`](/system-variables.md#tidb_query_log_max_len)：设置慢查询日志记录 SQL 语句的最大长度。默认值是 4096 byte。
262+
* [`tidb_redact_log`](/system-variables.md#tidb_redact_log)：设置慢查询日志记录 SQL 时，是否将用户数据脱敏用 `?` 代替。默认值是 `0`，即关闭该功能。
263+
* [`tidb_enable_collect_execution_info`](/system-variables.md#tidb_enable_collect_execution_info)：设置是否记录执行计划中各个算子的物理执行信息，默认值是 `1`。开启该功能会导致性能降低约 3%。开启后查看 `Plan` 的示例如下：
264+
265+
```sql
266+
> select tidb_decode_plan('jAOIMAk1XzE3CTAJMQlmdW5jczpjb3VudChDb2x1bW4jNyktPkMJC/BMNQkxCXRpbWU6MTAuOTMxNTA1bXMsIGxvb3BzOjIJMzcyIEJ5dGVzCU4vQQoxCTMyXzE4CTAJMQlpbmRleDpTdHJlYW1BZ2dfOQkxCXQRSAwyNzY4LkgALCwgcnBjIG51bTogMQkMEXMQODg0MzUFK0hwcm9jIGtleXM6MjUwMDcJMjA2HXsIMgk1BWM2zwAAMRnIADcVyAAxHcEQNQlOL0EBBPBbCjMJMTNfMTYJMQkzMTI4MS44NTc4MTk5MDUyMTcJdGFibGU6dCwgaW5kZXg6aWR4KGEpLCByYW5nZTpbLWluZiw1MDAwMCksIGtlZXAgb3JkZXI6ZmFsc2UJMjUBrgnQVnsA');
267+
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
268+
| tidb_decode_plan('jAOIMAk1XzE3CTAJMQlmdW5jczpjb3VudChDb2x1bW4jNyktPkMJC/BMNQkxCXRpbWU6MTAuOTMxNTA1bXMsIGxvb3BzOjIJMzcyIEJ5dGVzCU4vQQoxCTMyXzE4CTAJMQlpbmRleDpTdHJlYW1BZ2dfOQkxCXQRSAwyNzY4LkgALCwgcnBjIG51bTogMQkMEXMQODg0MzUFK0hwcm9jIGtleXM6MjUwMDcJMjA2HXsIMg |
269+
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
270+
| id task estRows operator info actRows execution info memory disk |
271+
| StreamAgg_17 root 1 funcs:count(Column#7)->Column#5 1 time:10.931505ms, loops:2 372 Bytes N/A |
272+
| └─IndexReader_18 root 1 index:StreamAgg_9 1 time:10.927685ms, loops:2, rpc num: 1, rpc time:10.884355ms, proc keys:25007 206 Bytes N/A |
273+
| └─StreamAgg_9 cop 1 funcs:count(1)->Column#7 1 time:11ms, loops:25 N/A N/A |
274+
| └─IndexScan_16 cop 31281.857819905217 table:t, index:idx(a), range:[-inf,50000), keep order:false 25007 time:11ms, loops:25 N/A N/A |
275+
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
276+
```
277+
278+
在性能测试中可以关闭自动收集算子的执行信息：
199279

200280
```sql
201281
set @@tidb_enable_collect_execution_info=0;
@@ -205,17 +285,17 @@ set @@tidb_enable_collect_execution_info=0;
205285

206286
更多详细信息，可以参见 [TiDB 专用系统变量和语法](/system-variables.md)。
207287

208-
## 慢日志内存映射表
288+
## 慢查询日志内存映射表
209289

210-
用户可通过查询 `INFORMATION_SCHEMA.SLOW_QUERY` 表来查询慢查询日志中的内容，表中列名和慢日志中字段名一一对应，表结构可查看 [`SLOW_QUERY` 表](/information-schema/information-schema-slow-query.md)中的介绍。
290+
用户可通过查询 `INFORMATION_SCHEMA.SLOW_QUERY` 表来查询慢查询日志中的内容，表中列名和慢查询日志中字段名一一对应，表结构可查看 [`SLOW_QUERY` 表](/information-schema/information-schema-slow-query.md)中的介绍。
211291

212292
> **注意：**
213293
>
214294
> 每次查询 `SLOW_QUERY` 表时，TiDB 都会去读取和解析一次当前的慢查询日志。
215295

216-
TiDB 4.0 中，`SLOW_QUERY` 已经支持查询任意时间段的慢日志，即支持查询已经被 rotate 的慢日志文件的数据。用户查询时只需要指定 `TIME` 时间范围即可定位需要解析的慢日志文件。如果查询不指定时间范围，则仍然只解析当前的慢日志文件，示例如下：
296+
TiDB 4.0 中，`SLOW_QUERY` 已经支持查询任意时间段的慢查询日志，即支持查询已经被 rotate 的慢查询日志文件的数据。用户查询时只需要指定 `TIME` 时间范围即可定位需要解析的慢查询日志文件。如果查询不指定时间范围，则仍然只解析当前的慢查询日志文件，示例如下：
217297

218-
不指定时间范围时，只会解析当前 TiDB 正在写入的慢日志文件的慢查询数据：
298+
不指定时间范围时，只会解析当前 TiDB 正在写入的慢查询日志文件的慢查询数据：
219299

220300
{{< copyable "sql" >}}
221301

@@ -234,7 +314,7 @@ from slow_query;
234314
+----------+----------------------------+----------------------------+
235315
```
236316
237-
指定查询 `2020-03-10 00:00:00` 到 `2020-03-11 00:00:00` 时间范围后，会定位指定时间范围内的慢日志文件后解析慢查询数据：
317+
指定查询 `2020-03-10 00:00:00` 到 `2020-03-11 00:00:00` 时间范围后，会定位指定时间范围内的慢查询日志文件后解析慢查询数据：
238318
239319
{{< copyable "sql" >}}
240320
@@ -257,7 +337,7 @@ where time > '2020-03-10 00:00:00'
257337

258338
> **注意：**
259339
>
260-
> 如果指定时间范围内的慢日志文件被删除，或者并没有慢查询，则查询结果会返回空。
340+
> 如果指定时间范围内的慢查询日志文件被删除，或者并没有慢查询，则查询结果会返回空。
261341
262342
TiDB 4.0 中新增了 [`CLUSTER_SLOW_QUERY`](/information-schema/information-schema-slow-query.md#cluster_slow_query-table) 系统表，用来查询所有 TiDB 节点的慢查询信息，表结构在 `SLOW_QUERY` 的基础上多增加了 `INSTANCE` 列，表示该行慢查询信息来自的 TiDB 节点地址。使用方式和 [`SLOW_QUERY`](/information-schema/information-schema-slow-query.md) 系统表一样。
263343

@@ -468,9 +548,9 @@ select instance, count(*) from information_schema.cluster_slow_query where time
468548
+---------------+----------+
469549
```
470550

471-
### 查询仅出现在异常时间段的慢日志
551+
### 查询仅出现在异常时间段的慢查询日志
472552

473-
假如发现 `2020-03-10 13:24:00` ~ `2020-03-10 13:27:00` 的 QPS 降低或者延迟上升等问题，可能是由于突然出现大查询导致的，可以用下面 SQL 查询仅出现在异常时间段的慢日志，其中 `2020-03-10 13:20:00` ~ `2020-03-10 13:23:00` 为正常时间段。
553+
假如发现 `2020-03-10 13:24:00` ~ `2020-03-10 13:27:00` 的 QPS 降低或者延迟上升等问题，可能是由于突然出现大查询导致的，可以用下面 SQL 查询仅出现在异常时间段的慢查询日志，其中 `2020-03-10 13:20:00` ~ `2020-03-10 13:23:00` 为正常时间段。
474554

475555
{{< copyable "sql" >}}
476556

@@ -521,7 +601,7 @@ min(prev_stmt) |
521601
digest | 24bd6d8a9b238086c9b8c3d240ad4ef32f79ce94cf5a468c0b8fe1eb5f8d03df
522602
```
523603

524-
## 解析其他的 TiDB 慢日志文件
604+
## 解析其他的 TiDB 慢查询日志文件
525605

526606
TiDB 通过 session 变量 `tidb_slow_query_file` 控制查询 `INFORMATION_SCHEMA.SLOW_QUERY` 时要读取和解析的文件，可通过修改改 session 变量的值来查询其他慢查询日志文件的内容：
527607

@@ -531,9 +611,9 @@ TiDB 通过 session 变量 `tidb_slow_query_file` 控制查询 `INFORMATION_SCHE
531611
set tidb_slow_query_file = "/path-to-log/tidb-slow.log"
532612
```
533613

534-
## 用 `pt-query-digest` 工具分析 TiDB 慢日志
614+
## 用 `pt-query-digest` 工具分析 TiDB 慢查询日志
535615

536-
可以用 `pt-query-digest` 工具分析 TiDB 慢日志。
616+
可以用 `pt-query-digest` 工具分析 TiDB 慢查询日志。
537617

538618
> **注意：**
539619
>

0 commit comments

Comments
 (0)