MySQL慢日志体系建设

概述

为啥我的数据库慢的和蜗牛一样？

天呢，我的应用好多查询报超时了，什么情况？

好烦，数据库QPS总是上不来，根本扛不住，怎么办呀？

DBA刚刚又找过来了，说我的SQL查询把数据库打挂了，怎么又是我？
…

或者这些都是万恶的慢SQL造成的。

说到这里，您会认为我应该介绍下SQL该怎么优化的，让您失望了，接下来我将介绍58同城MySQL慢日志是怎么收集统计的；作为DBA，我想在第一时间让您知道：是的，就是您的锅！

MySQL 慢日志介绍

默认情况下，慢查询日志是关闭的，可以通过参数slow_query_log[={0|1}]指定，设置为 1 就是启用慢日志的功能了，参数long_query_time控制着超过多少秒的查询会被记录下来，通过参数log_queries_not_using_indexes也可以将没有使用索引的查询也记录下来，而参数log_output控制着将慢日志保存在文件还是表中。官方文档慢查询日志

下面的设置来自于线上配置

慢日志收集已经打开
(root@(none))>show global variables like 'slow_query_log';
+----------------+-------+
| Variable_name  | Value |
+----------------+-------+
| slow_query_log | ON    |
+----------------+-------+
1 row in set (0.00 sec)
慢日志被写入到文件中
(root@(none))>show global variables like 'log_output';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_output    | FILE  |
+---------------+-------+
1 row in set (0.00 sec)
只要超过0.1s的查询会被记录到慢日志文件中
(root@(none))>show global variables like 'long_query_time';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 0.100000 |
+-----------------+----------+
1 row in set (0.00 sec)
慢日志的文件名为slow.log，如果没有指定绝对路径，默认路径为DATADIR
(root@(none))>show global variables like 'slow_query_log_file';
+---------------------+----------+
| Variable_name       | Value    |
+---------------------+----------+
| slow_query_log_file | slow.log |
+---------------------+----------+
1 row in set (0.01 sec)

收集慢日志

怎么收集慢日志呢，要么使用第三方开源工具，要么自己开发组件。

开源工具较为流行有pt-query-digest,mysqldumpslow, mysqlsla, myprofi, mysql-explain-slow-log, mysqllogfilter等，其中pt-query-digest较为流行，这些工具配合自动化脚本，适合按照一定的时间间隔收集归档慢日志，并生成慢日志报表，若实现实时展示慢sql则较为困难，因此我们采用了自己开发的组件，组件主要实现：

• 具有pt-query-digest的分析统计归档慢日志的功能，

• 具备实时展示慢sql的能力

我们使用的MySQL版本包括percona MySQL的5.5和5.6，以及MySQL社区版5.7和8.0，虽然来自于两家公司，版本跨度较大，但是慢日志格式差异不明显，例如每条慢sql都包括以下内容：

如果采用特定标识符切割，产生一条条完整的慢日志block（例如上图，就是一条block）；然后按照一定的规则将其中有用的信息抽取出来，再将sql语句指纹化，即对where变量做“?”替换生成唯一校验值，就完成慢日志的初步处理。

为了能准实时性查看慢日志详情，我们需要实时解析慢sql，需要解决以下问题：

• 如果用python实现，使用生成器也能完成对单个文件的快速处理，但是python的效率确实让人怀疑；
• 为了控制慢日志文件大小，每天要对慢日志文件进行切割，那么怎么发现新的慢日志文件呢？
• 如果解析工具中间出现故障，重启后会不会重复消费呢？

filebeat是用go开发的轻量级的文件处理工具，filebeat可以按照“# User@Host”切割慢日志文件为block到下游；且能按照一定规则发现新产生的慢日志文件，并能实时记录慢日志解析的位置。因此我们最终解析流程见下图：

组件说明：

• Kafka作为中间消息队列，起到削峰填谷的效果；

• 消费Kafka组件：为自研组件，主要目的是抽取block有用信息，例如：用户、来源ip、库、时间戳、sql语句等，并将sql语句指纹化；

• Elasticsearch：ES可以作为强大的搜索引擎，可以对sql语句按照不同的维度进行分桶统计分析；

生成慢sql报表和实时统计

Fileabeat按照“# User@Host”将慢日志文件切割为block，消费Kafka组件再抽取每个block中有用的信息，并最终作为独立的term存储到ES当中，下图是慢日志mapping详情：

