慢查询日志分析和mysqldumpslow

登录客户的数据库服务器查看慢查询日志，用于排查压力测试中响应时间较慢的sql语句。Mysql的慢日志是个ascii文件，可以直接用less等命令查看。
[root@CC-DB1 ~]# tail -n 1000 /var/lib/mysql/CC-DB1-slow.log|less
# Time: 140401 21:05:04
# User@Host: root[root] @ localhost []
# Query_time: 24.344446 Lock_time: 0.000048 Rows_sent: 0 Rows_examined: 0
SET timestamp=1396357504;
call p_insert();
# Time: 140401 21:09:13
# User@Host: root[root] @ [10.5.28.181]
# Query_time: 11.530267 Lock_time: 0.000084 Rows_sent: 1 Rows_examined: 502693
SET timestamp=1396357753;
select count(distinct customer0_.CUSTOMER_NO) as x0_0_ from TBL_CUSTOMER customer0_ where (customer0_.CUSTOMER_TYPE='200164' );
# Time: 140401 21:09:46
# User@Host: root[root] @ [10.5.28.181]
# Query_time: 11.921468 Lock_time: 0.000081 Rows_sent: 1 Rows_examined: 503963
SET timestamp=1396357786;
select count(distinct customer0_.CUSTOMER_NO) as x0_0_ from TBL_CUSTOMER customer0_ where (customer0_.CUSTOMER_TYPE='200164' );
# Time: 140401 21:09:59
# User@Host: root[root] @ [10.5.28.181]
# Query_time: 16.455297 Lock_time: 0.000106 Rows_sent: 1 Rows_examined: 504024
SET timestamp=1396357799;
select count(distinct customer0_.CUSTOMER_NO) as x0_0_ from TBL_CUSTOMER customer0_ where (customer0_.CUSTOMER_TYPE='200164' );
。。。

对部分信息进行说明：
# Time: 140401 21:09:59表示query语句的执行时间
# User@Host: root[root] @ [10.5.28.181]表示执行query语句的client用户名和主机地址
# Query_time: 16.455297 Lock_time: 0.000106 Rows_sent: 1 Rows_examined: 504024
其中query_time表示query语句的执行时间，但是为秒，lock time是锁定的时间，rows_sent是query语句执行返回的记录数，而rows_examined则是优化器估算的扫描行数
下面还包括的是时间戳和具体的query语句

其中slow_query_log控制是否启用慢查询日志，log_slow_queries指定日志文件存储位置，可以为空，slow_query_log_file慢查询日志的文件位置。

Long_query_time是控制query是否满足记录到slow query log中，当query执行时间大于等于long_query_time时，则会记录slow query log日志中。

除此之外mysql的另一个参数log_queries_not_using_indexes还可以控制不启用索引的query语句记录到slow query log中，该参数默认是1，表示不启用索引的query都会记录到slow query log中，小鱼为了slow query log信息尽量简明清晰，一般都将这个参数修改为0.
mysql> show variables like 'log_queries_not_using_indexes' ;
+-------------------------------+-------+
| Variable_name | Value |
+-------------------------------+-------+
| log_queries_not_using_indexes | OFF |
+-------------------------------+-------+
1 row in set (0.00 sec)

Mysql也提供一个可执行文件mysqldumpslow来查看mysql的满查询日志
[root@CC-DB1 ~]# mysqldumpslow --help
Usage: mysqldumpslow [ OPTS... ] [ LOGS... ]

Parse and summarize the MySQL slow query log. Options are

--verbose verbose
--debug debug
--help write this text to standard output

-v verbose
-d debug
-s ORDER what to sort by (al, at, ar, c, l, r, t), 'at' is default
al: average lock time
ar: average rows sent
at: average query time
c: count
l: lock time
r: rows sent
t: query time
-r reverse the sort order (largest last instead of first)
-t NUM just show the top n queries
-a don't abstract all numbers to N and strings to 'S'
-n NUM abstract numbers with at least n digits within names
-g PATTERN grep: only consider stmts that include this string
-h HOSTNAME hostname of db server for *-slow.log filename (can be wildcard),
default is '*', i.e. match all
-i NAME name of server instance (if using mysql.server startup script)
-l don't subtract lock time from total time

