二十六：慢日志分析

作用

慢日志slow-log用来记录运行较慢的语句,优化过程中常用的工具日志

开启慢日志功能

默认未开启慢日志，需要修改配置文件my.cnf开启

$ vim /etc/my.cnf
[mysqld]
#开启慢日志
slow_query_log=1 
#慢日志记录文件位置，目录提前创建好且有权限
slow_query_log_file=/data/mysql/slow.log
#如果查询事件超过0.1秒则记录到慢日志中，默认超过10s记录到慢日志
long_query_time=0.1
#记录没走索引的语句，可能是全表扫描，也会造成查询慢
log_queries_not_using_indexes

通过@@long_query_time变量查看

#这里已经通过上述配置文件修改为0.1秒记录到慢日志中
mysql> select @@long_query_time;
+-------------------+
| @@long_query_time |
+-------------------+
|          0.100000 |
+-------------------+
1 row in set (0.00 sec)

模拟慢查询

使用全表查询语句模拟慢查询，这里用到的是之前生成的t100w的表数据。

#建议使用多条语句进行查询
mysql> select num,k1 from t100w where num !=10 order by k1 limit 10000;

#查看sleep线程
$ mysql -e "show full processlist;"

#使用kill掉线程，注意不能kill掉insert,update命令会丢失数据
mysql> kill 212555221;

因为我模拟出来的数据跟书上的不一样，这里贴书上的图方便理解。

这里可以看到正在排队执行的查询语句

解决方案

调整MySQL两个超时参数

mysql> show variables like '%_timeout%';
+-----------------------------+----------+
| Variable_name               | Value    |
+-----------------------------+----------+
| interactive_timeout         | 28800    |
| wait_timeout                | 28800    |
+-----------------------------+----------+
13 rows in set (0.00 sec)

mysql> set global wait_timeout = 60;
mysql> set global interactive_timeout =60;

或者在配置文件/etc/my.cnf中修改

$ vim /etc/my.cnf
[mysqld]
interactive_timeout = 60
wait_timeout = 60

$ /etc/init.d/mysqld restart

参考资料:《MySQL入门与提高实践》第七章P149

分析慢日志

slow.log是文本格式的，可以直接使用vim打开。

使用mysqldumpslow分析慢日志

#-s，sort排序，-c,count次数，-t,top前10条数据
$ mysqldumpslow -s c -t 10 /data/mysql/slow.log

Count:12
表示该语句执行了12次
Time=0.32s(3s)
每次执行时间是2.79s，总共花费时间3s（执行了12次，每次0.32s一共3.84秒）
lock=0.00s
锁表时间0s
Rows=194.5(2334)
语句执行返回结果数是194.5条数据，一共返回过12*194.5=2334条数据

第三方分析工具

下载percona-toolkit

#安装依赖项
$ yum install perl-DBI perl-DBD-MySQL perl-Time-HiRes perl-IO-Socket-SSL perl-Digest-MD5

#分析二进制日志
$ pt-query-diagest  /data/mysql/slow.log

Anemometer基于pt-query-digest将MySQL慢查询以网页形式展现，方便查看。

学习来自：老男孩深标DBA课程 第六章 日志管理，《MySQL入门与提高实践》第七章P149