1 慢查询日志 配置
2 查看慢查询日志工具：mysqldumpslow mysqlsla
3. 五种MySQL日志分析工具比拼
----------------------------------------------------------------------------------1 慢查询日志 配置 开启慢查询日志 , 配置样例： /etc/mysql/my.cnf [mysqld] log-slow-queries 在 my.cnf 配置文件中增加上述配置项并重启 mysql 服务，这时 mysql 慢查询功能生效。慢查询 日志将写入参数 DATADIR （数据目录：/var/lib/mysql） 指定的路径下，默认文件名是 host_name-slow.log 。 和错误日志、查询日志一样，慢查询日志记录的格式也是纯文本，可以被直接读取。下例中演示了慢查询日志的设置和读取过程。
flush privileges; （ 1 ）首先查询一下 long_query_time 的值 。 mysql> show variables like 'long%'; +-----------------+-------+ | Variable_name | Value | +-----------------+-------+ | long_query_time | 10 | +-----------------+-------+ 1 row in set (0.00 sec) （ 2 ）为了方便测试，将修改慢查询时间为 5 秒。 mysql> set long_query_time=1; Query OK, 0 rows affected (0.02 sec)
以上操作只限于当前有效，关闭服务器得重新设置。下面的方法可直接写入my.cnf
log-slow-queries=/var/lib/mysql/slowquery.log long_query_time=1
（ 3 ）依次执行下面两个查询语句。 第一个查询因为查询时间低于 1 秒而不会出现在慢查询日志中： mysql> select count(*) from `gll_pro_ru`; +----------+ | count(*) | +----------+ | 208 | +----------+ 1 row in set (0.00 sec) 第二个查询因为查询时间大于 1 秒而应该出现在慢查询日志中： mysql> select count(*) from `gll_order_desc`;
mysql> select * from `gll_order_desc`; +----------+ | count(*) | +----------+ | 6552961 | +----------+ 1 row in set (11.07 sec) ----------------------------------------------------------------------------------2 查看慢查询日志工具
直接输出
# more localhost-slow.log
# Time: 081026 19:46:34 # User@Host: root[root] @ localhost [] # Query_time: 11 Lock_time: 0 Rows_sent: 1 Rows_examined: 6552961
select count(*) from t_user; 从上面日志中，可以发现查询时间超过 5 秒的 SQL ，而小于 5 秒的则没有出现在此日志中。 如果慢查询日志中记录内容很多，可以使用 mysqldumpslow 工具（ MySQL 客户端安装自带）来对慢查询日志进行分类汇总。下例中对日志文件 mysql_master-slow.log 进行了分类汇总，只显示汇总后摘要结果： [root@mysql_master mysql_data]# mysqldumpslow slowquery.log
－－－－－－－－－－－－－－－－－ mysqldumpslow mysql官方提供的慢查询日志 分析工具
@@@@@@需要注意所使用的mysqldumpslow的版本不匹配一致，否则会出现无法显示执行time：
/usr/local/mysql5_5_15/bin/mysqldumpslow -s t -t 5 /data/mysql5_5_15/mysql_3307/slowquery.log
-s，是order的顺序，说明写的不够详细，俺用下来，包括看了代码，主要有 c,t,l,r和ac,at,al,ar，分别是按照query次数，时间，lock的时间和返回的记录数来排序，前面加了a的时倒叙
-t，是top n的意思，即为返回前面多少条的数据 -g，后边可以写一个正则匹配模式，大小写不敏感的
mysqldumpslow -s t -t 20 host-slow.log #执行时间
mysqldumpslow -s l -t 20 host-slow.log #锁时间
mysqldumpslow -s c -t 20 host-slow.log 上述命令可以看出访问次数最多的20个sql语句 mysqldumpslow -s r -t 20 host-slow.log 上述命令可以看出返回记录集最多的20个sql。 mysqldumpslow -t 10 -s t -g “left join” host-slow.log 这个是按照时间返回前10条里面含有左连接的sql语句
－－－－－－－－－－－－－－－－－－－－－－－－
Reading mysql slow query log from mysql_master-slow.log Count: 2 Time=11.00s (22s) Lock=0.00s (0s) Rows=1.0 (2), root[root]@mysql_master select count(N) from t_user; 对于 SQL 文本完全一致，只是变量不同的语句， mysqldumpslow 将会自动视为同一个语句进行统计，变量值用 N 来代替。这个统计结果将大大增加用户阅读慢查询日志的效率，并迅速定位系统的 SQL 瓶颈。 注意：慢查询日志对于我们发现应用中有性能问题的 SQL 很有帮助，建议正常情况下，打开此日志并经常查看分析。
－－－－－－－－－－－－－－－－－－－－－－－－开始分析:
mysqldumpslow -s t -t 5 slow.log.20100427 > analyse.txt 打开 analyse.txt,最前面的语句就是你最需要优化的(最需要被优化的语句不是执行次数最多的,也不是执行最慢的,而是执行的总时间最长的,即max(执行次数*每条的执行时间),这种语句是最需要被优化的,而且优化后的效果是最明显的).下面举例说明: Count: 19083 Time=3.08s (58754s) Lock=0.00s (0s) Rows=1.4 (25871), work[work]@[10.13.14.15] SELECT _mis_uid, _mis_reqip, _mis_time FROM t_mis_user_ip WHERE _mis_time BETWEEN N AND N 19083表示这条sql语句执行了19083次,平均的执行时间是3.08s,总共的时间是58754s.够慢的吧,看来确实需要优化了. 通过BETWEEN N AND N,可以看到,本来是整数的时间被抽象成了Number.接下来我们去slow.log.20100427中找到真正的sql语句: 借助grep即可: grep --color -i "_mis_time" slow.log.20100427 ,如果结果语句很多,再用grep多过滤几次,就可以找到完全符合上述格式的sql了. 例如我找到了一条: SELECT _mis_uid, _mis_reqip, _mis_time FROM t_mis_user_ip WHERE _mis_time BETWEEN 1272247251 AND 1272247258; 接下来就开始用explain优化它: explain SELECT _mis_uid, _mis_reqip, _mis_time FROM t_mis_user_ip WHERE _mis_time BETWEEN 1272247251 AND 1272247258 \G
－－－－－－－－－－－－－－－－－－－－－－－－－实例输出
[root@localhost mysql]# mysqldumpslow -s c -t 5 mysql_slow_log Reading mysql slow query log from mysql_slow_log Count: 576 Time=2.02s (1164s) Lock=0.00s (0s) Rows=19964.1 (11499334), root[root]@localhost select * from maos_v_video where ct_id in(N,N,N,N,N,N,N,N,N) order by u_time desc Count: 84 Time=2.23s (187s) Lock=0.00s (0s) Rows=1.0 (84), 2users@localhost select * from maos_book_ext where b_id = N and chapter = N order by sort desc limit N,N Count: 34 Time=2.24s (76s) Lock=0.00s (0s) Rows=1041.4 (35409), root[root]@localhost select * from maos_v_video where ct_id in(N,N,N,N,N,N,N,N,N) and word = 'S' order by u_time desc
[root@localhost mysql]# mysqldumpslow -s r -t 5 mysql_slow_log Reading mysql slow query log from mysql_slow_log Count: 576 Time=2.02s (1164s) Lock=0.00s (0s) Rows=19964.1 (11499334), root[root]@localhost select * from maos_v_video where ct_id in(N,N,N,N,N,N,N,N,N) order by u_time desc Count: 28 Time=3.11s (87s) Lock=0.00s (0s) Rows=7296.0 (204288), root[root]@localhost select * from maos_v_video where ct_id in(N,N,N,N,N) order by u_time desc Count: 18 Time=3.56s (64s) Lock=0.00s (0s) Rows=8744.8 (157406), root[root]@localhost select * from maos_v_video where ct_id in(N,N,N,N,N,N,N,N,N) and cz_id = N order by u_time desc
－－－－－－－－－－－－－－－－－
主要功能是, 统计不同慢sql的 出现次数(Count), 执行最长时间(Time), 累计总耗费时间(Time), 等待锁的时间(Lock), 发送给客户端的行总数(Rows), 扫描的行总数(Rows), 用户以及sql语句本身(抽象了一下格式, 比如 limit 1, 20 用 limit N,N 表示).
======================================完整分析
/usr/local/mysql5_5_15/bin/mysqldumpslow -s t -t 5 /data/mysql5_5_15/mysql_3307/slowquery.log ======================= 1 Count: 496197 Time=7.05s (3497360s) Lock=0.00s (165s) Rows=1.0 (496197), replication[replication]@2hosts SELECT COUNT(*) FROM `order_fail` `t` WHERE sub_draws_id='S' AND user_id=N AND date(order_time) = 'S' #grep --color -i "SELECT COUNT(\*) FROM \`order_fail\` " /data/mysql5_5_15/mysql_3307/slowquery.log mysql> EXPLAIN SELECT COUNT(*) FROM `order_fail` `t` WHERE sub_draws_id='7197' AND user_id=4346 AND DATE(order_time) = '2012-06-28'; +----+-------------+-------+------+---------------+------+---------+------+--------+-------------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +----+-------------+-------+------+---------------+------+---------+------+--------+-------------+ | 1 | SIMPLE | t | ALL | NULL | NULL | NULL | NULL | 415857 | Using where | +----+-------------+-------+------+---------------+------+---------+------+--------+-------------+ 1 row in set (0.00 sec) ====================== 2 Count: 18559 Time=2.45s (45543s) Lock=0.00s (8s) Rows=92.0 (1707428), replication[replication]@2hosts SELECT l.game_id,l.number,l.odds,m.sum_amount,m.sum_share,m.sum_payment,m.sum_discount,m.reserve_amount,c.status,csc.short_covering_base FROM cur_stopbuy c LEFT JOIN latest_odds l ON c.game_id = l.game_id AND c.`number` = l.`number` AND l.ctrl_set_id = N AND l.odds_set = 'S' LEFT JOIN receive_user m ON m.`game_id` = c.game_id AND m.`number` = c.`number` AND m.user_id = N LEFT JOIN `config_short_covering` csc ON l.category_id = csc.`category_id` AND csc.user_id = 'S' mysql> explain SELECT l.game_id,l.number,l.odds,m.sum_amount,m.sum_share,m.sum_payment,m.sum_discount,m.reserve_amount,c.status,csc.short_covering_base FROM cur_stopbuy c LEFT JOIN latest_odds l ON c.game_id = l.game_id AND c.`number` = l.`number` AND l.ctrl_set_id = 0 AND l.odds_set = 'A' LEFT JOIN receive_user m ON m.`game_id` = c.game_id AND m.`number` = c.`number` AND m.user_id = 4323 LEFT JOIN `config_short_covering` csc ON l.category_id = csc.`category_id` AND csc.user_id = '4323'; +----+-------------+-------+--------+---------------+---------+---------+----------------------------------------------+------+-------+ | id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra | +----+-------------+-------+--------+---------------+---------+---------+----------------------------------------------+------+-------+ | 1 | SIMPLE | c | ALL | NULL | NULL | NULL | NULL | 92 | | | 1 | SIMPLE | l | eq_ref | PRIMARY | PRIMARY | 34 | const,ssc_da.c.game_id,ssc_da.c.number,const | 1 | | | 1 | SIMPLE | m | ref | PRIMARY | PRIMARY | 103 | const,ssc_da.c.game_id,ssc_da.c.number | 1 | | | 1 | SIMPLE | csc | ref | PRIMARY | PRIMARY | 4 | const | 9 | | +----+-------------+-------+--------+---------------+---------+---------+----------------------------------------------+------+-------+ 4 rows in set (0.00 sec) ====================== 3 Count: 13106 Time=2.85s (37401s) Lock=0.00s (1s) Rows=110.7 (1450960), replication[replication]@2hosts SELECT game_id,number,category_id,status FROM cur_stopbuy ====================== 4 Count: 4 Time=5475.02s (21900s) Lock=0.00s (0s) Rows=0.0 (0), replication[replication]@[192.168.1.213] CALL p_auto_truncate_table(N,N,@rs)
－－－－－－－－－－－－－---- MySQL的日志分析工具mysqlsla 【附下载 】 官方网站：http://hackmysql.com ------安装 perl Makefile.PL make make install －－－－－测试 sudo mysqlsla -lt slow /var/lib/mysql/slowquery.log
或者是 mysqlsla -lt slow /var/lib/mysql/slowquery.log >/tmp/slow.log 保存为文件
ubuntu@ubuntu-desktop:/tmp/mysqlsla-2.03$ sudo mysqlsla -lt slow /var/lib/mysql/slowquery.log Report for slow logs: /var/lib/mysql/slowquery.log 3 queries total, 3 unique Sorted by 't_sum' Grand Totals: Time 46 s, Lock 0 s, Rows sent 369.56k, Rows Examined 731.48k ______________________________________________________________________ 001 ___ Count : 1 (33.33%) Time : 39 s total, 39 s avg, 39 s to 39 s max (84.78%) Lock Time (s) : 0 total, 0 avg, 0 to 0 max (0.00%) Rows sent : 359.56k avg, 359.56k to 359.56k max (97.29%) Rows examined : 719.11k avg, 719.11k to 719.11k max (98.31%) Database : sq_gllutf8 Users : sq_szczkj@localhost : 100.00% (1) of query, 66.67% (2) of all users Query abstract: SELECT * FROM gll_pro_ru WHERE N = N ORDER BY id DESC; Query sample: select * from gll_pro_ru WHERE 1 = 1 ORDER BY id DESC; ______________________________________________________________________ 002 ___ Count : 1 (33.33%) Time : 5 s total, 5 s avg, 5 s to 5 s max (10.87%) Lock Time (s) : 0 total, 0 avg, 0 to 0 max (0.00%) Rows sent : 10.00k avg, 10.00k to 10.00k max (2.71%) Rows examined : 10.00k avg, 10.00k to 10.00k max (1.37%) Database : Users : sq_szczkj@localhost : 100.00% (1) of query, 66.67% (2) of all users Query abstract: SELECT * FROM gll_pro_ru WHERE N = N ORDER BY id DESC LIMIT N,N; Query sample: select * from gll_pro_ru WHERE 1 = 1 ORDER BY id DESC limit 0,10000; ______________________________________________________________________ 003 ___ Count : 1 (33.33%) Time : 2 s total, 2 s avg, 2 s to 2 s max (4.35%) Lock Time (s) : 0 total, 0 avg, 0 to 0 max (0.00%) Rows sent : 0 avg, 0 to 0 max (0.00%) Rows examined : 2.37k avg, 2.37k to 2.37k max (0.32%) Database : Users : debian-sys-maint[debian-sys-maint]@localhost : 100.00% (1) of query, 33.33% (1) of all users Query abstract: SELECT COUNT(*) INTO @discard FROM information_schema.columns; Query sample: select count(*) into @discard from `information_schema`.`COLUMNS`;
整体来说, 功能非常强大. 数据报表,非常有利于分析慢查询的原因, 包括执行频率, 数据量, 查询消耗等. 格式说明如下: 总查询次数 (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. 五种mysql日志分析工具比拼 mysql slow log 是用来记录执行时间较长(超过long_query_time秒)的sql的一种日志工具. 启用 slow log 有两种启用方式: 1, 在my.cnf 里 通过 log-slow-queries[=file_name] 2, 在mysqld进程启动时,指定–log-slow-queries[=file_name]选项 比较的五款常用工具 mysqldumpslow, mysqlsla, myprofi, mysql-explain-slow-log, mysqllogfilter
