<commit_before>---
title: 慢查询日志
category: how-to
aliases: ['/docs-cn/sql/slow-query/']
---

# 慢查询日志

TiDB 会将执行时间超过 [slow-threshold](/reference/configuration/tidb-server/configuration-file.md#slow-threshold)（默认值为 300 毫秒）的语句输出到 [slow-query-file](/reference/configuration/tidb-server/configuration-file.md#slow-query-file)（默认值："tidb-slow.log"）日志文件中，用于帮助用户定位慢查询语句，分析和解决 SQL 执行的性能问题。

## 日志示例

```sql
# Time: 2019-08-14T09:26:59.487776265+08:00
# Txn_start_ts: 410450924122144769
# User: root@127.0.0.1
# Conn_ID: 3086
# Query_time: 1.527627037
# Process_time: 0.07 Request_count: 1 Total_keys: 131073 Process_keys: 131072 Prewrite_time: 0.335415029 Commit_time: 0.032175429 Get_commit_ts_time: 0.000177098 Local_latch_wait_time: 0.106869448 Write_keys: 131072 Write_size: 3538944 Prewrite_region: 1
# DB: test
# Is_internal: false
# Digest: 50a2e32d2abbd6c1764b1b7f2058d428ef2712b029282b776beb9506a365c0f1
# Stats: t:pseudo
# Num_cop_tasks: 1
# Cop_proc_avg: 0.07 Cop_proc_p90: 0.07 Cop_proc_max: 0.07 Cop_proc_addr: 172.16.5.87:20171
# Cop_wait_avg: 0 Cop_wait_p90: 0 Cop_wait_max: 0 Cop_wait_addr: 172.16.5.87:20171
# Mem_max: 525211
# Succ: false
insert into t select * from t;
```

## 字段含义说明

> 注：慢查询日志中所有时间相关字段的单位都是 **“秒”**

Slow Query 基础信息：

* `Time`：表示日志打印时间。
* `Query_time`：表示执行这个语句花费的时间。
* `Query`：表示 SQL 语句。慢日志里面不会打印 `Query`，但映射到内存表后，对应的字段叫 `Query`。
* `Digest`：表示 SQL 语句的指纹。
* `Txn_start_ts`：表示事务的开始时间戳，也是事务的唯一 ID，可以用这个值在 TiDB 日志中查找事务相关的其他日志。
* `Is_internal`：表示是否为 TiDB 内部的 SQL 语句。`true` 表示 TiDB 系统内部执行的 SQL 语句，`false` 表示用户执行的 SQL 语句。
* `Index_ids`：表示语句涉及到的索引的 ID。
* `Succ`：表示语句是否执行成功。
* `Backoff_time`：表示语句遇到需要重试的错误时在重试前等待的时间，常见的需要重试的错误有以下几种：遇到了 lock、Region 分裂、`tikv server is busy`。

和内存使用相关的字段：

* `Memory_max`：表示执行期间 TiDB 使用的最大内存空间，单位为 byte。

和 SQL 执行的用户相关的字段：

* `User`：表示执行语句的用户名。
* `Conn_ID`：表示用户的链接 ID，可以用类似 `con:3` 的关键字在 TiDB 日志中查找该链接相关的其他日志。
* `DB`：表示执行语句时使用的 database。

和 TiKV Coprocessor Task 相关的字段：

* `Request_count`：表示这个语句发送的 Coprocessor 请求的数量。
* `Total_keys`：表示 Coprocessor 扫过的 key 的数量。
* `Process_time`：执行 SQL 在 TiKV 的处理时间之和，因为数据会并行的发到 TiKV 执行，这个值可能会超过 `Query_time`。
* `Wait_time`：表示这个语句在 TiKV 的等待时间之和，因为 TiKV 的 Coprocessor 线程数是有限的，当所有的 Coprocessor 线程都在工作的时候，请求会排队；当队列中有某些请求耗时很长的时候，后面的请求的等待时间都会增加。
* `Process_keys`：表示 Coprocessor 处理的 key 的数量。相比 total_keys，processed_keys 不包含 MVCC 的旧版本。如果 processed_keys 和 total_keys 相差很大，说明旧版本比较多。
* `Cop_proc_avg`：cop-task 的平均执行时间。
* `Cop_proc_p90`：cop-task 的 P90 分位执行时间。
* `Cop_proc_max`：cop-task 的最大执行时间。
* `Cop_proc_addr`：执行时间最长的 cop-task 所在地址。
* `Cop_wait_avg`：cop-task 的平均等待时间。
* `Cop_wait_p90`：cop-task 的 P90 分位等待时间。
* `Cop_wait_max`：cop-task 的最大等待时间。
* `Cop_wait_addr`：等待时间最长的 cop-task 所在地址。

## 慢日志内存映射表

用户可通过查询 `INFORMATION_SCHEMA.SLOW_QUERY` 表来查询慢查询日志中的内容，表中列名和慢日志中字段名一一对应，表结构可查看 [Information Schema](reference/system-databases/information-schema/#information-schema) 中关于 `SLOW_QUERY` 表的介绍。

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

## 查询 `SLOW_QUERY` 示例

### 搜索 Top N 的慢查询

查询 Top 2 的用户慢查询。`is_internal=false` 表示排除 TiDB 内部的慢查询，只看用户的慢查询：

{{< copyable "sql" >}}

```sql
select query_time, query
from information_schema.slow_query
where is_internal = false  -- 排除 TiDB 内部的慢查询 SQL
order by query_time desc
limit 2;
```

输出样例：

```
+--------------+------------------------------------------------------------------+
| query_time   | query                                                            |
+--------------+------------------------------------------------------------------+
| 12.77583857  | select * from t_slim, t_wide where t_slim.c0=t_wide.c0;          |
|  0.734982725 | select t0.c0, t1.c1 from t_slim t0, t_wide t1 where t0.c0=t1.c0; |<commit_msg>fix dead link, the third time<commit_after>---
title: 慢查询日志
category: how-to
aliases: ['/docs-cn/sql/slow-query/']
---

# 慢查询日志

TiDB 会将执行时间超过 [slow-threshold](/reference/configuration/tidb-server/configuration-file.md#slow-threshold)（默认值为 300 毫秒）的语句输出到 [slow-query-file](/reference/configuration/tidb-server/configuration-file.md#slow-query-file)（默认值："tidb-slow.log"）日志文件中，用于帮助用户定位慢查询语句，分析和解决 SQL 执行的性能问题。

## 日志示例

```sql
# Time: 2019-08-14T09:26:59.487776265+08:00
# Txn_start_ts: 410450924122144769
# User: root@127.0.0.1
# Conn_ID: 3086
# Query_time: 1.527627037
# Process_time: 0.07 Request_count: 1 Total_keys: 131073 Process_keys: 131072 Prewrite_time: 0.335415029 Commit_time: 0.032175429 Get_commit_ts_time: 0.000177098 Local_latch_wait_time: 0.106869448 Write_keys: 131072 Write_size: 3538944 Prewrite_region: 1
# DB: test
# Is_internal: false
# Digest: 50a2e32d2abbd6c1764b1b7f2058d428ef2712b029282b776beb9506a365c0f1
# Stats: t:pseudo
# Num_cop_tasks: 1
# Cop_proc_avg: 0.07 Cop_proc_p90: 0.07 Cop_proc_max: 0.07 Cop_proc_addr: 172.16.5.87:20171
# Cop_wait_avg: 0 Cop_wait_p90: 0 Cop_wait_max: 0 Cop_wait_addr: 172.16.5.87:20171
# Mem_max: 525211
# Succ: false
insert into t select * from t;
```

## 字段含义说明

> 注：慢查询日志中所有时间相关字段的单位都是 **“秒”**

Slow Query 基础信息：

* `Time`：表示日志打印时间。
* `Query_time`：表示执行这个语句花费的时间。
* `Query`：表示 SQL 语句。慢日志里面不会打印 `Query`，但映射到内存表后，对应的字段叫 `Query`。
* `Digest`：表示 SQL 语句的指纹。
* `Txn_start_ts`：表示事务的开始时间戳，也是事务的唯一 ID，可以用这个值在 TiDB 日志中查找事务相关的其他日志。
* `Is_internal`：表示是否为 TiDB 内部的 SQL 语句。`true` 表示 TiDB 系统内部执行的 SQL 语句，`false` 表示用户执行的 SQL 语句。
* `Index_ids`：表示语句涉及到的索引的 ID。
* `Succ`：表示语句是否执行成功。
* `Backoff_time`：表示语句遇到需要重试的错误时在重试前等待的时间，常见的需要重试的错误有以下几种：遇到了 lock、Region 分裂、`tikv server is busy`。

和内存使用相关的字段：

* `Memory_max`：表示执行期间 TiDB 使用的最大内存空间，单位为 byte。

和 SQL 执行的用户相关的字段：

* `User`：表示执行语句的用户名。
* `Conn_ID`：表示用户的链接 ID，可以用类似 `con:3` 的关键字在 TiDB 日志中查找该链接相关的其他日志。
* `DB`：表示执行语句时使用的 database。

和 TiKV Coprocessor Task 相关的字段：

* `Request_count`：表示这个语句发送的 Coprocessor 请求的数量。
* `Total_keys`：表示 Coprocessor 扫过的 key 的数量。
* `Process_time`：执行 SQL 在 TiKV 的处理时间之和，因为数据会并行的发到 TiKV 执行，这个值可能会超过 `Query_time`。
* `Wait_time`：表示这个语句在 TiKV 的等待时间之和，因为 TiKV 的 Coprocessor 线程数是有限的，当所有的 Coprocessor 线程都在工作的时候，请求会排队；当队列中有某些请求耗时很长的时候，后面的请求的等待时间都会增加。
* `Process_keys`：表示 Coprocessor 处理的 key 的数量。相比 total_keys，processed_keys 不包含 MVCC 的旧版本。如果 processed_keys 和 total_keys 相差很大，说明旧版本比较多。
* `Cop_proc_avg`：cop-task 的平均执行时间。
* `Cop_proc_p90`：cop-task 的 P90 分位执行时间。
* `Cop_proc_max`：cop-task 的最大执行时间。
* `Cop_proc_addr`：执行时间最长的 cop-task 所在地址。
* `Cop_wait_avg`：cop-task 的平均等待时间。
* `Cop_wait_p90`：cop-task 的 P90 分位等待时间。
* `Cop_wait_max`：cop-task 的最大等待时间。
* `Cop_wait_addr`：等待时间最长的 cop-task 所在地址。

## 慢日志内存映射表

用户可通过查询 `INFORMATION_SCHEMA.SLOW_QUERY` 表来查询慢查询日志中的内容，表中列名和慢日志中字段名一一对应，表结构可查看 [Information Schema](reference/system-databases/information-schema.md#information-schema) 中关于 `SLOW_QUERY` 表的介绍。

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

## 查询 `SLOW_QUERY` 示例

### 搜索 Top N 的慢查询

查询 Top 2 的用户慢查询。`is_internal=false` 表示排除 TiDB 内部的慢查询，只看用户的慢查询：

{{< copyable "sql" >}}

```sql
select query_time, query
from information_schema.slow_query
where is_internal = false  -- 排除 TiDB 内部的慢查询 SQL
order by query_time desc
limit 2;
```

输出样例：

```
+--------------+------------------------------------------------------------------+
| query_time   | query                                                            |
+--------------+------------------------------------------------------------------+
| 12.77583857  | select * from t_slim, t_wide where t_slim.c0=t_wide.c0;          |
|  0.734982725 | select t0.c0, t1.c1 from t_slim t0, t_wide t1 where t0.c0=t1.c0; |
{'fraction_non_alphanumeric': 0.1638332876336715, 'fraction_numerical': 0.0745818480943241, 'mean_word_length': 4.286231884057971, 'pattern_counts': {'":': 0, '<': 5, '<?xml version=': 0, '>': 9, 'https://': 0, 'lorem ipsum': 0, 'www.': 0, 'xml': 0}, 'pii_count': 6, 'substrings_counts': 0, 'word_list_counts': {'cursed_substrings.json': 5, 'profanity_word_list.json': 0, 'sexual_word_list.json': 0, 'zh_pornsignals.json': 0}}
{'dir': 'git-commits-cleaned', 'id': '5927755', 'n_tokens_mistral': 4331, 'n_tokens_neox': 4354, 'n_words': 563}