慢查询有什么用？
它能记录下所有执行超过long_query_time时间的SQL语句，帮你找到执行慢的SQL，方便我们对这些SQL进行优化。
测试用 MySQL 版本：Server version: 5.6.10-log Source distribution
未做任何慢日志设置时。
mysql> show variables like "%query%"; +------------------------------+--------------------------------------+ | Variable_name | Value | +------------------------------+--------------------------------------+ | binlog_rows_query_log_events | OFF | | ft_query_expansion_limit | 20 | | have_query_cache | YES | | long_query_time | 10.000000 | | query_alloc_block_size | 8192 | | query_cache_limit | 1048576 | | query_cache_min_res_unit | 4096 | | query_cache_size | 1048576 | | query_cache_type | OFF | | query_cache_wlock_invalidate | OFF | | query_prealloc_size | 8192 | | slow_query_log | OFF | | slow_query_log_file | /usr/local/mysql/data/Betty-slow.log | +------------------------------+--------------------------------------+ 13 rows in set (0.01 sec) mysql>
修改配置文件，开启 slow log 。 [chinastor.com-root@Betty data]# vi /etc/my.cnf # For advice on how to change settings please see # http://dev.mysql.com/doc/refman/5.6/en/server-configuration-defaults.html # *** DO NOT EDIT THIS FILE. It's a template which will be copied to the # *** default location during install, and will be replaced if you # *** upgrade to a newer version of MySQL. [mysqld] # Remove leading # and set to the amount of RAM for the most important data # cache in MySQL. Start at 70% of total RAM for dedicated server, else 10%. # innodb_buffer_pool_size = 128M # Remove leading # to turn on a very important data integrity option: logging # changes to the binary log between backups. log_bin=mysql-bin slow_query_log=on slow_query_log_file=mysql-slow long_query_time=2 # These are commonly set, remove the # and set as required. # basedir = ..... # datadir = ..... # port = ..... # server_id = ..... # socket = ..... # Remove leading # to set options mainly useful for reporting servers. # The server defaults are faster for transactions and fast SELECTs. # Adjust sizes as needed, experiment to find the optimal values. # join_buffer_size = 128M # sort_buffer_size = 2M # read_rnd_buffer_size = 2M sql_mode=NO_ENGINE_SUBSTITUTION,STRICT_TRANS_TABLES [mysql] socket = /tmp/mysql.sock
重启 MySQL 。 [chinastor.com-root@Betty data]# /etc/init.d/mysql restart Shutting down MySQL.. [ OK ] Starting MySQL. [ OK ] [chinastor.com-root@Betty data]#
查看 slow log 。 [chinastor.com-root@Betty data]# ll mysql-slow -rw-rw---- 1 mysql mysql 719 Sep 6 12:43 mysql-slow
重新查看系统变量值。 mysql> mysql> show variables like "%query%"; +------------------------------+------------+ | Variable_name | Value | +------------------------------+------------+ | binlog_rows_query_log_events | OFF | | ft_query_expansion_limit | 20 | | have_query_cache | YES | | long_query_time | 2.000000 | | query_alloc_block_size | 8192 | | query_cache_limit | 1048576 | | query_cache_min_res_unit | 4096 | | query_cache_size | 1048576 | | query_cache_type | OFF | | query_cache_wlock_invalidate | OFF | | query_prealloc_size | 8192 | | slow_query_log | ON | | slow_query_log_file | mysql-slow | +------------------------------+------------+ 13 rows in set (0.00 sec) mysql>
查看新生成的 slow log 的内容。 [chinastor.com-root@Betty data]# cat mysql-slow /usr/local/mysql/bin/mysqld, Version: 5.6.10-log (Source distribution). started with: Tcp port: 0 Unix socket: (null) Time Id Command Argument [chinastor.com-root@Betty data]#
测试 slow log 。 mysql> mysql> select 1; +---+ | 1 | +---+ | 1 | +---+ 1 row in set (0.00 sec) mysql> mysql> select sleep(1); +----------+ | sleep(1) | +----------+ | 0 | +----------+ 1 row in set (1.00 sec) mysql> mysql> mysql> select sleep(3); +----------+ | sleep(3) | +----------+ | 0 | +----------+ 1 row in set (3.00 sec) mysql> mysql> select sleep(4); +----------+ | sleep(4) | +----------+ | 0 | +----------+ 1 row in set (4.01 sec) mysql> mysql> mysql> select sleep(5); +----------+ | sleep(5) | +----------+ | 0 | +----------+ 1 row in set (5.00 sec) mysql> select sleep(2); +----------+ | sleep(2) | +----------+ | 0 | +----------+ 1 row in set (2.01 sec) mysql> mysql> select sleep(1); +----------+ | sleep(1) | +----------+ | 0 | +----------+ 1 row in set (1.00 sec) mysql> select 2; +---+ | 2 | +---+ | 2 | +---+ 1 row in set (0.00 sec) mysql>
查看此时 slow log 的内容。 [chinastor.com-root@Betty data]# cat mysql-slow /usr/local/mysql/bin/mysqld, Version: 5.6.10-log (Source distribution). started with: Tcp port: 0 Unix socket: (null) Time Id Command Argument # Time: 130906 12:52:51 # User@Host: root[root] @ localhost [] Id: 1 # Query_time: 3.002864 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 SET timestamp=1378443171; select sleep(3); # Time: 130906 12:53:01 # User@Host: root[root] @ localhost [] Id: 1 # Query_time: 4.001943 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 SET timestamp=1378443181; select sleep(4); # Time: 130906 12:53:09 # User@Host: root[root] @ localhost [] Id: 1 # Query_time: 5.002093 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 SET timestamp=1378443189; select sleep(5); # Time: 130906 12:53:15 # User@Host: root[root] @ localhost [] Id: 1 # Query_time: 2.002984 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 SET timestamp=1378443195; select sleep(2); [chinastor.com-root@Betty data]#
实验：
慢查询有什么用？ 它能记录下所有执行超过long_query_time时间的SQL语句，帮你找到执行慢的SQL，方便我们对这些SQL进行优化。 测试用 MySQL 版本：Server version: 5.6.10-log Source distribution 未做任何慢日志设置时。 mysql> show variables like "%query%"; +------------------------------+--------------------------------------+ | Variable_name | Value | +------------------------------+--------------------------------------+ | binlog_rows_query_log_events | OFF | | ft_query_expansion_limit | 20 | | have_query_cache | YES | | long_query_time | 10.000000 | | query_alloc_block_size | 8192 | | query_cache_limit | 1048576 | | query_cache_min_res_unit | 4096 | | query_cache_size | 1048576 | | query_cache_type | OFF | | query_cache_wlock_invalidate | OFF | | query_prealloc_size | 8192 | | slow_query_log | OFF | | slow_query_log_file | /usr/local/mysql/data/Betty-slow.log | +------------------------------+--------------------------------------+ 13 rows in set (0.01 sec) mysql>
修改配置文件，开启 slow log 。 [chinastor.com-root@Betty data]# vi /etc/my.cnf # For advice on how to change settings please see # http://dev.mysql.com/doc/refman/5.6/en/server-configuration-defaults.html # *** DO NOT EDIT THIS FILE. It's a template which will be copied to the # *** default location during install, and will be replaced if you # *** upgrade to a newer version of MySQL. [mysqld] # Remove leading # and set to the amount of RAM for the most important data # cache in MySQL. Start at 70% of total RAM for dedicated server, else 10%. # innodb_buffer_pool_size = 128M # Remove leading # to turn on a very important data integrity option: logging # changes to the binary log between backups. log_bin=mysql-bin slow_query_log=on slow_query_log_file=mysql-slow long_query_time=2 # These are commonly set, remove the # and set as required. # basedir = ..... # datadir = ..... # port = ..... # server_id = ..... # socket = ..... # Remove leading # to set options mainly useful for reporting servers. # The server defaults are faster for transactions and fast SELECTs. # Adjust sizes as needed, experiment to find the optimal values. # join_buffer_size = 128M # sort_buffer_size = 2M # read_rnd_buffer_size = 2M sql_mode=NO_ENGINE_SUBSTITUTION,STRICT_TRANS_TABLES [mysql] socket = /tmp/mysql.sock
重启 MySQL 。 [chinastor.com-root@Betty data]# /etc/init.d/mysql restart Shutting down MySQL.. [ OK ] Starting MySQL. [ OK ] [chinastor.com-root@Betty data]#
查看 slow log 。 [chinastor.com-root@Betty data]# ll mysql-slow -rw-rw---- 1 mysql mysql 719 Sep 6 12:43 mysql-slow
重新查看系统变量值。 mysql> mysql> show variables like "%query%"; +------------------------------+------------+ | Variable_name | Value | +------------------------------+------------+ | binlog_rows_query_log_events | OFF | | ft_query_expansion_limit | 20 | | have_query_cache | YES | | long_query_time | 2.000000 | | query_alloc_block_size | 8192 | | query_cache_limit | 1048576 | | query_cache_min_res_unit | 4096 | | query_cache_size | 1048576 | | query_cache_type | OFF | | query_cache_wlock_invalidate | OFF | | query_prealloc_size | 8192 | | slow_query_log | ON | | slow_query_log_file | mysql-slow | +------------------------------+------------+ 13 rows in set (0.00 sec) mysql>
查看新生成的 slow log 的内容。 [chinastor.com-root@Betty data]# cat mysql-slow /usr/local/mysql/bin/mysqld, Version: 5.6.10-log (Source distribution). started with: Tcp port: 0 Unix socket: (null) Time Id Command Argument [chinastor.com-root@Betty data]#
测试 slow log 。 mysql> mysql> select 1; +---+ | 1 | +---+ | 1 | +---+ 1 row in set (0.00 sec) mysql> mysql> select sleep(1); +----------+ | sleep(1) | +----------+ | 0 | +----------+ 1 row in set (1.00 sec) mysql> mysql> mysql> select sleep(3); +----------+ | sleep(3) | +----------+ | 0 | +----------+ 1 row in set (3.00 sec) mysql> mysql> select sleep(4); +----------+ | sleep(4) | +----------+ | 0 | +----------+ 1 row in set (4.01 sec) mysql> mysql> mysql> select sleep(5); +----------+ | sleep(5) | +----------+ | 0 | +----------+ 1 row in set (5.00 sec) mysql> select sleep(2); +----------+ | sleep(2) | +----------+ | 0 | +----------+ 1 row in set (2.01 sec) mysql> mysql> select sleep(1); +----------+ | sleep(1) | +----------+ | 0 | +----------+ 1 row in set (1.00 sec) mysql> select 2; +---+ | 2 | +---+ | 2 | +---+ 1 row in set (0.00 sec) mysql>
查看此时 slow log 的内容。 [chinastor.com-root@Betty data]# cat mysql-slow /usr/local/mysql/bin/mysqld, Version: 5.6.10-log (Source distribution). started with: Tcp port: 0 Unix socket: (null) Time Id Command Argument # Time: 130906 12:52:51 # User@Host: root[root] @ localhost [] Id: 1 # Query_time: 3.002864 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 SET timestamp=1378443171; select sleep(3); # Time: 130906 12:53:01 # User@Host: root[root] @ localhost [] Id: 1 # Query_time: 4.001943 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 SET timestamp=1378443181; select sleep(4); # Time: 130906 12:53:09 # User@Host: root[root] @ localhost [] Id: 1 # Query_time: 5.002093 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 SET timestamp=1378443189; select sleep(5); # Time: 130906 12:53:15 # User@Host: root[root] @ localhost [] Id: 1 # Query_time: 2.002984 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 SET timestamp=1378443195; select sleep(2); [chinastor.com-root@Betty data]#
实验：
a. 使用 mysql 自带慢查询日志分析工具 mysqldumpslow 。 [chinastor.com-root@Betty data]# mysqldumpslow mysql-slow Reading mysql slow query log from mysql-slow Count: 4 Time=3.50s (14s) Lock=0.00s (0s) Rows=1.0 (4), root[root]@localhost select sleep(N) [chinastor.com-root@Betty data]#
b. 使用 hackmysql.com 推出的一款日志分析工具 mysqlsla 。 [chinastor.com-root@Betty data]# mysqlsla -lt slow mysql-slow Report for slow logs: mysql-slow 4 queries total, 1 unique Sorted by 't_sum' Grand Totals: Time 14 s, Lock 0 s, Rows sent 4, Rows Examined 0 ______________________________________________________________________ 001 ___ Count : 4 (100.00%) Time : 14.009884 s total, 3.502471 s avg, 2.002984 s to 5.002093 s max (100.00%) Lock Time (s) : 0 total, 0 avg, 0 to 0 max (0.00%) Rows sent : 1 avg, 1 to 1 max (100.00%) Rows examined : 0 avg, 0 to 0 max (0.00%) Database : Users : chinastor.com-root@localhost : 100.00% (4) of query, 100.00% (4) of all users Query abstract: SET timestamp=N; SELECT sleep(N); Query sample: SET timestamp=1378443171; select sleep(3); [chinastor.com-root@Betty data]#
c. 使用德国人写的 mysql_explain_slow_log 。（不知道为什么未统计出信息） [chinastor.com-root@Betty WGET_DIR]# ./mysql_explain_slow_log --user=root --password= --socket=/tmp/mysql.sock < /usr/local/mysql/data/mysql-slow mysql_explain_slow_log ====================== Index usage ------------------------------------ Queries causing table scans ------------------- Sum: 0 table scans Summary --------------------------------------- Select: 0 queries Update: 0 queries Load: 0 queries Logfile: 26 lines Started: Fri Sep 6 15:59:13 2013 Finished: Fri Sep 6 15:59:13 2013 [chinastor.com-root@Betty WGET_DIR]#
d. google code 上的一个分析工具 mysql_filter_slow_log （最后更新日期为2007年），提供了 python 和 php 两种可执行的脚本。 [chinastor.com-root@Betty WGET_DIR]# python mysql_filter_slow_log.py /usr/local/mysql/data/mysql-slow --no-duplicates --sort-execution-count --top=10 # Execution count: 1 time on 2013-09-06 16:07:23. # Column : avg | max | sum # Query time : 5 | 5 | 5 # Lock time : 0 | 0 | 0 # Rows examined: 0 | 0 | 0 # Rows sent : 1 | 1 | 1 # User@Host: root[root] @ localhost [] Id: 1 SET timestamp=1378454843;select sleep(5); # Execution count: 1 time on 2013-09-06 16:07:15. # Column : avg | max | sum # Query time : 4 | 4 | 4 # Lock time : 0 | 0 | 0 # Rows examined: 0 | 0 | 0 # Rows sent : 1 | 1 | 1 # User@Host: root[root] @ localhost [] Id: 1 SET timestamp=1378454835;select sleep(4); # Execution count: 1 time on 2013-09-06 16:07:01. # Column : avg | max | sum # Query time : 3 | 3 | 3 # Lock time : 0 | 0 | 0 # Rows examined: 0 | 0 | 0 # Rows sent : 1 | 1 | 1 # User@Host: root[root] @ localhost [] Id: 1 SET timestamp=1378454821;select sleep(3); # Execution count: 1 time on 2013-09-06 16:07:28. # Column : avg | max | sum # Query time : 2 | 2 | 2 # Lock time : 0 | 0 | 0 # Rows examined: 0 | 0 | 0 # Rows sent : 1 | 1 | 1 # User@Host: root[root] @ localhost [] Id: 1 SET timestamp=1378454848;select sleep(2); [chinastor.com-root@Betty WGET_DIR]#
e. 使用 percona-toolkit 中的 pt-query-digest （在《高性能MySQL》中多次提出，值得使用的工具）。 [chinastor.com-root@Betty data]# pt-query-digest --user=root mysql-slow # 120ms user time, 10ms system time, 20.21M rss, 68.70M vsz # Current date: Mon Sep 9 13:21:38 2013 # Hostname: Betty # Files: mysql-slow # Overall: 4 total, 1 unique, 0.15 QPS, 0.52x concurrency ________________ # Time range: 2013-09-06 16:07:01 to 16:07:28 # Attribute total min max avg 95% stddev median # ============ ======= ======= ======= ======= ======= ======= ======= # Exec time 14s 2s 5s 4s 5s 1s 4s # Lock time 0 0 0 0 0 0 0 # Rows sent 4 1 1 1 1 0 1 # Rows examine 0 0 0 0 0 0 0 # Query size 60 15 15 15 15 0 15 # Profile # Rank Query ID Response time Calls R/Call V/M Item # ==== ================== ============== ===== ====== ===== ====== # 1 0xF9A57DD5A41825CA 14.0097 100.0% 4 3.5024 0.36 SELECT # Query 1: 0.15 QPS, 0.52x concurrency, ID 0xF9A57DD5A41825CA at byte 548 # This item is included in the report because it matches --limit. # Scores: V/M = 0.36 # Time range: 2013-09-06 16:07:01 to 16:07:28 # Attribute pct total min max avg 95% stddev median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count 100 4 #