TiDB 慢查询日志分析

2024-03-08
北京
本文字数：3051 字
阅读完需：约 10 分钟

作者： longzhuquan 原文来源：https://tidb.net/blog/90e27aa0

背景

TiDB 中的慢查询日志是一项关键的性能监控工具，其主要作用在于协助数据库管理员追踪执行时间较长的 SQL 查询语句。通过记录那些超过设定阈值的查询，慢查询日志为性能优化提供了关键的线索，有助于发现潜在的性能瓶颈，优化索引以及重构查询语句，从而提升数据库的整体性能。本文主要介绍了 TiDB 中慢查询日志的功能，并探讨了常用的慢查询日志分析方法。

慢查询相关参数

tidb_enable_slow_log ：用于控制是否开启 slow log 功能。
tidb_slow_log_threshold：设置慢日志的阈值，执行时间超过阈值的 SQL 语句将被记录到慢日志中。默认值是 300 ms。
tidb_query_log_max_len：设置慢日志记录 SQL 语句的最大长度。默认值是 4096 byte。
tidb_redact_log：设置慢日志记录 SQL 时是否将用户数据脱敏用 ? 代替。默认值是 0，即关闭该功能。
tidb_enable_collect_execution_info：设置是否记录执行计划中各个算子的物理执行信息，默认值是 1。

慢查询日志原理

TiDB 的慢查询日志原理与 Mysql 一致，在每条 SQL 执行结束时，并且执行时间超过慢日志阈值时，会把 SQL 执行相关信息记录到慢日志中，同样的 SQL 多次执行超过阈值都会记录。

分析慢查询日志

由于 TiDB 采用存算分离架构的分布式数据库，在这种架构下，每个 TiDB Server 节点都会产生慢日志。为方便查询慢日志，TiDB 提供了内存映射表 INFORMATION_SCHEMA.SLOW_QUERY，并在 TiDB Dashboard 中提供了专门的界面用于搜索和查看慢查询日志。官方文档中也提供了多种常见的慢查询日志查询语句，参考：慢查询日志。

然而，在系统高负载或异常情况下，短时间内生成过多慢 SQL 导致慢 SQL 变得难以分析，这也是像 MySQL 等数据库提供慢日志分析工具的原因，例如 mysqldumpslow、pt-query-digest 等工具。这些工具通常以某种聚合的方式输出结果，使结果更加清晰易懂。借鉴这些工具的思路，笔者开发了一条常用的慢日志分析 SQL，以更便捷地处理慢查询日志。

慢日志聚合查询 SQL

