mysql 慢日志flush_time_mysql中的慢查询日志

首先我们看一下关于mysql中的日志，主要包含：错误日志、查询日志、慢查询日志、事务日志、二进制日志；

日志是mysql数据库的重要组成部分。日志文件中记录着mysql数据库运行期间发生的变化；也就是说用来记录mysql数据库的客 户端连接状况、SQL语句的执行情况和错误信息等。当数据库遭到意外的损坏时，可以通过日志查看文件出错的原因，并且可以通过日志文件进行数据恢复。

先看一下日志参数

mysql> show variables like '%log%';

+-----------------------------------------+---------------------------------------+

| Variable_name | Value |

+-----------------------------------------+---------------------------------------+

| back_log | 80 |

| binlog_cache_size | 32768 |

| binlog_checksum | CRC32 |

| binlog_direct_non_transactional_updates | OFF |

| binlog_error_action | IGNORE_ERROR |

| binlog_format | STATEMENT |

| binlog_gtid_simple_recovery | OFF |

| binlog_max_flush_queue_time | 0 |

| binlog_order_commits | ON |

| binlog_row_image | FULL |

| binlog_rows_query_log_events | OFF |

| binlog_stmt_cache_size | 32768 |

| binlogging_impossible_mode | IGNORE_ERROR |

| expire_logs_days | 0 |

| general_log | OFF |

| general_log_file | /data/mysql/localhost.log |

| innodb_api_enable_binlog | OFF |

| innodb_flush_log_at_timeout | 1 |

| innodb_flush_log_at_trx_commit | 1 |

| innodb_locks_unsafe_for_binlog | OFF |

| innodb_log_buffer_size | 8388608 |

| innodb_log_compressed_pages | ON |

| innodb_log_file_size | 50331648 |

| innodb_log_files_in_group | 2 |

| innodb_log_group_home_dir | ./ |

| innodb_mirrored_log_groups | 1 |

| innodb_online_alter_log_max_size | 134217728 |

| innodb_undo_logs | 128 |

| log_bin | OFF |

| log_bin_basename | |

| log_bin_index | |

| log_bin_trust_function_creators | OFF |

| log_bin_use_v1_row_events | OFF |

| log_error | /data/mysql/localhost.localdomain.err |

| log_output | FILE |

| log_queries_not_using_indexes | OFF |

| log_slave_updates | OFF |

| log_slow_admin_statements | OFF |

| log_slow_slave_statements | OFF |

| log_throttle_queries_not_using_indexes | 0 |

| log_warnings | 1 |

| max_binlog_cache_size | 18446744073709547520 |

| max_binlog_size | 1073741824 |

| max_binlog_stmt_cache_size | 18446744073709547520 |

| max_relay_log_size | 0 |

| relay_log | |

| relay_log_basename | |

| relay_log_index | |

| relay_log_info_file | relay-log.info |

| relay_log_info_repository | FILE |

| relay_log_purge | ON |

| relay_log_recovery | OFF |

| relay_log_space_limit | 0 |

| simplified_binlog_gtid_recovery | OFF |

| slow_query_log | OFF |

| slow_query_log_file | /data/mysql/localhost-slow.log |

| sql_log_bin | ON |

| sql_log_off | OFF |

| sync_binlog | 0 |

| sync_relay_log | 10000 |

| sync_relay_log_info | 10000 |

+-----------------------------------------+---------------------------------------+

61 rows in set (0.03 sec)

看一下slow参数

mysql> show variables like '%slow%';

+---------------------------+--------------------------------+

| Variable_name | Value |

+---------------------------+--------------------------------+

| log_slow_admin_statements | OFF |

| log_slow_slave_statements | OFF |

| slow_launch_time | 2 |

| slow_query_log | OFF |

| slow_query_log_file | /data/mysql/localhost-slow.log |

+---------------------------+--------------------------------+

5 rows in set (0.00 sec)

global slow

mysql> show global status like '%slow%';

+---------------------+-------+

| Variable_name | Value |

+---------------------+-------+

| Slow_launch_threads | 0 |

| Slow_queries | 0 |

+---------------------+-------+

一、关于一些参数的解释

1、slow_launch_time：如果创建线程的时间超过该秒数，服务器增加Slow_launch_threads状态变量。

2、slow_query_log：是否记录慢查询。用long_query_time变量的值来确定“慢查询”。

3、slow_query_log_file：慢日志文件路径

4、long_query_time：慢日志执行时长(秒)，超过设定的时间才会记日志

5、log-slow-admin-statements：一些管理指令，也会被记录。比如OPTIMEZE TABLE, ALTER TABLE等等

6、log-queries-not-using-indexes：MySQL会将没有使用索引的查询记录到slow query日志中。无论它执行有多快，查询语句没有使用索引，都会被记录。有的时候，有些没有使用引索的查询非常快(例如扫描很小的表)，但也有可能导致服务器变慢，甚至还会使用大量的磁盘空间。

二、配置

#将下列配置放到my.cnf中

[mysqld]

slow_query_log_file = /var/lib/mysql/slow-queries.log

log_slow_queries = ON

long_query_time = 1

log-queries-not-using-indexes

log-slow-admin-statements

我们也可以登录之后进行配置

set global slow_query_log=on;

set global slow_query_log_file = /var/lib/mysql/slow-queries.log ;

set global long_query_time=1;

set gloabl log_slow_admin_statements=on;

set global log_queries_not_using_indexes = on;

查看日志

