MySQL慢查詢日誌總結

慢查詢日誌概念

     MySQL的慢查詢日誌是MySQL提供的一種日誌記錄，它用來記錄在MySQL中響應時間超過閥值的語句，具體指執行時間超過long_query_time值的SQL，則會被記錄到慢查詢日誌中。long_query_time的預設值為10，意思是執行10S以上的語句。預設情況下，Mysql資料庫並不啟動慢查詢日誌，需要我們手動來設定這個引數，當然，如果不是調優需要的話，一般不建議啟動該引數，因為開啟慢查詢日誌會或多或少帶來一定的效能影響。慢查詢日誌支援將日誌記錄寫入檔案，也支援將日誌記錄寫入資料庫表。

 

官方文件，關於慢查詢的日誌介紹如下（部分資料，具體參考官方相關連結）：

The slow query log consists of SQL statements that took more than long_query_time seconds to execute and required at least min_examined_row_limit rows to be examined. The minimum and default values of long_query_time are 0 and 10, respectively. The value can be specified to a resolution of microseconds. For logging to a file, times are written including the microseconds part. For logging to tables, only integer times are written; the microseconds part is ignored.

By default, administrative statements are not logged, nor are queries that do not use indexes for lookups. This behavior can be changed usinglog_slow_admin_statements and log_queries_not_using_indexes, as described later.

 

慢查詢日誌相關引數

MySQL 慢查詢的相關引數解釋：

slow_query_log    ：是否開啟慢查詢日誌，1表示開啟，0表示關閉。

log-slow-queries  ：舊版（5.6以下版本）MySQL資料庫慢查詢日誌儲存路徑。可以不設定該引數，系統則會預設給一個預設的檔案host_name-slow.log

slow-query-log-file：新版（5.6及以上版本）MySQL資料庫慢查詢日誌儲存路徑。可以不設定該引數，系統則會預設給一個預設的檔案host_name-slow.log

long_query_time ：慢查詢閾值，當查詢時間多於設定的閾值時，記錄日誌。

log_queries_not_using_indexes：未使用索引的查詢也被記錄到慢查詢日誌中（可選項）。

log_output：日誌儲存方式。log_output='FILE'表示將日誌存入檔案，預設值是'FILE'。log_output='TABLE'表示將日誌存入資料庫，這樣日誌資訊就會被寫入到mysql.slow_log表中。MySQL資料庫支援同時兩種日誌儲存方式，配置的時候以逗號隔開即可，如：log_output='FILE,TABLE'。日誌記錄到系統的專用日誌表中，要比記錄到檔案耗費更多的系統資源，因此對於需要啟用慢查詢日誌，又需要能夠獲得更高的系統效能，那麼建議優先記錄到檔案。

 

 

慢查詢日誌配置

預設情況下slow_query_log的值為OFF，表示慢查詢日誌是禁用的，可以透過設定slow_query_log的值來開啟，如下所示：

mysql> show variables  like '%slow_query_log%';
+---------------------+-----------------------------------------------+
| Variable_name       | Value                                         |
+---------------------+-----------------------------------------------+
| slow_query_log      | OFF                                           |
| slow_query_log_file | /home/WDPM/MysqlData/mysql/DB-Server-slow.log |
+---------------------+-----------------------------------------------+
2 rows in set (0.00 sec)

mysql> set global slow_query_log=1;
Query OK, 0 rows affected (0.09 sec)

mysql> show variables like '%slow_query_log%';
+---------------------+-----------------------------------------------+
| Variable_name       | Value                                         |
+---------------------+-----------------------------------------------+
| slow_query_log      | ON                                            |
| slow_query_log_file | /home/WDPM/MysqlData/mysql/DB-Server-slow.log |
+---------------------+-----------------------------------------------+
2 rows in set (0.00 sec)

mysql>

 

使用set global slow_query_log=1開啟了慢查詢日誌只對當前資料庫生效，如果MySQL重啟後則會失效。如果要永久生效，就必須修改配置檔案my.cnf（其它系統變數也是如此）。例如如下所示：

mysql> show variables like 'slow_query%';
+---------------------+-----------------------------------------------+
| Variable_name       | Value                                         |
+---------------------+-----------------------------------------------+
| slow_query_log      | OFF                                           |
| slow_query_log_file | /home/WDPM/MysqlData/mysql/DB-Server-slow.log |
+---------------------+-----------------------------------------------+
2 rows in set (0.01 sec)

mysql>

 

