TiDB 慢日志解析源码解读
作者: aylen 原文来源:https://tidb.net/blog/5ffcdd1e
TiDB 从 2.1.8 开始,information_schema 中包含了 SLOW_QUERY 表。SLOW_QUERY 表中提供了慢查询相关的信息,其内容通过解析 TiDB 慢查询日志而来,列名和慢日志中的字段名是一一对应。对于慢日志的解析,有很多实现的方法。那我们今天就来看看 TiDB 中慢日志解析是怎么实现的吧。
Slow_query 定义
TiDB 会将执行时间超过 slow-threshold(默认值为 300 毫秒)的语句输出到 slow-query-file(默认值:”tidb-slow.log”)日志文件中,用于帮助用户定位慢查询语句,分析和解决 SQL 执行的性能问题。
从 3.0.5 开始,TiDB 慢日志中引入了执行计划相关信息,故 slow_query 的定义也发生了变化,具体如下:
较之前版本,增加了 SlowLogPlan,用以存储执行计划。
Slow Query 字段含义说明
根据官方文档,一些 Slow Query 的基础字段含义如下:
注意:
慢查询日志中所有时间相关字段的单位都是 “秒”
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 所在地址。
读取慢日志文件
官方文档中提到不支持多多个慢日志文件的的解析,从源码中可以很直观的看出的。
另外,官方文档提到 TiDB 通过 session 变量 tidb_slow_query_file 控制查询 INFORMATION_SCHEMA.SLOW_QUERY 时要读取和解析的文件,可通过修改改 session 变量的值来查询其他慢查询日志文件的内容:
慢日志解析时,获取 session 的信息如下:
慢日志的解析过程
1. 判断是不是慢日志的开始
与 filebeat 类似,通过设定起始字符串,来判断慢日志的开始。使用 setFieldValue 可以将处理的信息赋值给对应的栏位,这块将在下面讲解。慢日志每行的起始值定义可以从 sessionctx/variable/session.go 中获取这些起始值的相关定义,SlowLogStartPrefixStr 的定义是 # Time: ,即慢日志的开始时间,也是慢日志开始的标志。
2. 解析非 SQL 语句相关信息
和判断慢日志开始逻辑类似,通过判断每行的起始信息, 每行的起始标志为 SlowLogRowPrefixStr 的定义如下:
2.1 处理事务相关的信息
举个例子:
当 commit 时,已经超过慢查询的时间,如果只记录 commit,会造成分析慢日志时的困惑,到底是什么 SQL 引起的,通过记录相关的上一条事务来更好的分析慢日志。 对 SlowLogPrevStmtPrefix 定义如下:
2.2 处理慢日志中的其他非 SQL 语句信息
这时处理的是诸如执行时间、CPU 耗时、DB 等信息。
3. 解析 SQL 语句相关信息
判断 SQL 的后缀,进行处理。SlowLogSQLSuffixStr 的定义如下:
4. 数据格式的转换
将经过 SQL 语句经过 setFieldValue 处理后,一段慢日志也就分析完了,下面是数据的转存储过程,将上面简单处理过的数据经过 convertToDatumRow 再次处理以满足 slow_query 的存储需求。同时将 startFlag 设置为 false,以开始新的一段慢日志分析。
以上是慢日志处理的主要过程,下面将对其中涉及的两个主要函数 setFieldValue 和 convertToDatumRow 进行解读。
1.setFieldValue
功能是将解析的数据赋予对应的栏位,同时进行数据类型的转换,其中 ParseTime 将慢日志的时间进行兼容性解析。
2.convertToDatumRow
功能是将赋值后的数据进行类型转换已满足定义需求,同时使用 parsePlan 将执行计划进行解析以便更方便存储。
定位问题语句的方法(官方推荐)
并不是所有 SLOW_QUERY 的语句都是有问题的。会造成集群整体压力增大的,是那些 process_time 很大的语句。wait_time 很大,但 process_time 很小的语句通常不是问题语句,是因为被问题语句阻塞,在执行队列等待造成的响应时间过长。
admin show slow
命令
除了获取 TiDB 日志,还有一种定位慢查询的方式是通过 admin show slow
SQL 命令:
recent N
会显示最近的 N 条慢查询记录,例如:
top N
则显示最近一段时间(大约几天)内,最慢的查询记录。如果指定 internal
选项,则返回查询系统内部 SQL 的慢查询记录;如果指定 all
选项,返回系统内部和用户 SQL 汇总以后的慢查询记录;默认只返回用户 SQL 中的慢查询记录。
由于内存限制,保留的慢查询记录的条数是有限的。当命令查询的 N
大于记录条数时,返回的结果记录条数会小于 N
。
输出内容详细说明,如下:
定位问题语句的方法(个人经验)
虽然官方提供了简便的定位慢查询的方法,但因其保留时间短,不便于后续的慢日志的追踪和预警。因此建议大家可以基于上述的慢日志解析原理,构建自己的慢日志系统和工具。下图是常见的慢日志分析系统架构:
包含采集、消息流、分析、展示四大模块。其中采集模块一般是使用 filebeat,当然也可以采用其他的方案,建议将对应的宿主机 IP 和 Port 信息一起采集;消息流模块一般使用 kafka;分析模块就可以基于官方的源码进行魔改,如果在采集时包含了 IP+Port 可以在这一步结合元数据系统进行数据的进一步规整和区分;展示模块中最简单的方案就是基于 es+kibana,至于其他的需要结合实际的使用场景要规划,如 Prometheus 提供的一套解决方案。
以上是抛砖引玉,欢迎大家吐槽。
版权声明: 本文为 InfoQ 作者【TiDB 社区干货传送门】的原创文章。
原文链接:【http://xie.infoq.cn/article/873c51291e1c90b7077baac2f】。文章转载请联系作者。
评论