数据库系列之MySQL和TiDB中慢日志分析

慢日志主要用来记录在数据库中执行时间超过指定时间的SQL语句。通过慢查询日志,可以查找出哪些语句的执行效率低,以便进行优化。本文简要介绍了MySQL和TiDB中的慢日志结构,通过横向对比加深对分布式数据库慢日志结构的理解。


1、MySQL中的慢日志

1.1 MySQL慢日志介绍

慢日志主要用来记录在数据库中执行时间超过指定时间的SQL语句。通过慢查询日志,可以查找出哪些语句的执行效率低,以便进行优化。默认情况下,MySQL并没有开启慢日志,可以通过修改slow_query_log参数来打开慢日志。与慢日志相关的参数介绍如下:

[外链图片转存失败,源站可能有防盗链机制,建议将图片保存下来直接上传(img-pTUaGfEA-1635052662407)(https://note.youdao.com/favicon.ico)]

一般情况下,我们只需开启慢日志记录,配置下阈值时间,其余参数可按默认配置。在实际生产环境中可以根据需要进行调整,通常设置为long_query_time为100ms。

1.2 慢日志分析工具
1.2.1 开启慢查询

默认情况下slow_query_log的值为OFF,表示慢查询日志是禁用的,可以通过设置slow_query_log的值来开启。下面这种修改方法是临时开启慢查询,不需要重启数据库,但是重启mysql后慢查询失效。如果需要重启后生效,需要修改配置文件。

mysql> show variables like 'slow_query%';
+---------------------+-----------------------------------------------+
| Variable_name       | Value                                         |
+---------------------+-----------------------------------------------+
| slow_query_log      | OFF                                           |
| slow_query_log_file | /usr/local/mysql/data/tango-GDB-DB01-slow.log |
+---------------------+-----------------------------------------------+
2 rows in set (0.11 sec)
mysql> show variables like 'long%';
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)

#开启slow query并设置阈值为100ms
mysql> set global slow_query_log=1;
Query OK, 0 rows affected (0.10 sec)

mysql> set long_query_time=0.1;
Query OK, 0 rows affected (0.00 sec)

mysql> show variables like 'slow_query%';
+---------------------+-----------------------------------------------+
| Variable_name       | Value                                         |
+---------------------+-----------------------------------------------+
| slow_query_log      | ON                                            |
| slow_query_log_file | /usr/local/mysql/data/tango-GDB-DB01-slow.log |
+---------------------+-----------------------------------------------+
2 rows in set (0.00 sec)

mysql> show variables like 'long%';
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 0.100000 |
+-----------------+----------+
1 row in set (0.00 sec)

开启慢日志后,运行简单的SQL查看慢查询日志

mysql> select count(1) from sbtest.sbtest1 where id between 100 and 10000 ;
+----------+
| count(1) |
+----------+
|     9901 |
+----------+
1 row in set (0.55 sec)

[root@tango-GDB-DB01 data]# less tango-GDB-DB01-slow.log 
# Time: 2021-10-17T00:26:03.079183Z
# User@Host: root[root] @ localhost []  Id:     8
# Query_time: 0.546503  Lock_time: 0.386796 Rows_sent: 1  Rows_examined: 9901
SET timestamp=1634430362;
select count(1) from sbtest.sbtest1 where id between 100 and 10000;

通过命令查看有多少慢查询日志

mysql> show global status like '%Slow_queries%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Slow_queries  | 3     |
+---------------+-------+
1 row in set (0.49 sec)
1.2.2 日志分析工具mysqldumpslow

在生产环境中,如果要手工分析日志,查找、分析SQL,显然是个体力活,MySQL提供了日志分析工具mysqldumpslow。使用很简单,可以跟-h来查看具体的用法

[root@tango-GDB-DB01 data]# ../bin/mysqldumpslow  tango-GDB-DB01-slow.log
Reading mysql slow query log from tango-GDB-DB01-slow.log
Count: 1  Time=0.16s (0s)  Lock=0.39s (0s)  Rows=1.0 (1), root[root]@localhost
  select count(N) from sbtest.sbtest1 where id between N and N

主要功能是, 统计不同慢 sql 下面这些属性:

  • 出现次数(Count),
  • 执行最长时间(Time),
  • 等待锁的时间(Lock),
  • 发送给客户端的行总数(Rows),
  • 用户以及sql语句本身(抽象了一下格式, 比如 limit 1, 20 用 limit N,N 表示).
1.2.3 开源工具pt-query-digest

pt-query-digest是用于分析mysql慢查询的一个工具,它可以分析binlog、General log、slowlog,也可以通过SHOWPROCESSLIST或者通过tcpdump抓取的MySQL协议数据来进行分析。可以把分析结果输出到文件中,分析过程是先对查询语句的条件进行参数化,然后对参数化以后的查询进行分组统计,统计出各查询的执行时间、次数、占比等,可以借助分析结果找出问题进行优化。

1)安装pt-query-digest