[admin@dev config]$ sudo tail -f /var/lib/mysql/dev-slow.log

SET timestamp=1437572901;

show warnings;

# Time: 150722 21:48:49

# User@Host: root[root] @ localhost []

# Query_time: 0.021936 Lock_time: 0.000121 Rows_sent: 1 Rows_examined: 5294

SET timestamp=1437572929;

select sql_no_cache id,bid,pic,cateid,title,tag,indextitle,dateline,summary from acc_info_article where status=1 and find_in_set("84",bid) order by sort asc limit 1;

/usr/libexec/mysqld, Version: 5.5.29-log (MySQL Community Server (GPL)). started with:

Tcp port: 3306 Unix socket: /var/lib/mysql/mysql.sock

说明

第一行：执行时间

第二行：执行用户

第三行(重要)

Query_time SQL执行的时间,越长则越慢

Lock_time 在MySQL服务器阶段(不是在存储引擎阶段)等待表锁时间

Rows_sent 查询返回的行数

Rows_examined 查询检查的行数

1、日志不能说明一切问题，可能跟锁表、系统繁忙的偶发性有关，

a、锁表，导致查询处于等态状态，lock_time显示了查询等待锁被翻译的时间

b、数据或索引没有被缓存,常见于第一次启动服务器或者服务器没有调优

c、备份数据库，I/O变慢，

d、同时运行了其它的查询，减少了当前查询，

e、当然，如果某条SQL语句经常查询慢那基本可以判断是可以再次优化的

2、不要开启log-queries-not-using-indexes(没有索引查询记录功能)

a、这个功能实际用处不大，就是记录SQL查询的时候，没有索引的通通记录

b、虽然索引对查询的速度有影响，但要看数据量大小

c、因为开启了这个功能以后，select * from blog这样的查询也会被记录在日志中，很快日志文件就会被垃圾信息给充满，从而影响主要的查询慢日志记录的查看

三、日志分析、工欲善其事必先利其器

主要推荐两种方式

1、mysqldumpslow

[root@mysql_data]#mysqldumpslow slow-query.log

Reading mysql slow query log from slow-query.log

Count: 2 Time=11.00s (22s) Lock=0.00s (0s) Rows=1.0 (2), root[root]@mysql

select count(N) from t_user;

mysqldumpslow -s c -t 10 /database/mysql/slow-query.log

这会输出记录次数最多的10条SQL语句，其中：

-s, 是表示按照何种方式排序，c、t、l、r分别是按照记录次数、时间、查询时间、返回的记录数来排序，ac、at、al、ar，表示相应的倒叙；

-t, 是top n的意思，即为返回前面多少条的数据；

-g, 后边可以写一个正则匹配模式，大小写不敏感的；

mysqldumpslow -s r -t 10 /database/mysql/slow-log

得到返回记录集最多的10个查询。

mysqldumpslow -s t -t 10 -g "left join" /database/mysql/slow-log

得到按照时间排序的前10条里面含有左连接的查询语句。

使用mysqldumpslow命令可以非常明确的得到各种我们需要的查询语句，对MySQL查询语句的监控、分析、优化是MySQL优化非常重要的一步。开启慢查询日志后，由于日志记录操作，在一定程度上会占用CPU资源影响mysql的性能，但是可以阶段性开启来定位性能瓶颈。

2、pt-query-digest

下载安装

[root@localhost ~]# wget https://www.percona.com/get/pt-query-digest

[root@localhost ~]# chmod u+x pt-query-digest

参数解释

--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可以分析一段时间内的慢查询。

用法

(1)直接分析慢查询文件:

pt-query-digest slow.log > slow_report.log

(2)分析最近12小时内的查询：

pt-query-digest --since=12h slow.log > slow_report2.log

(3)分析指定时间范围内的查询：

pt-query-digest slow.log --since '2014-04-17 09:30:00' --until '2014-04-17 10:00:00'> > slow_report3.log

(4)分析指含有select语句的慢查询

pt-query-digest--filter '$event->{fingerprint} =~ m/^select/i' slow.log> slow_report4.log

(5) 针对某个用户的慢查询

pt-query-digest--filter '($event->{user} || "") =~ m/^root/i' slow.log> slow_report5.log

(6) 查询所有所有的全表扫描或full join的慢查询

pt-query-digest--filter '(($event->{Full_scan} || "") eq "yes") ||(($event->{Full_join} || "") eq "yes")' slow.log> slow_report6.log

(7)把查询保存到query_review表

pt-query-digest --user=root –password=abc123 --review h=localhost,D=test,t=query_review--create-review-table slow.log

(8)把查询保存到query_history表

pt-query-digest --user=root –password=abc123 --review h=localhost,D=test,t=query_ history--create-review-table slow.log_20140401

pt-query-digest --user=root –password=abc123--review h=localhost,D=test,t=query_history--create-review-table slow.log_20140402

(9)通过tcpdump抓取mysql的tcp协议数据，然后再分析

tcpdump -s 65535 -x -nn -q -tttt -i any -c 1000 port 3306 > mysql.tcp.txt

pt-query-digest --type tcpdump mysql.tcp.txt> slow_report9.log

(10)分析binlog

mysqlbinlog mysql-bin.000093 > mysql-bin000093.sql

pt-query-digest --type=binlog mysql-bin000093.sql > slow_report10.log

(11)分析general log

pt-query-digest --type=genlog localhost.log > slow_report11.log

官方文档：http://www.percona.com/doc/percona-toolkit/2.2/pt-query-digest.html