Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

sql: update tidb slow log operation docs #1182

Merged
merged 11 commits into from
Apr 23, 2019
Merged

sql: update tidb slow log operation docs #1182

Show file tree
Hide file tree
Changes from 6 commits
Commits
Show all changes
11 commits
Select commit Hold shift + click to select a range
c583736
sql: update tidb slow log operation
crazycs520 Mar 19, 2019
06ac945
update log
crazycs520 Mar 19, 2019
e8fe9fd
update log
crazycs520 Mar 19, 2019
fcd1aaf
add digest declare
crazycs520 Apr 22, 2019
9cdb982
update eg
crazycs520 Apr 22, 2019
a9d855f
add stats eg
crazycs520 Apr 22, 2019
c17e678
update eg
crazycs520 Apr 22, 2019
c950a81
address comment and add more field
crazycs520 Apr 22, 2019
5602230
add declare for v2.1.8
crazycs520 Apr 23, 2019
a4ae942
address comment
crazycs520 Apr 23, 2019
d117c38
address comment
crazycs520 Apr 23, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 1 addition & 1 deletion op-guide/tidb-config-file.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -57,7 +57,7 @@ TiDB 配置文件比命令行参数支持更多的选项。你可以在 [config/
### `slow-query-file`
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved

+ 慢查询日志的文件名。
+ 默认: ""
+ 默认: "tidb-slow.log"
+ 设置后，慢查询日志会单独输出到该文件。

### `slow-threshold`
Expand Down
211 changes: 162 additions & 49 deletions sql/slow-query.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,81 +9,194 @@ category: user guide

### 获取日志

通过在 TiDB 的日志文件上 grep `SLOW_QUERY` 这个关键字，可以得到执行时间超过 [slow-threshold](../op-guide/tidb-config-file.md#slow-threshold) 的语句日志。

`slow-threshold` 可以通过配置文件修改，默认是 300ms。如果配置了 [slow-query-file](../op-guide/tidb-config-file.md#slow-query-file)，慢查询日志会全部写在这个文件里。
TiDB 会将执行时间超过 [slow-threshold](../op-guide/tidb-config-file.md#slow-threshold) 的语句默认单独输出到 [slow-query-file](../op-guide/tidb-config-file.md#slow-query-file) 文件中 ，并对慢日志的格式做了兼容，可以用 `pt-query-digest` 直接分析慢日志 文件。`slow-threshold` 可以通过配置文件修改，默认是 300ms。`slow-query-file` 默认是 `tidb-slow.log` 。
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved

### 示例

```
2018/08/20 19:52:08.632 adapter.go:363: [warning] [SLOW_QUERY] cost_time:18.647928814s
process_time:1m6.768s wait_time:12m11.212s backoff_time:600ms request_count:2058
total_keys:1869712 processed_keys:1869710 succ:true con:3 user:root@127.0.0.1
txn_start_ts:402329674704224261 database:test table_ids:[31],index_ids:[1],
sql:select count(c) from sbtest1 use index (k_1)
```sql
# Time: 2019-03-18-12:10:19.513961 +0800
# Txn_start_ts: 407078752230047745
# User: root@127.0.0.1
# Conn_ID: 1
# Query_time: 16.479155653
# Process_time: 5.634 Wait_time: 0.002 Request_count: 2 Total_keys: 20002 Process_keys: 20000
# DB: test
# Index_ids: [1]
# Is_internal: false
# Digest: 3635413fe0c8e1aa8307f4f018fe1a9325ea0b97452500106d3f6783fcb65e33
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
select * from t_slim, t_wide where t_slim.c0=t_wide.c0;
```

### 字段解析

#### cost_time

表示执行这个语句花费的时间。只有执行时间超过 slow-threshold 的语句才会输出这个日志。

#### process_time

表示这个语句在 TiKV 的处理时间之和，因为数据会并行的发到 TiKV 执行，这个值可能会超过 cost_time。

#### wait_time

表示这个语句在 TiKV 的等待时间之和，因为 TiKV 的 Coprocessor 线程数是有限的，当所有的 Coprocessor 线程都在工作的时候，请求会排队，当队列中有某些请求耗时很长的时候，后面的请求的等待时间都会增加。

#### backoff_time

表示语句遇到需要重试的错误时在重试前等待的时间，常见的需要重试的错误有以下几种：遇到了 lock、Region 分裂、`tikv server is busy`。

#### request_count

表示这个语句发送的 Coprocessor 请求的数量。

#### total_keys
* `Time`：表示日志打印时间。
* `Txn_start_ts`：表示事务的开始时间戳，也是事务的 ID, 可以用这个值在日志中 grep 出事务相关的日志。
* `User`：表示执行语句的用户名
* `Conn_ID`：表示 connection ID，即 session ID, 可以用类似 `con:3 ` 的关键字在 TiDB 日志中 grep 出 session ID 为 3 的日志。
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
* `Query_time`：表示执行这个语句花费的时间。只有执行时间超过 slow-threshold 的语句才会输出这个日志。
* `Process_time`：执行 SQL 在 TiKV 的处理时间之和，因为数据会并行的发到 TiKV 执行，这个值可能会超过 `Query_time`。
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
* `Wait_time`：表示这个语句在 TiKV 的等待时间之和，因为 TiKV 的 Coprocessor 线程数是有限的，当所有的 Coprocessor 线程都在工作的时候，请求会排队，当队列中有某些请求耗时很长的时候，后面的请求的等待时间都会增加。
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
* `Backoff_time`：表示语句遇到需要重试的错误时在重试前等待的时间，常见的需要重试的错误有以下几种：遇到了 lock、Region 分裂、`tikv server is busy`。
* `Request_count`：表示这个语句发送的 Coprocessor 请求的数量。
* `Total_keys`：表示 Coprocessor 扫过的 key 的数量。
* `Process_keys`：表示 Coprocessor 处理的 key 的数量。相比 total_keys，processed_keys 不包含 MVCC 的旧版本。如果 processed_keys 和 total_keys 相差很大，说明旧版本比较多。
* `DB`：表示当前的 database。
* `Index_ids` ：表示语句涉及到的索引的 ID
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
* `Is_internal`：表示是否是 TiDB 内部 SQL。true 为TiDB 内部执行的SQL, 比如 analyze，load variable 等；false 为用户执行的 SQL 。
* `Digest`： 表示 SQL 语句的指纹
qw4990 marked this conversation as resolved.
Show resolved Hide resolved
* `Query`：表示 SQL 语句。慢日志里面不会打印 `Query`，但映射到内存表后，对应的字段叫 `Query`。

### 慢日志内存映射表
为了方便用 SQL 查询定位慢查询，TiDB 将慢日志内容解析后映射到 `INFORMATION_SCHEMA.SLOW_QUERY` 表中，表中 column 名和慢日志中记录的字段名一一对应 。
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved

表示 Coprocessor 扫过的 key 的数量
```sql
tidb > show create table INFORMATION_SCHEMA.SLOW_QUERY;
+------------+-------------------------------------------------------------+
| Table | Create Table |
+------------+-------------------------------------------------------------+
| SLOW_QUERY | CREATE TABLE `SLOW_QUERY` ( |
| | `Time` timestamp UNSIGNED NULL DEFAULT NULL, |
| | `Txn_start_ts` bigint(20) UNSIGNED DEFAULT NULL, |
| | `User` varchar(64) DEFAULT NULL, |
| | `Conn_ID` bigint(20) UNSIGNED DEFAULT NULL, |
| | `Query_time` double UNSIGNED DEFAULT NULL, |
| | `Process_time` double UNSIGNED DEFAULT NULL, |
| | `Wait_time` double UNSIGNED DEFAULT NULL, |
| | `Backoff_time` double UNSIGNED DEFAULT NULL, |
| | `Request_count` bigint(20) UNSIGNED DEFAULT NULL, |
| | `Total_keys` bigint(20) UNSIGNED DEFAULT NULL, |
| | `Process_keys` bigint(20) UNSIGNED DEFAULT NULL, |
| | `DB` varchar(64) DEFAULT NULL, |
| | `Index_ids` varchar(100) DEFAULT NULL, |
| | `Is_internal` tinyint(1) UNSIGNED DEFAULT NULL, |
| | `Digest` varchar(64) DEFAULT NULL, |
| | `Query` varchar(4096) DEFAULT NULL |
| | ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin |
+------------+-------------------------------------------------------------+
```

#### processed_keys
#### 实现细节

表示 Coprocessor 处理的 key 的数量。相比 total_keys，processed_keys 不包含 MVCC 的旧版本。如果 processed_keys 和 total_keys 相差很大，说明旧版本比较多。
`INFORMATION_SCHEMA.SLOW_QUERY` 表里面的内容是通过实时解析 TiDB 慢日志里面的内容得到的。每次查询这个表时都会去读取慢日志文件里面的内容，然后解析。

#### succ
### 查询 SLOW_QUERY 示例

表示请求是否执行成功
下面示例展示如何通过查询 SLOW_QUERY 表来定位慢查询。

#### con
#### 查询 TopN 的慢查询

表示 connection ID，即 session ID, 可以用类似 `con:3 ` 的关键字在日志中 grep 出 session ID 为 3 的日志。
查询 Top2 的用户慢查询。`Is_internal=false` 表示排除 TiDB 内部的慢查询，只看用户的慢查询。

#### user
```sql
/* 查询所有用户执行的SQL, 且按执行消耗时间排序 */
tidb > select `Query_time`, query from INFORMATION_SCHEMA.`SLOW_QUERY` where `Is_internal`=false 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; |
+--------------+------------------------------------------------------------------+
2 rows in set
Time: 0.012s
```

表示执行语句的用户名
#### 查询 `test` 用户的 TopN 慢查询
```sql
/* 查询 test 用户执行的SQL, 且按执行消耗时间排序*/
tidb > select `Query_time`, query, user from INFORMATION_SCHEMA.`SLOW_QUERY` where `Is_internal`=false and user like "test%" order by `Query_time` desc limit 2;
+-------------+------------------------------------------------------------------+----------------+
| Query_time | query | user |
+-------------+------------------------------------------------------------------+----------------+
| 0.676408014 | select t0.c0, t1.c1 from t_slim t0, t_wide t1 where t0.c0=t1.c1; | test@127.0.0.1 |
+-------------+------------------------------------------------------------------+----------------+
1 row in set
Time: 0.014s
```

#### txn_start_ts
#### 根据 SQL 指纹来查询类似 SQL 的慢查询
如果查询了 TopN 的SQL 后，想查询相同 SQL 指纹的查询，可以用指纹作为过滤条件。
```sql
tidb > select query_time, query,digest from INFORMATION_SCHEMA.`SLOW_QUERY` where `Is_internal`=false order by `Query_time` desc limit 1;
+-------------+-----------------------------+------------------------------------------------------------------+
| query_time | query | digest |
+-------------+-----------------------------+------------------------------------------------------------------+
| 0.558006 | select * from t1 where a=1; | 4751cb6008fda383e22dacb601fde85425dc8f8cf669338d55d944bafb46a6fa |
+-------------+-----------------------------+------------------------------------------------------------------+
1 row in set
Time: 0.007s
tidb > select query, query_time from INFORMATION_SCHEMA.`SLOW_QUERY` where digest="4751cb6008fda383e22dacb601fde85425dc8f8cf669338d55d944bafb46a6fa";
+-----------------------------+-------------+
| query | query_time |
+-----------------------------+-------------+
| select * from t1 where a=1; | 0.558006 |
| select * from t1 where a=2; | 0.313532 |
+-----------------------------+-------------+
2 rows in set
```

表示事务的开始时间戳，也是事务的 ID, 可以用这个值在日志中 grep 出事务相关的日志。
查询统计信息是 pseudo 的慢查询

#### database
```sql
tidb > select query, query_time, stats from INFORMATION_SCHEMA.`SLOW_QUERY` where is_internal=false and stats like('%pseudo%');
+-----------------------------+-------------+---------------------------------+
| query | query_time | stats |
+-----------------------------+-------------+---------------------------------+
| select * from t1 where a=1; | 0.302558006 | t1:pseudo |
| select * from t1 where a=2; | 0.401313532 | t1:pseudo |
| select * from t1 where a>2; | 0.602011247 | t1:pseudo |
| select * from t1 where a>3; | 0.50077719 | t1:pseudo |
| select * from t1 join t2; | 0.931260518 | t1:407872303825682445,t2:pseudo |
+-----------------------------+-------------+---------------------------------+
```

表示当前的 database

#### table_ids

表示语句涉及到的表的 ID

#### index_ids

表示语句涉及到的索引的 ID
#### 解析其他的 TiDB 慢日志文件

#### sql
目前查询 `INFORMATION_SCHEMA.SLOW_QUERY` 只会解析配置文件中 `slow-query-file` 设置的慢日志文件名，默认是 "tidb-slow.log" 。 但如果想要解析其他的日志文件，可以通过设置 session 变量 `tidb_slow_query_file` 为具体的文件路径，然后查询 `INFORMATION_SCHEMA.SLOW_QUERY` 就会按照设置的路径去解析慢日志文件。
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved
```sql
/* 设置慢日志文件路径，方便解析其他的慢日志文件，tidb_slow_query_file 变量的作用域是 session */
mysql test@127.0.0.1:test> set tidb_slow_query_file="/path-to-log/tidb-slow.log"
Query OK, 0 rows affected
Time: 0.001s
```

表示 SQL 语句
#### 不足
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved

`INFORMATION_SCHEMA.SLOW_QUERY` 目前暂时只支持解析一个慢日志文件，如果慢日志文件超过一定大小后被 logrotate 成多个文件了，查询 `INFORMATION_SCHEMA.SLOW_QUERY` 也只会去解析一个文件。后续我们会改善这点。

#### 用 pt-query-digest 工具分析 TiDB 慢日志

可以用 pt-query-digest 工具分析 TiDB 慢日志，下面是示例。
crazycs520 marked this conversation as resolved.
Show resolved Hide resolved

```shell
$ pt-query-digest --report tidb-slow.log
# 320ms user time, 20ms system time, 27.00M rss, 221.32M vsz
# Current date: Mon Mar 18 13:18:51 2019
# Hostname: localhost.localdomain
# Files: tidb-slow.log
# Overall: 1.02k total, 21 unique, 0 QPS, 0x concurrency _________________
# Time range: 2019-03-18-12:22:16 to 2019-03-18-13:08:52
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 218s 10ms 13s 213ms 30ms 1s 19ms
# Query size 175.37k 9 2.01k 175.89 158.58 122.36 158.58
# Commit time 46ms 2ms 7ms 3ms 7ms 1ms 3ms
# Conn ID 71 1 16 8.88 15.25 4.06 9.83
# Process keys 581.87k 2 103.15k 596.43 400.73 3.91k 400.73
# Process time 31s 1ms 10s 32ms 19ms 334ms 16ms
# Request coun 1.97k 1 10 2.02 1.96 0.33 1.96
# Total keys 636.43k 2 103.16k 652.35 793.42 3.97k 400.73
# Txn start ts 374.38E 0 16.00E 375.48P 1.25P 89.05T 1.25P
# Wait time 943ms 1ms 19ms 1ms 2ms 1ms 972us
# Write keys 978 2 477 69.86 463.90 161.64 1.96
# Write size 89.12k 138 43.67k 6.37k 42.34k 14.76k 136.99
.
.
.
```

### 定位问题语句的方法

Expand Down