# yum install perl-DBI
# yum install perl-DBD-MySQL
# yum install perl-Time-HiRes
# yum install perl-IO-Socket-SSL
# yum -y install perl-Digest-MD5
cd /usr/local/src
wget percona.com/get/percona-toolkit.tar.gz
tar zxf percona-toolkit.tar.gz
cd percona-toolkit-3.3.1
perl Makefile.PL PREFIX=/usr/local/percona-toolkit
make && make install

2)pt-query-digest语法及重要选项

pt-query-digest [OPTIONS] [FILES] [DSN]
--create-review-table  当使用--review参数把分析结果输出到表中时,如果没有表就自动创建。
--create-history-table  当使用--history参数把分析结果输出到表中时,如果没有表就自动创建。
--filter  对输入的慢查询按指定的字符串进行匹配过滤后再进行分析
--limit    限制输出结果百分比或数量,默认值是20,即将最慢的20条语句输出,如果是50%则按总响应时间占比从大到小排序,输出到总和达到50%位置截止。
--host  mysql服务器地址
--user  mysql用户名
--password  mysql用户密码
--history 将分析结果保存到表中,分析结果比较详细,下次再使用--history时,如果存在相同的语句,且查询所在的时间区间和历史表中的不同,则会记录到数据表中,可以通过查询同一CHECKSUM来比较某类型查询的历史变化。
--review 将分析结果保存到表中,这个分析只是对查询条件进行参数化,一个类型的查询一条记录,比较简单。当下次使用--review时,如果存在相同的语句分析,就不会记录到数据表中。
--output 分析结果输出类型,值可以是report(标准分析报告)、slowlog(Mysql slow log)、json、json-anon,一般使用report,以便于阅读。
--since 从什么时间开始分析,值为字符串,可以是指定的某个”yyyy-mm-dd [hh:mm:ss]”格式的时间点,也可以是简单的一个时间值:s(秒)、h(小时)、m(分钟)、d(天),如12h就表示从12小时前开始统计。
--until 截止时间,配合—since可以分析一段时间内的慢查询。

3)分析pt-query-digest输出结果

  • 第一部分:总体统计结果
