一、MySQL慢日志分析工具方法
在日常运维中,经常需要开启慢查询日志,可以让MySQL记录下查询超过指定时间的语句,通过定位分析性能的瓶颈,更好的优化数据库系统的性能。
那如何能更好更快的分析慢查询日志来协助我们分析并定位?官方提供了mysqldumpslow工具,也存在第三方工具如Mysqlsla及 pt-query-digest工具,下面分别介绍三个工具帮助运维人员了解并使用如上几个工具。
1、Mysqldumpslow工具
Mysqldumpslow 是 Mysql自带的一种慢日志分析工具。可以使用该工具对慢日志中所获取到SQL进行一系列的统计与排序。
1.常用参数
常用参数 | 含义 |
-a | 不将数字和字符串抽象成N和S |
-n | 名称中至少有N位数字的抽象数字 |
-g | 只考虑与(grep样式)模式匹配的查询 |
--help | 查看帮助 |
-h | 日志文件名中服务器的主机名 |
-i | 服务器实例的名称 |
-l | 不要从总时间中减去锁时间 |
-r | 反转排序顺序 |
-s |
排序方式-s t:按照总的查询时间排序-s at:按照平均查询时间排序-s l:按照总的锁定时间排序-s al:按照平均锁定时间排序-s s:按照总的记录行数排序-s as:按照平局的记录行数排序-s c:按照语句执行的次数排序,默认排序方式 |
-t | 输出前X行 |
2.范例
2.1 按照query time排序查看日志
1
|
mysqldumpslow -s t mysql-slow.log |
2.2 按照平均query time排序查看日志
1
|
mysqldumpslow -s at mysql-slow.log |
2.3 按照平均query time排序并且不抽象数字的方式排序
1
|
mysqldumpslow -a -s at mysql-slow.log |
2.4 按照执行次数排序
1
|
mysqldumpslow -a -s c mysql-slow.log |
2.5 按照执行次数排序,输出一条sql
1
|
mysqldumpslow -s c -t 1 mysql-slow.log |
3. 结果解析
1
2
3
4
5
6
7
|
Count: 3 Time=62.67s (188s) Lock=0.00s (0s) Rows=1623770.7 (4871312), root[root]@localhost SELECT /*!N SQL_NO_CACHE */ * FROM `feed_receive_0287` Count: 3 该类型SQL语句执行次数3次 Time=62.67s (188s) 执行最长时间62.67s(3次总计执行时间188s) Lock=0.00s (0s) 等待锁的时间0s(3次总计等待锁时间0s) Rows=1623770.7 (4871312) 返回给客户端行总数4871312 /3 =1623770.7行(3次共扫描行总数4871312次)
root[root]@localhost 连接用户 |
2、Mysqlsla工具
Mysqlsla是一款帮助语句分析、过滤、分析和排序MySQL慢日志、查询日志、二进制日志和microslow patched日志的分析工具。整体来说, 功能非常强大。 数据报表,非常有利于分析慢查询的原因, 包括执行频率, 数据量, 查询消耗等。是基于perl 写的一个脚本,专门用于处理分析Mysql的日志而存在。
1.Mysqlsla软件下载及安装
下载:
GITHUB
百度云盘
安装:
1)安装依赖
1
|
yum install perl perl-DBI perl-DBD-MySQL perl-ExtUtils-CBuilder perl-ExtUtils-MakeMaker
|
2)安装软件
1
2
3
4
|
tar –xvf mysqlsla-2.03. tar .gz
perl Makefile.PL make make install
|
2.常用参数
常用参数 | 含义 |
--log-type (-lt) TYPE LOGS | slow, general, binary, msl or udl |
--sf | (+-)(TYPE),(TYPE)有SELECT, CREATE, DROP, UPDATE, INSERT,不出现的默认是-,即不包括 |
--db | 要处理哪个库的日志 |
--top | 表示取按规则排序的前多少条 |
--sort | t_sum:按总时间排序(默认);c_sum:按总次数排序;c_sum_p: sql语句执行次数占总执行次数的百分比 |
3.范例
3.1 查看帮助信息
1
|
man mysqlsla
|
3.2 查询慢日志中最多的20个SQL语句
1
|
mysqlsla -lt slow -- sort t_sum -- top 20 /var/lib/mysql/log/mysql-slow .log
|
3.3有select和update查询次数最多的10条SQL
1
|
mysqlsla -lt slow -sf "+select,update" - top 10 - sort c_sum -db mydata /var/lib/mysql/log/mysql-slow .log
|
3.4 查询通用日志查询次数最多的10条SQL
1
|
mysqlsla -lt general - top 10 - sort c_sum /var/lib/mysql/log/mysql-general .log
|
4 结果解析
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
|
shell> mysqlsla -lt slow -- sort t_sum -- top 20 /var/lib/mysql/log/mysql-slow .log
Report for slow logs: /var/lib/mysql/log/mysql-slow .log
2 queries total, 2 unique Sorted by ‘t_sum‘
Grand Totals: Time 28 s, Lock 0 s, Rows sent 7, Rows Examined 6 ________________________________________________________________001 ___ Count : 1 (50.00%) Time : 22.596567 s total, 22.596567 s avg, 22.596567 s to 22.596567 s max (81.88%) Lock Time (s) : 170 μs total, 170 μs avg, 170 μs to 170 μs max (100.00%) Rows sent : 6 avg, 6 to 6 max (85.71%) Rows examined : 6 avg, 6 to 6 max (100.00%) Database : test
Users : root@localhost : 100.00% (1) of query, 100.00% (2) of all users
Query abstract: SET timestamp=N; SELECT sleep (N) FROM test ;
Query sample: SET timestamp=1574747237; select sleep (4) FROM test ;
________________________________________________________________002 ___ Count : 1 (50.00%) Time : 5.001365 s total, 5.001365 s avg, 5.001365 s to 5.001365 s max (18.12%) Lock Time (s) : 0 total, 0 avg, 0 to 0 max (0.00%) Rows sent : 1 avg, 1 to 1 max (14.29%) Rows examined : 0 avg, 0 to 0 max (0.00%) Database : Users : root@localhost : 100.00% (1) of query, 100.00% (2) of all users
Query abstract: SET timestamp=N; SELECT sleep (N);
Query sample: SET timestamp=1574746391; select sleep (5);
|
总查询次数 (queries total), 去重后的sql数量 (unique)
输出报表的内容排序(sorted by)
最重大的慢sql统计信息, 包括 平均执行时间, 等待锁时间, 结果行的总数, 扫描的行总数.
Count, sql的执行次数及占总的slow log数量的百分比.
Time, 执行时间, 包括总时间, 平均时间, 最小, 最大时间, 时间占到总慢sql时间的百分比.
95% of Time, 去除最快和最慢的sql, 覆盖率占95%的sql的执行时间.
Lock Time, 等待锁的时间.
95% of Lock , 95%的慢sql等待锁时间.
Rows sent, 结果行统计数量, 包括平均, 最小, 最大数量.
Rows examined, 扫描的行数量.
Database, 属于哪个数据库
Users, 哪个用户,IP, 占到所有用户执行的sql百分比
Query abstract, 抽象后的sql语句
Query sample, sql语句
3、 pt-query-digest工具
该工具已在前面章节介绍percona-toolkit运维工具中详细介绍过,可自行往前翻阅
二、aborted告警日志的分析
在MySQL的error log中,我们会经常性看到一些各类的Aborted connection错误,本文中会针对这类错误进行一个初步分析,并了解一个问题产生后的基本排查思路和方法。
首先通过官方文档来了解Aborted_clients & Aborted_connects两个状态变量的代表意义,以及哪些情况或因素会导致这些状态变量变化呢?
造成Aborted_connects状态变量增加的可能原因:
1.客户机试图访问数据库,但没有数据库的特权。
2.客户端使用了错误的密码。
3.连接包不包含正确的信息。
4.获取一个连接包需要的时间超过connect_timeout秒。
造成Aborted_clients 状态变量增加的可能原因:
1.程序退出前,客户机程序没有调用mysql_close()。
2.客户端睡眠时间超过了wait_timeout或interactive_timeout秒
3.客户端程序在数据传输过程中突然终止
简单来说即:
数据库会话未能正常连接到数据库,会造成Aborted_connects变量增加。
数据库会话已正常连接到数据库但未能正常退出,会造成Aborted_clients变量增加。
2.测试案例
测试环境说明:MySQL5.7
测试环境及相关参数
connect_timeout | 10 |
interactive_timeout | 28800 |
wait_timeout | 28800 |
max_connections | 151 |
net_write_timeout | 60 |
net_read_timeout | 30 |
注:每次测试前均重启数据库重置状态值,方便后续比较
1
2
3
4
5
6
|
+------------------+-------+ | Variable_name | Value | +------------------+-------+ | Aborted_clients | 0 | | Aborted_connects | 0 | +------------------+-------+ |
测试一:错误密码、错误用户
1
2
3
4
5
6
7
|
shell> mysql -uroot -perrorpass -S /tmp/mysql57 .sock
ERROR 1045 (28000): Access denied for user ‘root‘ @ ‘localhost‘ (using password: YES)
shell> mysql -uroot -perrorpass -h127.0.0.1 -P3307 ERROR 1045 (28000): Access denied for user ‘root‘ @ ‘localhost‘ (using password: YES)
错误用户: shell> mysql –uroot1 -perrorpass -S /tmp/mysql57 .sock
ERROR 1045 (28000): Access denied for user ‘root‘ @ ‘localhost‘ (using password: YES)
|
查看数据库内状态值
1
2
3
4
5
6
|
+------------------+-------+ | Variable_name | Value | +------------------+-------+ | Aborted_clients | 0 | | Aborted_connects | 3 | +------------------+-------+ |
查看错误日志
1
2
3
|
2019-11-20T22:03:31.226480Z 3 [Note] Access denied for user ‘root‘ @ ‘localhost‘ (using password: YES)
2019-11-20T22:04:14.420560Z 4 [Note] Access denied for user ‘root‘ @ ‘localhost‘ (using password: YES)
2019-11-20T22:04:32.670073Z 5 [Note] Access denied for user ‘root1‘ @ ‘localhost‘ (using password: YES)
|
测试二:超时参数
当前数据库wait_timeout 及interactive_timeout均为默认的28800,下面调整这两个参数,测试对数据库连接的行为影响。
该实验同时修改两个参数为10
1
2
3
|
<h4>mysql> set global wait_timeout=10;
<br>mysql> set global interactive_timeout=10;
<br></h4> |
------等待一段时间之后-----
1
2
3
4
5
6
7
8
9
10
11
|
mysql> show processlist; ERROR 2006 (HY000): MySQL server has gone away No connection . Trying to reconnect...
Connection id: 4
Current database : *** NONE ***
+ ----+------+-----------+------+---------+------+----------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+ ----+------+-----------+------+---------+------+----------+------------------+
| 4 | root | localhost | NULL | Query | 0 | starting | show processlist |
+ ----+------+-----------+------+---------+------+----------+------------------+
1 row in set (0.00 sec)
|
查看数据库内状态值
1
2
3
4
5
6
|
+ ------------------+-------+
| Variable_name | Value | + ------------------+-------+
| Aborted_clients | 2 | | Aborted_connects | 0 | + ------------------+-------+
|
查看错误日志
1
2
|
2019-11-20T23:29:04.012321Z 3 [Note] Aborted connection 3 to db: ‘unconnected‘ user : ‘root‘ host: ‘localhost‘ (Got timeout reading communication packets)
2019-11-20T23:29:37.137417Z 4 [Note] Aborted connection 4 to db: ‘unconnected‘ user : ‘root‘ host: ‘localhost‘ (Got timeout reading communication packets)
|
测试三:最大连接数
当前数据库max_connections参数默认为151,下面调整改参数,测试对数据库连接的行为影响。
1
|
mysql> set global max_connections=2;
|
当开启第四个连接会话,报如下错误:
1
2
|
shell> mysql57 ERROR 1040 (HY000): Too many connections |
查看数据库内状态值
1
2
3
4
5
6
|
+ ------------------+-------+
| Variable_name | Value | + ------------------+-------+
| Aborted_clients | 0 | | Aborted_connects | 0 | + ------------------+-------+
|
此时错误日志无变化。
测试四:第三方工具SQLyog select结果没有出来的时候选择停止则出现
1
|
SELECT SLEEP(10);
|
查看数据库内状态值
1
2
3
4
5
6
|
+ ------------------+-------+
| Variable_name | Value | + ------------------+-------+
| Aborted_clients | 1 | | Aborted_connects | 0 | + ------------------+-------+
|
此时错误日志无变化。