MySQL 慢查詢日誌(Slow Query Log)，mysqlslow

MySQL 慢查詢日誌(Slow Query Log)，mysqlslow

    同大多數關係型資料庫一樣，記錄檔是MySQL資料庫的重要組成部分。MySQL有幾種不同的記錄檔，通常包括錯誤記錄檔檔案，二進位日誌，通用日誌，慢查詢日誌，等等。這些日誌可以協助我們定位mysqld內部發生的事件，資料庫效能故障，記錄資料的變更曆史，使用者恢複資料庫等等。本文主要描述通用查詢日誌。

 

1、MySQL記錄檔系統的組成
   a、錯誤記錄檔：記錄啟動、運行或停止mysqld時出現的問題。
   b、通用日誌：記錄建立的用戶端串連和執行的語句。
   c、更新日誌：記錄更改資料的語句。該日誌在MySQL 5.1中已不再使用。
   d、二進位日誌：記錄所有更改資料的語句。還用於複製。
   e、慢查詢日誌：記錄所有執行時間超過long_query_time秒的所有查詢或不使用索引的查詢。
   f、Innodb日誌：innodb redo log
   
   預設情況下，所有日誌建立於mysqld資料目錄中。
   可以通過重新整理日誌，來強制mysqld來關閉和重新開啟記錄檔（或者在某些情況下切換到一個新的日誌）。
   當你執行一個FLUSH LOGS語句或執行mysqladmin flush-logs或mysqladmin refresh時，則日誌被老化。
   對於存在MySQL複製的情形下，從複製伺服器將維護更多記錄檔，被稱為接替日誌。

 

2、慢查詢日誌
   慢查詢日誌是將mysql伺服器中影響資料庫效能的相關SQL語句記錄到記錄檔，通過對這些特殊的SQL語句分析，改進以達到提高資料庫效能的目的。
   通過使用--slow_query_log[={0|1}]選項來啟用慢查詢日誌。所有執行時間超過long_query_time秒的SQL語句都會被記錄到慢查詢日誌。
   預設情況下hostname-slow.log為慢查詢記錄檔安名，存放到資料目錄，同時預設情況下未開啟慢查詢日誌。
   預設情況下資料庫相關管理型SQL(比如OPTIMIZE TABLE、ANALYZE TABLE和ALTER TABLE)不會被記錄到日誌。
   對於管理型SQL可以通過--log-slow-admin-statements開啟記錄管理型慢SQL。
   mysqld在語句執行完並且所有鎖釋放後記入慢查詢日誌。記錄順序可以與執行順序不相同。獲得初使表鎖定的時間不算作執行時間。
   
   可以使用mysqldumpslow命令獲得日誌中顯示的查詢摘要來處理慢查詢日誌。
   用查詢快取處理的查詢不加到慢查詢日誌中，表有零行或一行而不能從索引中受益的查詢也不寫入慢查詢日誌。
   MySQL伺服器按以下順序記錄SQL是否寫入到慢查詢日誌
     a. The query must either not be an administrative statement, or --log-slow-adminstatements must have been specified.
     b. The query must have taken at least long_query_time seconds, or log_queries_not_using_indexes must be enabled and the query used no indexes for row lookups.
     c. The query must have examined at least min_examined_row_limit rows.
     d. The query must not be suppressed according to the log_throttle_queries_not_using_indexes setting.

 

3、慢查詢日誌示範