# 该工具执行日志分析的用户时间,系统时间,物理内存占用大小,虚拟内存占用大小
# 200ms user time, 130ms system time, 25.73M rss, 220.28M vsz
# 工具执行时间
# Current date: Sat Oct 24 10:30:19 2021
# 运行分析工具的主机名
# Hostname: tango-GDB-DB01
# 被分析的文件名
# Files: /usr/local/mysql/data/tango-GDB-DB01-slow.log
# 语句总数量,唯一的语句数量,QPS,并发数
# Overall: 4 total, 4 unique, 0.01 QPS, 0.11x concurrency________________
# 日志记录的时间范围
# Time range: 2021-10-17T00:24:42 to 2021-10-17T00:29:33
# 属性               总计      最小    最大    平均    95%  标准    中等
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# 语句执行时间
# Exec time            33s   398ms     32s      8s     32s     14s     16s
# 锁占用时间
# Lock time          390ms   147us   387ms    97ms   374ms   162ms   188ms
# 发送到客户端的行数
# Rows sent              4       1       1       1       1       0       1
# select语句扫描行数
# Rows examine       9.67k       0   9.67k   2.42k   9.33k   4.04k   4.67k
# 查询的字符数
# Query size           208      28      74      52   72.65   18.73   69.27
  1. Overall:总共有多少条查询
  2. Time range:查询执行的时间范围
  3. unique:唯一查询数量,即对查询条件进行参数化以后,总共有多少个不同的查询
  4. total:总计 min:最小 max:最大 avg:平均
  5. 95%:把所有值从小到大排列,位置位于95%的那个数,这个数一般最具有参考价值
  6. median:中位数,把所有值从小到大排列,位置位于中间那个数
  • 第二部分:查询分组统计结果
# Profile
# Rank Query ID                            Response time Calls R/Call  V/M
# ==== =================================== ============= ===== ======= ===
#    1 0x028E79DCDB99AC4C8AE06173AA02BA16  31.9112 95.7%     1 31.9112  0.00 SELECT sbtest?
# MISC 0xMISC                               1.4378  4.3%     3  0.4793   0.0 <3 ITEMS>
  1. Rank:所有语句的排名,默认按查询时间降序排列,通过–order-by指定
  2. Query ID:语句的ID,(去掉多余空格和文本字符,计算hash值)
  3. Response:总的响应时间
  4. time:该查询在本次分析中总的时间占比
  5. calls:执行次数,即本次分析总共有多少条这种类型的查询语句
  6. R/Call:平均每次执行的响应时间
  7. V/M:响应时间Variance-to-mean的比率
  8. Item:查询对象
  • 第三部分:每一种查询的详细统计结果
# Query 1: 0 QPS, 0x concurrency, ID 0x028E79DCDB99AC4C8AE06173AA02BA16 at byte 382
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2021-10-17T00:24:42
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         25       1
# Exec time     95     32s     32s     32s     32s     32s       0     32s
# Lock time      0     2ms     2ms     2ms     2ms     2ms       0     2ms
# Rows sent     25       1       1       1       1       1       0       1
# Rows examine   0       0       0       0       0       0       0       0
# Query size    13      28      28      28      28      28       0      28
# String:
# Hosts        localhost
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms
#    1s
#  10s+  ################################################################
# Tables
#    SHOW TABLE STATUS LIKE 'sbtest1'\G
#    SHOW CREATE TABLE `sbtest1`\G
# EXPLAIN /*!50100 PARTITIONS*/
select count(1) from sbtest1\G
  1. 由下面查询的详细统计结果,最上面的表格列出了执行次数、最大、最小、平均、95%等各项目的统计。
  2. ID:查询的ID号,和上图的Query ID对应
  3. Databases:数据库名
  4. Users:各个用户执行的次数(占比)
  5. Query_time distribution :查询时间分布, 长短体现区间占比,本例中1s-10s之间查询数量是10s以上的两倍。
  6. Tables:查询中涉及到的表
  7. Explain:SQL语句

2、TiDB中的慢日志

2.1 TiDB中慢日志介绍

TiDB会将执行时间超过slow-threshold(默认值为300毫秒)的语句输出到slow-query-file日志文件中,用于帮助用户定位慢查询语句,分析和解决SQL执行的性能问题。TiDB默认启用慢查询日志,可以修改配置 enable-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。该功能对性能的影响约为 3%。

用户可通过查询INFORMATION_SCHEMA.SLOW_QUERY表来查询慢查询日志中的内容,表中列名和慢日志中字段名一一对应。在TiDB 4.0中,SLOW_QUERY已经支持查询任意时间段的慢日志,即支持查询已经被rotate的慢日志文件的数据。用户查询时只需要指定TIME时间范围即可定位需要解析的慢日志文件。如果查询不指定时间范围,则只解析当前的慢日志文件