比如我们要查看慢查询日志中，最消耗时间的10条sql语句：
[root@CC-DB1 ~]# mysqldumpslow -v -s t -t 10 /var/lib/mysql/CC-DB1-slow.log
返回返回数据最多的10条sql语句：
[root@CC-DB1 ~]# mysqldumpslow -v -s r -t 10 /var/lib/mysql/CC-DB1-slow.log
这里还有一个参数-g可以用于过滤出我们需要的query语句，比如过滤出某些表
[root@CC-DB1 ~]# mysqldumpslow -v -s at -t 10 -g "tbl_customer" /var/lib/mysql/CC-DB1-slow.log
。。。
Count: 843 Time=27.35s (23056s) Lock=0.04s (32s) Rows=1.0 (843), 2users@10hosts
select count(distinct customer0_.CUSTOMER_NO) as x0_0_ from TBL_CUSTOMER customer0_ where (customer0_.CUSTOMER_TYPE='S' )

Count: 1 Time=23.99s (23s) Lock=0.00s (0s) Rows=0.0 (0), root[root]@[116.228.62.230]
DELETE FROM `tbl_customer`

其中的count表示执行次数，time分别表示单次执行的时间和总共执行消耗的时间，lock表示锁定的时间，rows表示返回的行数信息。

顺便查看了一下漫日志的大小，发觉已经有800多m了
[root@CC-DB1 mysql]# ls -lh /var/lib/mysql/CC-DB1-slow.log
-rw-rw---- 1 mysql mysql 818M Apr 2 15:11 /var/lib/mysql/CC-DB1-slow.log

根据需求看是否需要mv备份下
[root@CC-DB1 mysql]# mv /var/lib/mysql/CC-DB1-slow.log /var/lib/mysql/CC-DB1-slow.log.bak

[root@CC-DB1 mysql]# mysqladmin --help
…
flush-hosts Flush all cached hosts
flush-logs Flush all logs
flush-status Clear status variables
flush-tables Flush all tables
flush-threads Flush the thread cache
flush-privileges Reload grant tables (same as reload)

mysqladmin有个参数flush-logs用于刷新所有的日志
[root@CC-DB1 mysql]# mysqladmin -uroot -phollycrm flush-logs

刷新后发觉漫日志已经重新开始生成，
[root@CC-DB1 mysql]# ls -lh /var/lib/mysql/CC-DB1-slow.log.bak
-rw-rw---- 1 mysql mysql 818M Apr 2 15:11 /var/lib/mysql/CC-DB1-slow.log.bak

同样flush-logs还会重新生成新的binlog
[root@CC-DB1 mysql]# ls -lh /var/lib/mysql/CC-DB1-slow.log
-rw-rw---- 1 mysql mysql 183 Apr 2 15:34 /var/lib/mysql/CC-DB1-slow.log

[root@CC-DB1 mysql]# ls -lh /var/lib/mysql/|grep mysql-bin
-rw-rw---- 1 mysql mysql 29K Nov 22 23:33 mysql-bin.000001
-rw-rw---- 1 mysql mysql 1.1M Nov 22 23:33 mysql-bin.000002
-rw-rw---- 1 mysql mysql 46M Nov 29 15:09 mysql-bin.000003
-rw-rw---- 1 mysql mysql 639K Dec 5 13:11 mysql-bin.000004
-rw-rw---- 1 mysql mysql 420K Dec 9 11:04 mysql-bin.000005
-rw-rw---- 1 mysql mysql 4.7K Dec 9 11:32 mysql-bin.000006
-rw-rw---- 1 mysql mysql 23K Dec 9 16:56 mysql-bin.000007
-rw-rw---- 1 mysql mysql 1.1G Jan 16 22:49 mysql-bin.000008
-rw-rw---- 1 mysql mysql 310M Jan 17 11:13 mysql-bin.000009
-rw-rw---- 1 mysql mysql 37K Jan 17 11:30 mysql-bin.000010
-rw-rw---- 1 mysql mysql 1.1G Apr 1 20:34 mysql-bin.000011
-rw-rw---- 1 mysql mysql 592M Apr 2 15:34 mysql-bin.000012
-rw-rw---- 1 mysql mysql 34K Apr 2 15:37 mysql-bin.000013
-rw-rw---- 1 mysql mysql 416 Apr 2 15:34 mysql-bin.index

此文转：http://www.dbaxiaoyu.com/archives/1904

快乐生活每一天