From fead57abd3257eabf1dee316a81af9c882166e30 Mon Sep 17 00:00:00 2001 From: Ziqian Qin Date: Fri, 18 Mar 2022 14:58:30 +0800 Subject: [PATCH] add a few explanation for slow logs (#8691) --- identify-slow-queries.md | 4 ++-- sql-statements/sql-statement-explain-analyze.md | 16 ++++++++++------ 2 files changed, 12 insertions(+), 8 deletions(-) diff --git a/identify-slow-queries.md b/identify-slow-queries.md index 16963da4f7a8..e3097df7d110 100644 --- a/identify-slow-queries.md +++ b/identify-slow-queries.md @@ -101,11 +101,11 @@ Slow Query 基础信息： * `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_avg`：cop-task 的平均执行时间，包括一些无法统计的等待时间，如 RocksDB 内的 mutex。 * `Cop_proc_p90`：cop-task 的 P90 分位执行时间。 * `Cop_proc_max`：cop-task 的最大执行时间。 * `Cop_proc_addr`：执行时间最长的 cop-task 所在地址。 -* `Cop_wait_avg`：cop-task 的平均等待时间。 +* `Cop_wait_avg`：cop-task 的平均等待时间，包括请求排队和获取 snapshot 时间。 * `Cop_wait_p90`：cop-task 的 P90 分位等待时间。 * `Cop_wait_max`：cop-task 的最大等待时间。 * `Cop_wait_addr`：等待时间最长的 cop-task 所在地址。 diff --git a/sql-statements/sql-statement-explain-analyze.md b/sql-statements/sql-statement-explain-analyze.md index 2596a399b059..2f7bfe57dda9 100644 --- a/sql-statements/sql-statement-explain-analyze.md +++ b/sql-statements/sql-statement-explain-analyze.md @@ -88,12 +88,12 @@ EXPLAIN ANALYZE SELECT * FROM t1; ``` ``` -+-------------------+---------+---------+-----------+---------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------+-----------+------+ -| id | estRows | actRows | task | access object | execution info | operator info | memory | disk | -+-------------------+---------+---------+-----------+---------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------+-----------+------+ -| TableReader_5 | 13.00 | 13 | root | | time:923.459µs, loops:2, cop_task: {num: 4, max: 839.788µs, min: 779.374µs, avg: 810.926µs, p95: 839.788µs, max_proc_keys: 12, p95_proc_keys: 12, rpc_num: 4, rpc_time: 3.116964ms, copr_cache_hit_ratio: 0.00} | data:TableFullScan_4 | 632 Bytes | N/A | -| └─TableFullScan_4 | 13.00 | 13 | cop[tikv] | table:t1 | proc max:0s, min:0s, p80:0s, p95:0s, iters:4, tasks:4 | keep order:false, stats:pseudo | N/A | N/A | -+-------------------+---------+---------+-----------+---------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------+-----------+------+ ++-------------------+----------+---------+-----------+---------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------+-----------+------+ +| id | estRows | actRows | task | access object | execution info | operator info | memory | disk | ++-------------------+----------+---------+-----------+---------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------+-----------+------+ +| TableReader_5 | 10000.00 | 3 | root | | time:278.2µs, loops:2, cop_task: {num: 1, max: 437.6µs, proc_keys: 3, rpc_num: 1, rpc_time: 423.9µs, copr_cache_hit_ratio: 0.00} | data:TableFullScan_4 | 251 Bytes | N/A | +| └─TableFullScan_4 | 10000.00 | 3 | cop[tikv] | table:t1 | tikv_task:{time:0s, loops:1}, scan_detail: {total_process_keys: 3, total_process_keys_size: 111, total_keys: 4, rocksdb: {delete_skipped_count: 0, key_skipped_count: 3, block: {cache_hit_count: 0, read_count: 0, read_byte: 0 Bytes}}} | keep order:false, stats:pseudo | N/A | N/A | ++-------------------+----------+---------+-----------+---------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------+-----------+------+ 2 rows in set (0.00 sec) ``` @@ -255,6 +255,10 @@ commit_txn: {prewrite:48.564544ms, wait_prewrite_binlog:47.821579, get_commit_ts - `write_keys`：事务中写入 `key` 的数量。 - `write_byte`：事务中写入 `key-value` 的总字节数量，单位是 byte。 +### 其它常见执行信息 + +Coprocessor 算子通常包含 `cop_task` 和 `tikv_task` 两部分执行时间信息。前者是 TiDB 端记录的时间，从发出请求到接收回复；后者是 TiKV Coprocessor 算子自己记录的时间。两者相差较大可能说明在等待、gRPC 或网络上耗时较长。 + ## MySQL 兼容性 `EXPLAIN ANALYZE` 是 MySQL 8.0 的功能，但该语句在 MySQL 中的输出格式和可能的执行计划都与 TiDB 有较大差异。