2.2 使用pt-query-digest分析慢日志

TiDB中的慢日志可以使用工具pt-query-digest进行解析:

[root@tango-centos01 bin]# ./pt-query-digest --report /tidb-deploy/tidb-4000/log/tidb_slow_query.log > /tmp/result.txt

# Query 1: 0.00 QPS, 0.00x concurrency, ID 0xF56F9650E481C1EAE6740F83A3E451C9 at byte 1705729
# This item is included in the report because it matches --limit.
# Scores: V/M = 45.86
# Time range: 2020-11-15T18:02:59 to 2021-03-15T19:32:58
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count         27    1151
# Exec time     28   5698s   301ms    344s      5s     21s     15s      1s
# Query size    20 201.21k     179     183  179.01  174.84       0  174.84
# Backoff time  32     18s     2ms      6s      1s      5s      2s    91ms
# Compile time  33    577s   190us     42s   501ms      2s      2s     3ms
# Cop backoff   29     15s      2s      6s      4s      6s      2s      5s
# Cop backoff   29     57s     11s     19s     14s     19s      3s     17s
# Cop backoff    9     2ms     2ms     2ms     2ms     2ms       0     2ms
# Cop backoff   14      1s      1s      1s      1s      1s       0      1s
# Cop backoff   78      3s    61ms      2s   256ms   163ms   513ms    82ms
# Cop backoff   61     16s      1s      5s      1s      2s      1s   992ms
# Cop backoff   31   222ms     2ms   164ms    56ms   163ms    66ms   108ms
# Cop backoff   25     27s      1s     18s      7s     18s      7s     12s
# Cop proc avg  19    1.57       0    0.93    0.00       0    0.03       0
# Cop time      37    715s     1us     38s   639ms      2s      2s   219ms
# Cop wait avg  45   16.85       0    2.46    0.02    0.00    0.15       0
# Mem max       39  33.54M  30.69k  30.70k  30.69k  30.09k       0  30.09k
# Num cop task  27   1.09k       0       1    0.97    0.99    0.16    0.99
# Parse time    22    359s    47us     66s   312ms   705ms      3s   144us
# Process time  15      2s     1ms   934ms    31ms    56ms   134ms   972us
# Request coun  27   1.09k       1       1       1       1       0       1
# Total keys     0   1.09k       1       1       1       1       0       1
# Txn start ts  27 410.92E       0 376.21P 365.58P   1.25P 209.72T   1.25P
# Wait time     35     17s     1ms      2s    86ms   393ms   346ms   972us
# String:
# Cop proc add 192.168.112.102:20160 (656/56%)... 2 more
# Cop wait add 192.168.112.102:20160 (656/56%)... 2 more
# Digest       e0cf0e2dccc824f34e52c6341356354f77cce9342074...
# Has more res false
# Index names  [bind_info:time_index]
# Is internal  true
# Plan         tidb_decod... (1149/99%), tidb_decod... (2/0%)
# Plan digest  76900b4634678820c876c2855d6bd7e7a7b0f9b46a8d...
# Plan from ca false
# Prepared     false
# Stats        bind_info:pseudo
# Succ         true (1119/97%), false (32/2%)
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms  #######################################################
#    1s  ################################################################
#  10s+  ############
# Tables
#    SHOW TABLE STATUS FROM `mysql` LIKE 'bind_info'\G
#    SHOW CREATE TABLE `mysql`.`bind_info`\G
# EXPLAIN /*!50100 PARTITIONS*/
select original_sql, bind_sql, default_db, status, create_time, update_time, charset, collation from mysql.bind_info where update_time > "0000-00-00 00:00:00" order by update_time\G
2.3 慢查询中的字段