"mappings" : {
      "_doc" : {
        "properties" : {
          "@timestamp" : {
            "type" : "date",
            "format" : "yyyy-MM-dd HH:mm:ss||yyyy-MM-dd||epoch_millis"
          },
          "checksum" : {
            "type" : "keyword"
          },
          "host" : {
            "type" : "keyword",
            "ignore_above" : 256
          },
          "ip" : {
            "type" : "keyword",
            "ignore_above" : 256
          },
          "lock_time" : {
            "type" : "float"
          },
          "port" : {
            "type" : "long"
          },
          "query_time" : {
            "type" : "float"
          },
          "rows_examined" : {
            "type" : "long"
          },
          "rows_sent" : {
            "type" : "long"
          },
          "schema" : {
            "type" : "keyword",
            "ignore_above" : 256
          },
          "sql" : {
            "type" : "text"
          },
          "sql_fingerprint" : {
            "type" : "text"
          },
          "status" : {
            "type" : "long"
          },
          "user" : {
            "type" : "keyword",
            "ignore_above" : 256
          }
        }
      }
    }

下图为解析的单条慢sql详情：

字段说明：

• Time：为慢日志文件的时间戳，转化为ES的data格式
• user：为应用用户，即发起请求的用户
• ip：为应用ip，即发起请求的来源机器
• port：该MySQL实例的端口
• lock_time: 加锁时间
• query_time: 查询时间，这个时间可不包括锁等待的时间哦
• rows_examined：慢sql扫描的行数，本实例展示扫描了10000行
• Rows_sent：发送到客户端的行数，本示例展示发送了10000行
• schema：库名，查询的库名，实际大部分慢日志文件是不带有名的，我们只能通过其他方式解决
• sql：原始sql语句
• sql_fingerprint：sql指纹后生成的sql语句，这个主要用于生成checksum
• checksum：指纹化相同的sql会生成一样的校验值，这个是分桶统计的依据，非常非常的重要

基础数据已经准备妥当，是时候展示我们的成果了。

目前我们通过ES检索分析衍生出两个产品：

• 慢sql报表
• 实时慢sql

慢sql报表

慢sql报表功能在58一直都存在，而且前人做的真的不错；但是使用的是pt-query-digest工具，在改造的过程发现优化空间不大，并最终弃用了。

报表是按照天生成的，并且是T+1的，实时性要求不高，所以可以按照不同维度做很多功能。例如：每个集群慢sql数量趋势图、每天慢sql详情及生成优化建议、每日新增慢sql等，个人负责集群慢sql整体趋势、邮件提醒等，按照不同业务线等级统计慢sql个数、部门之间的对比等。报表功能做的很多，下图只是简单展示：

您负责的业务或许很多，关心的数据库也很多，我们在CDB工作台为您提供了慢SQL总量趋势，当然了您也可以对慢SQL严重的库进行优化。

• 单个集群我们为您提供了一年的慢SQL变化趋势；当然，您也可以重点关注某一天的慢SQL详情
• 或许您只关心具体的某一条sql，例如执行次数，执行时间等，您也可以根据具体情况并结合优化建议进行优化

实时慢sql

实时慢sql充分发挥了ES实时检索分析能力，下图为实时汇总统计，重点部分已经用数字进行了标记

• 您可以按照数据库域名、来源IP、库名、用户名或者SQL编号进行快速检索，我们不仅展示正确的，更给你最需要的；
• 您也可以按照不同的时间间隔进行筛选，例如最近15min、最近一周等；或者任意时间间隔，例如：23:21:21-23:22:45，秒级也是支持的哦
• 条形图为您展示了在您选择的时间范围内慢SQL条数的变化情况，那高高立起的小柱，可能就是一次严重的慢sql堆积，赶快点击小柱看看吧
• 分析统计表为您展示详细的内容，这个表是通过来源IP和SQL编号分组，并按照执行次数从高到底排序
• 我们也为您提供了复制该条SQL的功能，后期我们会把生成的SQL优化建议也会放在这里，敬请期待

有时间您可能就想知道在某个时间点具体发生了什么慢查询，即SQL流水，实时慢SQL也提供了这方面的功能，如下图：

结语：

为了缩减开发时间，我们也使用了部分开愿工具，例如生成sql指纹的sql-calculator和生成sql优化建议的soar等。

另外还有个小问题，由于慢日志文件很多sql没有库名，我们采用了层级上推的方式，查找库名的流程为：单条block-多条block-单个慢日志文件-多个慢日志文件-多个实例满日志文件-手工补录。一般通过多个慢日志文件就能找到库名了，还没有到手工补录的阶段，一旦某个慢sql指纹语与库名绑定，这个映射关系将会固化，下次就不用这么麻烦的查找了。

慢日志体系建设还有很多可以做，例如实时生成sql优化建议、实时解读执行计划，并配合报警将慢sql实时推送相关负责同学等。