修改my.cnf檔案，增加或修改引數slow_query_log 和slow_query_log_file後，然後重啟MySQL伺服器，如下所示

slow_query_log =1

slow_query_log_file=/tmp/mysql_slow.log

mysql> show variables like 'slow_query%';
+---------------------+---------------------+
| Variable_name       | Value               |
+---------------------+---------------------+
| slow_query_log      | ON                  |
| slow_query_log_file | /tmp/mysql_slow.log |
+---------------------+---------------------+
2 rows in set (0.00 sec)

mysql>

關於慢查詢的引數slow_query_log_file ，它指定慢查詢日誌檔案的存放路徑，系統預設會給一個預設的檔案host_name-slow.log（如果沒有指定引數slow_query_log_file的話）

mysql> show variables like 'slow_query_log_file';
+---------------------+-----------------------------------------------+
| Variable_name       | Value                                         |
+---------------------+-----------------------------------------------+
| slow_query_log_file | /home/WDPM/MysqlData/mysql/DB-Server-slow.log |
+---------------------+-----------------------------------------------+
1 row in set (0.00 sec)

 

那麼開啟了慢查詢日誌後，什麼樣的SQL才會記錄到慢查詢日誌裡面呢？ 這個是由引數long_query_time控制，預設情況下long_query_time的值為10秒，可以使用命令修改，也可以在my.cnf引數裡面修改。關於執行時間正好等於long_query_time的情況，並不會被記錄下來。也就是說，在mysql原始碼裡是判斷大於long_query_time，而非大於等於。從MySQL 5.1開始，long_query_time開始以微秒記錄SQL語句執行時間，之前僅用秒為單位記錄。如果記錄到表裡面，只會記錄整數部分，不會記錄微秒部分。

mysql> show variables like 'long_query_time%';
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)

mysql> set global long_query_time=4;
Query OK, 0 rows affected (0.00 sec)

mysql> show variables like 'long_query_time';
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)

 

如上所示，我修改了變數long_query_time，但是查詢變數long_query_time的值還是10，難道沒有修改到呢？注意：使用命令 set global long_query_time=4修改後，需要重新連線或新開一個會話才能看到修改值。你用show variables like 'long_query_time'檢視是當前會話的變數值，你也可以不用重新連線會話，而是用show global variables like 'long_query_time'; 如下所示：

在MySQL裡面執行下面SQL語句，然後我們去檢查對應的慢查詢日誌，就會發現類似下面這樣的資訊。

mysql> select sleep(3);
+----------+
| sleep(3) |
+----------+
|        0 |
+----------+
1 row in set (3.00 sec)

[root@DB-Server ~]# more /tmp/mysql_slow.log
/usr/sbin/mysqld, Version: 5.6.20-enterprise-commercial-advanced-log (MySQL Enterprise Server - Advanced Edition (Commercial)). started with:
Tcp port: 0  Unix socket: (null)
Time                 Id Command    Argument
/usr/sbin/mysqld, Version: 5.6.20-enterprise-commercial-advanced-log (MySQL Enterprise Server - Advanced Edition (Commercial)). started with:
Tcp port: 0  Unix socket: (null)
Time                 Id Command    Argument
# Time: 160616 17:24:35
# User@Host: root[root] @ localhost []  Id:     5
# Query_time: 3.002615  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
SET timestamp=1466069075;
select sleep(3);

 

log_output 引數是指定日誌的儲存方式。log_output='FILE'表示將日誌存入檔案，預設值是'FILE'。log_output='TABLE'表示將日誌存入資料庫，這樣日誌資訊就會被寫入到mysql.slow_log表中。MySQL資料庫支援同時兩種日誌儲存方式，配置的時候以逗號隔開即可，如：log_output='FILE,TABLE'。日誌記錄到系統的專用日誌表中，要比記錄到檔案耗費更多的系統資源，因此對於需要啟用慢查詢日誌，又需要能夠獲得更高的系統效能，那麼建議優先記錄到檔案。

mysql> show variables like '%log_output%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_output    | FILE  |
+---------------+-------+
1 row in set (0.00 sec)

mysql> set global log_output='TABLE';
Query OK, 0 rows affected (0.00 sec)

mysql> show variables like '%log_output%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_output    | TABLE |
+---------------+-------+
1 row in set (0.00 sec)

mysql> select sleep(5) ;
+----------+
| sleep(5) |
+----------+
|        0 |
+----------+
1 row in set (5.00 sec)

mysql>