long_query_time     ：  設定慢查詢的閥值，超出次設定值的SQL即被記錄到慢查詢日誌，預設值為10sslow_query_log      ：  指定是否開啟慢查詢日誌log_slow_queries    ：  指定是否開啟慢查詢日誌(該參數要被slow_query_log取代，做相容性保留)slow_query_log_file ：  指定慢記錄檔存放位置，可以為空白，系統會給一個預設的檔案host_name-slow.logmin_examined_row_limit：查詢檢查返回少於該參數指定行的SQL不被記錄到慢查詢日誌log_queries_not_using_indexes: 不使用索引的慢查詢日誌是否記錄到索引    --目前的版本root@localhost[(none)]> show variables like 'version';+---------------+------------+| Variable_name | Value      |+---------------+------------+| version       | 5.5.39-log |+---------------+------------+root@localhost[(none)]> show variables like '%slow%';+---------------------+---------------------------------+| Variable_name       | Value                           |+---------------------+---------------------------------+| log_slow_queries    | OFF                             || slow_launch_time    | 2                               || slow_query_log      | OFF                             || slow_query_log_file | /var/lib/mysql/suse11b-slow.log |+---------------------+---------------------------------+root@localhost[tempdb]> set global log_slow_queries=1;Query OK, 0 rows affected, 1 warning (0.00 sec)root@localhost[(none)]> show warnings;+---------+------+-------------------------------------------------------------------------------------------------------------------+| Level   | Code | Message                                                                                                           |+---------+------+-------------------------------------------------------------------------------------------------------------------+| Warning | 1287 | '@@log_slow_queries' is deprecated and will be removed in a future release. Please use '@@slow_query_log' instead |+---------+------+-------------------------------------------------------------------------------------------------------------------+--從下面的查詢中可知，2個系統變數log_slow_queries，slow_query_log同時被置為onroot@localhost[(none)]> show variables like '%slow%';+---------------------+---------------------------------+| Variable_name       | Value                           |+---------------------+---------------------------------+| log_slow_queries    | ON                              || slow_launch_time    | 2                               || slow_query_log      | ON                              || slow_query_log_file | /var/lib/mysql/suse11b-slow.log |+---------------------+---------------------------------+root@localhost[tempdb]> show variables like '%long_query_time%';+-----------------+-----------+| Variable_name   | Value     |+-----------------+-----------+| long_query_time | 10.000000 |+-----------------+-----------+--為便於示範，我們將全域和session層級long_query_time設定為1root@localhost[tempdb]> set global long_query_time=1;Query OK, 0 rows affected (0.00 sec)root@localhost[tempdb]> set session long_query_time=1;Query OK, 0 rows affected (0.00 sec)--Author : Leshami--Blog   : http://blog.csdn.net/leshamiroot@localhost[tempdb]> create table tb_slow as select * from information_schema.columns;Query OK, 829 rows affected (0.10 sec)Records: 829  Duplicates: 0  Warnings: 0root@localhost[tempdb]> insert into tb_slow select * from tb_slow;Query OK, 829 rows affected (0.05 sec)Records: 829  Duplicates: 0  Warnings: 0       .....為便於示範，我們插入一些資料，中間重複過程省略root@localhost[tempdb]> insert into tb_slow select * from tb_slow;Query OK, 26528 rows affected (4.40 sec)Records: 26528  Duplicates: 0  Warnings: 0root@localhost[tempdb]> system tail  /var/lib/mysql/suse11b-slow.log/usr/sbin/mysqld, Version: 5.5.39-log (MySQL Community Server (GPL)). started with:Tcp port: 3306  Unix socket: /var/lib/mysql/mysql.sockTime                 Id Command    Argument# Time: 141004 22:05:48# User@Host: root[root] @ localhost []# Query_time: 4.396858  Lock_time: 0.000140 Rows_sent: 0  Rows_examined: 53056use tempdb;SET timestamp=1412431548;insert into tb_slow select * from tb_slow;    ....再次插入一些記錄....root@localhost[tempdb]> insert into tb_slow select * from tb_slow;Query OK, 212224 rows affected (37.51 sec)Records: 212224  Duplicates: 0  Warnings: 0root@localhost[tempdb]> select table_schema,table_name,count(*) from tb_slow    -> group by table_schema,table_name order by 3,2;+--------------------+----------------------------------------------+----------+| table_schema       | table_name                                   | count(*) |+--------------------+----------------------------------------------+----------+| information_schema | COLLATION_CHARACTER_SET_APPLICABILITY        |     1024 || performance_schema | cond_instances                               |     1024 |                  ...........| mysql              | user                                         |    21504 |+--------------------+----------------------------------------------+----------+83 rows in set (1.58 sec)                  root@localhost[tempdb]> system tail  /var/lib/mysql/suse11b-slow.log# User@Host: root[root] @ localhost []# Query_time: 37.514172  Lock_time: 0.000123 Rows_sent: 0  Rows_examined: 424448SET timestamp=1412431806;insert into tb_slow select * from tb_slow;# Time: 141004 22:10:47# User@Host: root[root] @ localhost []# Query_time: 1.573293  Lock_time: 0.000183 Rows_sent: 83  Rows_examined: 424614SET timestamp=1412431847;select table_schema,table_name,count(*) from tb_slow  --這條SQL被記錄下來了，其查詢時間為1.573293sgroup by table_schema,table_name order by 3,2;root@localhost[tempdb]> show variables like '%log_queries_not_using_indexes';+-------------------------------+-------+| Variable_name                 | Value |+-------------------------------+-------+| log_queries_not_using_indexes | OFF   |+-------------------------------+-------+root@localhost[tempdb]> set global log_queries_not_using_indexes=1;Query OK, 0 rows affected (0.00 sec)--查看錶tb_slow索引資訊，表tb_slow無任何索引root@localhost[tempdb]> show index from tb_slow;Empty set (0.00 sec)root@localhost[tempdb]> select count(*) from tb_slow;+----------+| count(*) |+----------+|   424448 |+----------+1 row in set (0.20 sec)root@localhost[tempdb]> system tail -n3 /var/lib/mysql/suse11b-slow.log# Query_time: 0.199840  Lock_time: 0.000152 Rows_sent: 1  Rows_examined: 424448SET timestamp=1412432188;select count(*) from tb_slow;   --此次查詢時間為0.199840，被記錄的原因是因為沒有走索引，因為表本身沒有索引