1)Slow Query 基础信息:

  • Time:表示日志打印时间。
  • Query_time:表示执行这个语句花费的时间。
  • Parse_time:表示这个语句在语法解析阶段花费的时间。
  • Compile_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。
  • Plan:表示语句的执行计划,用 select tidb_decode_plan(‘xxx…’) SQL 语句可以解析出具体的执行计划。
  • Prepared:表示这个语句是否是 Prepare 或 Execute 的请求。
  • Plan_from_cache:表示这个语句是否命中了执行计划缓存。
  • Rewrite_time:表示这个语句在查询改写阶段花费的时间。
  • Preproc_subqueries:表示这个语句中被提前执行的子查询个数,如 where id in (select if from t) 这个子查询就可能被提前执行。
  • Preproc_subqueries_time:表示这个语句中被提前执行的子查询耗时。
  • Exec_retry_count:表示这个语句执行的重试次数。一般出现在悲观事务中,上锁失败时重试执行该语句。
  • Exec_retry_time:表示这个语句的重试执行时间。例如某个查询一共执行了三次(前两次失败),则 Exec_retry_time 表示前两次的执行时间之和,Query_time 减去 Exec_retry_time 则为最后一次执行时间。

2)和事务执行相关的字段:

  • Prewrite_time:表示事务两阶段提交中第一阶段(prewrite 阶段)的耗时。
  • Commit_time:表示事务两阶段提交中第二阶段(commit 阶段)的耗时。
  • Get_commit_ts_time:表示事务两阶段提交中第二阶段(commit 阶段)获取 commit 时间戳的耗时。
  • Local_latch_wait_time:表示事务两阶段提交中第二阶段(commit 阶段)发起前在 TiDB 侧等锁的耗时。
  • Write_keys:表示该事务向 TiKV 的 Write CF 写入 Key 的数量。
  • Write_size:表示事务提交时写 key 或 value 的总大小。
  • Prewrite_region:表示事务两阶段提交中第一阶段(prewrite 阶段)涉及的 TiKV Region 数量。每个 Region 会触发一次远程过程调用。

3)和内存使用相关的字段:

  • Mem_max:表示执行期间 TiDB 使用的最大内存空间,单位为 byte。

4)和硬盘使用相关的字段:

  • Disk_max: 表示执行期间 TiDB 使用的最大硬盘空间,单位为 byte。

5)和 SQL 执行的用户相关的字段:

  • User:表示执行语句的用户名。
  • Conn_ID:表示用户的链接 ID,可以用类似 con:3 的关键字在 TiDB 日志中查找该链接相关的其他日志。
  • DB:表示执行语句时使用的 database。

6)和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 所在地址。
  • Cop_backoff_{backoff-type}_total_times:因某种错误造成的 backoff 总次数。
  • Cop_backoff_{backoff-type}_total_time:因某种错误造成的 backoff 总时间。
  • Cop_backoff_{backoff-type}_max_time:因某种错误造成的最大 backoff 时间。
  • Cop_backoff_{backoff-type}_max_addr:因某种错误造成的最大 backoff 时间的 cop-task 地址。
  • Cop_backoff_{backoff-type}_avg_time:因某种错误造成的平均 backoff 时间。
  • Cop_backoff_{backoff-type}_p90_time:因某种错误造成的 P90 分位 backoff 时间。

参考资料:

  1. https://blog.csdn.net/enweitech/article/details/80239189
  2. https://www.cnblogs.com/luyucheng/p/6265873.html
  3. https://www.cnblogs.com/mysqljs/p/14779645.html
  4. https://docs.pingcap.com/zh/tidb/stable/identify-slow-queries

转载请注明原文地址:https://blog.csdn.net/solihawk/article/details/120932818
文章会同步在公众号“牧羊人的方向”更新,感兴趣的可以关注公众号,谢谢!
数据库系列之MySQL和TiDB中慢日志分析

上一篇:分布式数据库 TiDB 在商业银行的设计与实践


下一篇:react 项目 mock数据