-- 慢查询日志，聚合查询WITH ss AS(SELECT s.Digest ,s.Plan_digest,count(1) exec_count,sum(s.Succ) succ_count,round(sum(s.Query_time),4) sum_query_time,round(avg(s.Query_time),4) avg_query_time,sum(s.Total_keys) sum_total_keys,avg(s.Total_keys) avg_total_keys,sum(s.Process_keys) sum_process_keys,avg(s.Process_keys) avg_process_keys,min(s.`Time`) min_time,max(s.`Time`) max_time,round(max(s.Mem_max)/1024/1024,4) Mem_max,round(max(s.Disk_max)/1024/1024,4) Disk_max,avg(s.Result_rows) avg_Result_rows,max(s.Result_rows) max_Result_rows,sum(Plan_from_binding) Plan_from_bindingFROM information_schema.cluster_slow_query sWHERE s.time>=adddate(now(),INTERVAL -1 DAY)AND s.time<=now()AND s.Is_internal =0-- AND UPPER(s.query) NOT LIKE '%ANALYZE TABLE%'-- AND UPPER(s.query) NOT LIKE '%DBEAVER%'-- AND UPPER(s.query) NOT LIKE '%ADD INDEX%'-- AND UPPER(s.query) NOT LIKE '%CREATE INDEX%'GROUP BY s.Digest ,s.Plan_digestORDER BY sum(s.Query_time) descLIMIT 35)SELECT ss.Digest,         -- SQL Digestss.Plan_digest,           -- PLAN Digest(SELECT s1.Query FROM information_schema.cluster_slow_query s1 WHERE s1.Digest=ss.digest AND s1.time>=ss.min_time AND s1.time<=ss.max_time LIMIT 1) query,  -- SQL文本(SELECT s2.plan FROM information_schema.cluster_slow_query s2 WHERE s2.Plan_digest=ss.plan_digest AND s2.time>=ss.min_time AND s2.time<=ss.max_time LIMIT 1) plan, -- 执行计划ss.exec_count,            -- SQL总执行次数ss.succ_count,            -- SQL执行成功次数ss.sum_query_time,        -- 总执行时间（秒）ss.avg_query_time,        -- 平均单次执行时间（秒）ss.sum_total_keys,        -- 总扫描key数量ss.avg_total_keys,        -- 平均单次扫描key数量ss.sum_process_keys,      -- 总处理key数量ss.avg_process_keys,      -- 平均单次处理key数量ss.min_time,              -- 查询时间段内第一次SQL执行结束时间ss.max_time,              -- 查询时间段内最后一次SQL执行结束时间ss.Mem_max,               -- 单次执行中内存占用最大值（MB）ss.Disk_max,              -- 单次执行中磁盘占用最大值（MB）ss.avg_Result_rows,       -- 平均返回行数ss.max_Result_rows,       -- 单次最大返回行数ss.Plan_from_binding      -- 走SQL binding的次数FROM ss;

复制代码

这个 SQL 是笔者常用的一条查询语句，大家可以根据个人需要灵活地调整排序字段、查询字段和查询条件，以满足不同场景下的分析需求。

在这个 SQL 中，query 和 plan 字段是使用标量子查询的方式获取。经过测试，这种写法相比直接使用 group by，能够节省大量内存，所以能够分析更长时间段的慢查询。

既然是聚合查询，为什么不直接用statements_summary_history表呢？笔者觉得有三点原因，一是statements_summary_history由于本身是半小时的聚合数据，在应对短时间段的性能分析时可能不够精细。二是早期版本的statements_summary_history 是纯内存表，可能由于 TiDB Server OOM 重启而导致数据丢失，而慢查询日志是存储在文件中的，因此 TiDB Server OOM 重启不会导致慢查询日志丢失。三是statements_summary_history有容量限制，记录的 SQL 可能被驱逐出去，而慢查询日志默认记录超过 300 毫秒的查询，已满足分析需求了。

单条 SQL 执行历史

SELECT date_format(adddate(s.Time,interval s.Query_time second),'%Y-%m-%d %H') sql_exec_start,count(1) exec_cnt,sum(s.Succ) succ_cnt,count(distinct s.Plan_digest) plan_cnt,case when count(distinct s.Plan_digest)<5 then group_concat(distinct substr( s.Plan_digest,1,4)) else null end plan_digest,round(sum(s.Query_time),4) sum_q_time,round(avg(s.Query_time),4) avg_q_time,sum(s.Total_keys) sum_t_keys,round(avg(s.Total_keys),4) avg_t_keys,sum(s.Process_keys) sum_p_keys,avg(s.Process_keys) avg_p_keys,round(max(s.Mem_max/1024/1024),2) Mem_max_m,round(max(s.Disk_max/1024/1024),2) Disk_max_m,round(avg(s.Result_rows),4) avg_rows,max(s.Result_rows) max_rows,sum(Plan_from_binding) PFBfrom information_schema.cluster_slow_query swhere s.digest='a0adeeb79b71315ac13a77f3f11162106b5ec7b48212cf17c20c754263ab9228'and time>=adddate(now(),interval -3 day)and time<=now()group by date_format(adddate(s.Time,interval s.Query_time second),'%Y-%m-%d %H')order by 1 desc;