4、格式化慢查詢日誌

結構化慢查詢日誌就是把慢查詢日誌中的重要訊息按照便於閱讀以及按照特定的排序方式來提取SQL。這種方式有點類似於Oracle中有個tkprof來格式化oracle的trace檔案。對於前面的慢查詢日誌我們使用mysqldumpslow來提取如下：suse11b:~ # mysqldumpslow -s at,al /var/lib/mysql/suse11b-slow.logReading mysql slow query log from /var/lib/mysql/suse11b-slow.logCount: 4  Time=16.87s (67s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost  insert into tb_slow select * from tb_slowCount: 1  Time=0.20s (0s)  Lock=0.00s (0s)  Rows=1.0 (1), root[root]@localhost  select count(*) from tb_slowCount: 1  Time=1.57s (1s)  Lock=0.00s (0s)  Rows=83.0 (83), root[root]@localhost  select table_schema,table_name,count(*) from tb_slow  group by table_schema,table_name order by N,N#以下是按照最大耗用時間排最後，只顯示2條的方式格式化記錄檔suse11b:~ # mysqldumpslow -r -t 2 /var/lib/mysql/suse11b-slow.logReading mysql slow query log from /var/lib/mysql/suse11b-slow.logCount: 1  Time=1.57s (1s)  Lock=0.00s (0s)  Rows=83.0 (83), root[root]@localhost  select table_schema,table_name,count(*) from tb_slow  group by table_schema,table_name order by N,NCount: 4  Time=16.87s (67s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost  insert into tb_slow select * from tb_slow  #擷取mysqldumpslow的協助資訊suse11b:~ # mysqldumpslow --helpUsage: 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        #query的次數                 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

怎設定慢查詢日誌？預設mysql是不會記錄慢查詢日誌的，問怎設定讓其記錄慢查詢？

Linux:

在mysql設定檔my.cnf中增加

log-slow-queries=/var/lib/mysql/slowquery.log (指定記錄檔存放位置，可以為空白，系統會給一個預設的檔案host_name-slow.log)
long_query_time=2 (記錄超過的時間，預設為10s)
log-queries-not-using-indexes (log下來沒有使用索引的query,可以根據情況決定是否開啟)
log-long-format (如果設定了，所有沒有使用索引的查詢也將被記錄)

Windows:

在my.ini的[mysqld]添加如下語句：
log-slow-queries = E:\web\mysql\log\mysqlslowquery.log
long_query_time = 2(其他參數如上)
 
mysql 慢查詢

你看一下你的“long_query_time”配置的值是多少，這個是慢查詢的時間，只有超過這個時間的查詢才會在慢查詢日誌中記錄。
而不是所有查詢都會記入日誌。