酷应用

TiDB 慢日志在伴鱼的实践

百家作者：PingCAP 2021-09-14 23:42:54

作者简介

刘江，伴鱼英语数据库负责人，TUG 2020 年度 MOA。负责伴鱼数据库运维、大数据运维以及数据库平台化建设。

本文来自于伴鱼英语 DBA 组负责人刘江在「能量钛」第二期活动的分享，刘江为大家分享了 TiDB 慢日志在伴鱼的实践。本文将从以下三个方面展开：

第一部分是背景与需求，首先介绍伴鱼做 TiDB 慢日志系统的背景，以及基于这个背景，要把慢日志系统做成什么样子；
第二部分介绍下慢日志系统具体是怎么做的；
第三部分通过几个线上案例，看看慢日志系统是如何定位线上问题的。

背景与需求

今年上半年，阿里云发布了新一代 DAS（数据库自治服务）服务，里面谈到数据库的问题，90% 以上的问题都是来源于数据库的异常请求。其实在我们日常的数据库问题场景，大部分的问题也都是异常 SQL 请求，像数据库的 bug 或者是机器导致的故障问题，平时遇到还是相对较少的。对于异常 SQL 的定位，数据库的慢日志分析，是一种特别有效的手段。

那么我们在平时利用慢日志分析问题的时候，会有哪些痛点？在做慢日志系统之前，集群的慢日志是分布在多台机器上面的，如果数据库出现了问题，就需要登录到多台机器一台台的去分析，问题处理的效率很低。特别是当集群规模特别大的时候，基本上没办法去快速定位问题。

当然，TiDB 在 4.0 版本支持了 Dashboard，我们可以通过 Dashboard 查看整个集群的慢日志信息，比如最近 15 分钟的或者最近半个小时的慢日志。但当系统真正出现问题的时候，慢日志会特别多，Dashboard 会面临计算加载等性能问题，同时 Dashboard 不支持检索和分析统计，这不利于我们快速定位到异常 SQL。

TiDB 系统库自带了一张表（INFORMATION_SCHEMA.SLOW_QUERY）来实时存储慢日志，我们也可以通过它来定位异常SQL，但这张表是一个关系型的表，本身是没有索引的，当日志量特别大的时候，多维检索和分析是特别慢的。同时，对于关系型表的多维检索和分析统计，也不是它所擅长的。

基于以上的痛点，伴鱼的慢日志系统需要满足以下几个需求：

首先，就是慢日志集中式收集，能够把线上多个集群甚至几十个集群的慢日志全部收拢在一起，便于集中分析，这样做入口就统一了。
其次，要保证收集的慢日志是准实时的。因为如果收集的慢日志延迟太大的话，对于处理线上问题和分析问题是没有帮助的。
然后，慢日志可以检索和统计分析。因为当出现问题的时候慢日志是特别多的，这个时候如果能够检索和统计分析的话，就可以快速定位到异常 SQL。
最后，慢日志系统需要支持监控和告警。

系统详解

基于以上的背景和需求，我们来看一下伴鱼的慢日志系统是怎么做的。

系统架构

伴鱼慢日志系统整体架构，如下图所示。我们在 TiDB Server 机器初始化时部署了 Filebeat 组件，通过它把采集的慢日志，写入到 Kafka，同时打上机器 IP 信息。然后通过 logstash 解析出我们关注的字段，存储到 ES。ES 本身是一个搜索引擎，做数据的分析和统计，速度是特别快的。同时我们通过 Kibana 查看 ES 里的慢日志数据，做可视化的统计和检索。

当然，慢日志系统还有一种架构，如下图所示。Clickhouse 是最近几年比较火的分析型数据库，有些公司通过把监控数据发送到 Clickhouse，做实时监控和告警分析。我们可以用 Flink 替换 logstash 组件，通过简单的计算，把慢日志数据写入到 Clickhouse。

因为伴鱼的慢日志系统做得比较早，所以采用的是 ELK 的架构。

首先，Filebeat 足够轻量。我们在线上对几百兆文件做过解析测试，结论是对数据库的性能基本上没有影响。
其次，当线上出现问题时，瞬时的日志量是特别大的，如果把慢日志直接写入到 Logstash，会对 Logstash 机器负载造成冲击，所以通过 Kafka 来消峰。
当 Logstash 解析慢日志的时候，应尽量少用模糊匹配的规则。因为用模糊匹配的规则去解析慢日志，会导致机器 CPU 飙高的问题。
然后，ES 索引本身就是 Schema Free 的，然后加上倒排索引这种数据结构，这种特性非常适合统计分析类场景。
同时，通过 Kibana 做可视化检索和统计分析。
最后，我们每 2 分钟读取一次 ES 的慢日志数据，做监控报警。

日志采集

接下来看一下每个组件的细节，左边是 Filebeat 采集的配置，如下图所示。我们在部署 Filebeat 的时候，会把部署机器的 IP 给传进去，这样在后期统计的时候，就知道慢日志是来源于哪台机器。然后右边是 Kafka 的配置，数据收集好之后，会发送到 Kafka 集群。

下面是一条 TiDB 慢日志的示例，格式是这样的。