mysql> select * from mysql.slow_log;
+---------------------+---------------------------+------------+-----------+-----------+---------------+----+----------------+-----------+-----------+-----------------+-----------+
| start_time          | user_host                 | query_time | lock_time | rows_sent | rows_examined | db | last_insert_id | insert_id | server_id | sql_text        | thread_id |
+---------------------+---------------------------+------------+-----------+-----------+---------------+----+----------------+-----------+-----------+-----------------+-----------+
| 2016-06-16 17:37:53 | root[root] @ localhost [] | 00:00:03   | 00:00:00  |         1 |             0 |    |              0 |         0 |         1 | select sleep(3) |         5 |
| 2016-06-16 21:45:23 | root[root] @ localhost [] | 00:00:05   | 00:00:00  |         1 |             0 |    |              0 |         0 |         1 | select sleep(5) |         2 |
+---------------------+---------------------------+------------+-----------+-----------+---------------+----+----------------+-----------+-----------+-----------------+-----------+
2 rows in set (0.00 sec)

mysql>

 

系統變數log-queries-not-using-indexes：未使用索引的查詢也被記錄到慢查詢日誌中（可選項）。如果調優的話，建議開啟這個選項。另外，開啟了這個引數，其實使用full index scan的sql也會被記錄到慢查詢日誌。

This option does not necessarily mean that no index is used. For example, a query that uses a full index scan uses an index but would be logged because the index would not limit the number of rows.

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> set global log_queries_not_using_indexes=1;
Query OK, 0 rows affected (0.00 sec)

mysql> show variables like 'log_queries_not_using_indexes';
+-------------------------------+-------+
| Variable_name                 | Value |
+-------------------------------+-------+
| log_queries_not_using_indexes | ON    |
+-------------------------------+-------+
1 row in set (0.00 sec)

mysql>

系統變數log_slow_admin_statements表示是否將慢管理語句例如ANALYZE TABLE和ALTER TABLE等記入慢查詢日誌

mysql> show variables like 'log_slow_admin_statements';
+---------------------------+-------+
| Variable_name             | Value |
+---------------------------+-------+
| log_slow_admin_statements | OFF   |
+---------------------------+-------+
1 row in set (0.00 sec)

mysql>

 

系統變數log_slow_slave_statements 表示

By default, a replication slave does not write replicated queries to the slow query log. To change this, use thelog_slow_slave_statements system variable.

When the slow query log is enabled, this variable enables logging for queries that have taken more than long_query_time seconds to execute on the slave. This variable was added in MySQL 5.7.1. Setting this variable has no immediate effect. The state of the variable applies on all subsequent START SLAVE statements.

 

引數--log-short-format

The server writes less information to the slow query log if you use the --log-short-format option.

Command-Line Format	--log-short-format
Permitted Values	Type	boolean
	Default	FALSE

 

另外，如果你想查詢有多少條慢查詢記錄，可以使用系統變數。

mysql> show global status like '%Slow_queries%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Slow_queries  | 2104  |
+---------------+-------+
1 row in set (0.00 sec)

mysql>

 

日誌分析工具mysqldumpslow

在生產環境中，如果要手工分析日誌，查詢、分析SQL，顯然是個體力活，MySQL提供了日誌分析工具mysqldumpslow

檢視mysqldumpslow的幫助資訊：

[root@DB-Server ~]# 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

-s, 是表示按照何種方式排序，

c: 訪問計數

l: 鎖定時間

r: 返回記錄

t: 查詢時間

al:平均鎖定時間

ar:平均返回記錄數

at:平均查詢時間

-t, 是top n的意思，即為返回前面多少條的資料；

-g, 後邊可以寫一個正則匹配模式，大小寫不敏感的；

比如

得到返回記錄集最多的10個SQL。

mysqldumpslow -s r -t 10 /database/mysql/mysql06_slow.log

得到訪問次數最多的10個SQL

mysqldumpslow -s c -t 10 /database/mysql/mysql06_slow.log

得到按照時間排序的前10條裡面含有左連線的查詢語句。

mysqldumpslow -s t -t 10 -g “left join” /database/mysql/mysql06_slow.log

另外建議在使用這些命令時結合 | 和more 使用 ，否則有可能出現刷屏的情況。

mysqldumpslow -s r -t 20 /mysqldata/mysql/mysql06-slow.log | more

 

參考資料：

https://dev.mysql.com/doc/refman/5.7/en/slow-query-log.html

https://dev.mysql.com/doc/refman/5.7/en/server-system-variables.html#sysvar_long_query_time