MySQL之慢查询日志(1)

发布时间：2013-09-12 09:30 来源：未知

慢查询有什么用？  

它能记录下所有执行超过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 # Exec time    100     14s      2s      5s      4s      5s      1s      4s # Lock time      0       0       0       0       0       0       0       0 # Rows sent    100       4       1       1       1       1       0       1 # Rows examine   0       0       0       0       0       0       0       0 # Query size   100      60      15      15      15      15       0      15 # String: # Hosts        localhost # Users        root # Query_time distribution #   1us #  10us # 100us #   1ms #  10ms # 100ms #    1s  ################################################################ #  10s+ # EXPLAIN /*!50100 PARTITIONS*/ select sleep(5)\G [chinastor.com-root@Betty data]# 

# I.e. you could add the following lines under the [mysqld] section of your my.ini or my.cnf configuration file:  # Log all queries taking more than 3 seconds long_query_time=3  # minimum: 1, default: 10  # MySQL >= 5.1.21 (or patched): 3 seconds = 3000000 microseconds # long_query_time=3.000000  # minimum: 0.000001 (1 microsecond)  # Activate the Slow Query Log slow_query_log  # >= 5.1.29 # log-slow-queries  # deprecated since 5.1.29  # Write to a custom file name (>= 5.1.29) # slow_query_log_file=file_name  # default: /data_dir/host_name-slow.log  # Log all queries without indexes # log-queries-not-using-indexes  # Log only queries which examine at least N rows (>= 5.1.21) # min_examined_row_limit=1000  # default: 0  # Log slow OPTIMIZE TABLE, ANALYZE TABLE, and ALTER TABLE statements # log-slow-admin-statements  # Log slow queries executed by replication slaves (>= 5.1.21) # log-slow-slave-statements  # MySQL 5.1.6 through 5.1.20 had a default value of log-output=TABLE, so you should force # Attention: logging to TABLE only includes whole seconds information log-output=FILE   ## Admin query for online activation is possible since MySQL 5.1 (without server restart) ## SET @@global.slow_query_log=1 ## SET @@global.long_query_time=1   ## Show current variables related to the Slow Query Log ## SHOW GLOBAL VARIABLES WHERE Variable_name REGEXP 'admin|min_examined|log_output|log_queries|log_slave|long|slow_quer' 

原文链接：http://my.oschina.net/moooofly/blog/160201