慢日志以 Time 开头，带有 Query_time，Total_keys，Process_keys，DB 等字段，最后还有 SQL 的信息。这条慢日志在通过 Filebeat 的采集之后，会变成下面这样的一行文本，如下图所示。如果把这行文本直接存到 ES 的话，是没办法去做检索和统计分析的。

字段筛选

一条文本没法做统计分析和多维检索的，如果我们要做，就需要把这行文本里面的字段解析出来，那么我们关注哪些字段呢？首先来看一下 MySQL 5.7 的慢日志，如下图所示。我们在处理 MySQL 故障的时候，首先会看一条 SQL 的查询时间，如果该 SQL 查询时间比较长，我们认为它可能会是导致线上问题的原因。

但是当线上请求量比较大的时候，查询时间长并不能代表它就是引发问题的根本原因，还要结合其它关键字段来综合分析。比如慢日志里一个特别重要的关键字 Rows_examined，Rows_examined 代表了数据逻辑扫描的行数，通常我们通过 Query_time 和 Rows_examined 综合分析，才可以定位问题 SQL。

接下来，我们看一下 TiDB 的慢日志。首先来看一下 TiDB 3.0.13 走 KV 接口的慢日志，如下图所示。这里有一些比较重要的关键字，比如说 Query_time，DB，SQL 和 Prewrite_time，这些关键字对于定位线上问题是很有帮助的。

下面是另外一种格式的 TiDB 3.0.13 的慢日志，它是走 DistSQL 接口的，如下图所示。

它除了把 Query_time、Total_keys 同时打印出来之后，还有 Index_names，代表这条 SQL 有没有走索引，同时 Index_names 字段里面还有表名等信息。

看完了 TiDB 3.0.13 的慢日志，我们再来看一下 TiDB 4.0.13 的慢日志，慢日志内容相比 TiDB 3.0.13 版本又增加了一些字段，比如 KV_total，PD_total，Backoff_total 等信息。

通过上面的慢日志，我们可以发现其中包含了很多关键信息，我们甚至可以看到请求慢在数据库的哪个环节。如果我们把慢日志收集起来，通过某些关系进行检索，甚至聚合，对于发现问题是很有帮助的。

在伴鱼，我们关注的 TiDB 慢日志字段主要有以下几个：

TiDB IP：在部署 Filebeat 的时候，会把机器的 IP 给传进去。有了这个 IP，我们可以知道日志的来源以及按照 IP 的维度进行统计；
DB：执行语句时使用的 DATABASE。我们可以按照 DB 维度进行统计，同时也可以通过内部系统将 DB 和具体的数据库集群映射起来；
TABLE：有些慢日志是可以解析出表名的，可按照表的维度进行统计；
IDX_NAME：除 Insert 语句和走 KV 接口的语句外，慢日志信息记录了语句有没有走索引；
TOTAL_KEYS：Coprocessor 扫过的 Key 的数量；
PROCESS_KEYS：Coprocessor 处理的 Key 的数量；
QUERY_TIME：语句执行的时间；
SQL：具体的 SQL 语句。

字段解析

通过 Logstash 的 Grok 语法将一条慢日志所需要的字段解析出来，如下图所示。

统计分析

下面这个图是我们所有集群在最近 30 分钟之内的慢日志情况。我们通过 Kibana，可以看到慢日志的总条数，可以通过 DB、Quwry_time、Total_keys 来进行检索，还可以按 DB、Table、IP 等维度进行统计。这样能够极大地提高定位问题 SQL 的效率。

除了通过 Kibana 进行可视化检索和聚合之外，我们内部平台系统也会通过慢日志的各种维度去进行聚合和排序，聚合维度包括集群、库、表、IP和操作类型等，排序规则可以按照总耗时，平均耗时，最大耗时和日志条数等维度。我们可以定期向研发发送慢日志报表。

监控告警

除了可视化检索和统计分析之外，我们还对慢日志做了监控和告警，如下图所示。通过统计每个库下的慢 SQL 条数，每个库设置两种告警规则。比如说 advertising 这个库，通用的规则是执行时间超过 200 毫秒，告警阀值达到 5 条的会告警。

但是我们发现线上也存在执行频率特别低，但是执行时间特别长的情况，就没办法通过通用的规则去覆盖。所以后面又加了一条规则：执行时间超过 500 毫秒，告警阀值达到 2 条就告警。这样对于线上的慢 SQL 就基本上全覆盖了。

告警信息，如下图所示。可以看一下左边的这张图，我们采集了慢日志的 DB 字段，通过内部系统把 DB 和数据库集群关联起来，我们可以看到慢日志发生在哪个集群，哪个库。慢日志产生的时候，这些慢日志超过了多少阀值，总的 SQL 执行时间以及平均时间等信息。通过这样的慢日志告警信息，我们能在短时间内判断问题 SQL 对线上的冲击有多大。

案例分享

讲完了慢日志系统是怎么做的，接下来看一下我们是如何通过慢日志系统去发现线上问题。

第一个案例，如下图所示。我们在某天发现集群的 Coprocessor CPU 上去了，同时对应着右边的延时也上去了，通过慢日志系统很快就能发现问题 SQL，它的 Total_keys 和 Process_keys 耗得比较多，另外它的 index_name 是空的，说明它没有走到索引。我们通过给这条 SQL 加上索引，性能问题就快速地解决了。