mysql中的慢查詢日誌

標籤：

首先我們看一下關於mysql中的日誌，主要包含：錯誤記錄檔、查詢日誌、慢查詢日誌、交易記錄、二進位日誌；

日誌是mysql資料庫的重要組成部分。記錄檔中記錄著mysql資料庫運行期間發生的變化；也就是說用來記錄mysql資料庫的客 戶端串連狀況、SQL語句的執行情況和錯誤資訊等。當資料庫遭到意外的損壞時，可以通過日誌查看檔案出錯的原因，並且可以通過記錄檔進行資料恢複。

先看一下日誌參數

mysql> show variables like ‘%log%‘;+-----------------------------------------+---------------------------------------+| Variable_name                           | Value                                 |+-----------------------------------------+---------------------------------------+| back_log                                | 80                                    || binlog_cache_size                       | 32768                                 || binlog_checksum                         | CRC32                                 || binlog_direct_non_transactional_updates | OFF                                   || binlog_error_action                     | IGNORE_ERROR                          || binlog_format                           | STATEMENT                             || binlog_gtid_simple_recovery             | OFF                                   || binlog_max_flush_queue_time             | 0                                     || binlog_order_commits                    | ON                                    || binlog_row_image                        | FULL                                  || binlog_rows_query_log_events            | OFF                                   || binlog_stmt_cache_size                  | 32768                                 || binlogging_impossible_mode              | IGNORE_ERROR                          || expire_logs_days                        | 0                                     || general_log                             | OFF                                   || general_log_file                        | /data/mysql/localhost.log             || innodb_api_enable_binlog                | OFF                                   || innodb_flush_log_at_timeout             | 1                                     || innodb_flush_log_at_trx_commit          | 1                                     || innodb_locks_unsafe_for_binlog          | OFF                                   || innodb_log_buffer_size                  | 8388608                               || innodb_log_compressed_pages             | ON                                    || innodb_log_file_size                    | 50331648                              || innodb_log_files_in_group               | 2                                     || innodb_log_group_home_dir               | ./                                    || innodb_mirrored_log_groups              | 1                                     || innodb_online_alter_log_max_size        | 134217728                             || innodb_undo_logs                        | 128                                   || log_bin                                 | OFF                                   || log_bin_basename                        |                                       || log_bin_index                           |                                       || log_bin_trust_function_creators         | OFF                                   || log_bin_use_v1_row_events               | OFF                                   || log_error                               | /data/mysql/localhost.localdomain.err || log_output                              | FILE                                  || log_queries_not_using_indexes           | OFF                                   || log_slave_updates                       | OFF                                   || log_slow_admin_statements               | OFF                                   || log_slow_slave_statements               | OFF                                   || log_throttle_queries_not_using_indexes  | 0                                     || log_warnings                            | 1                                     || max_binlog_cache_size                   | 18446744073709547520                  || max_binlog_size                         | 1073741824                            || max_binlog_stmt_cache_size              | 18446744073709547520                  || max_relay_log_size                      | 0                                     || relay_log                               |                                       || relay_log_basename                      |                                       || relay_log_index                         |                                       || relay_log_info_file                     | relay-log.info                        || relay_log_info_repository               | FILE                                  || relay_log_purge                         | ON                                    || relay_log_recovery                      | OFF                                   || relay_log_space_limit                   | 0                                     || simplified_binlog_gtid_recovery         | OFF                                   || slow_query_log                          | OFF                                   || slow_query_log_file                     | /data/mysql/localhost-slow.log        || sql_log_bin                             | ON                                    || sql_log_off                             | OFF                                   || sync_binlog                             | 0                                     || sync_relay_log                          | 10000                                 || sync_relay_log_info                     | 10000                                 |+-----------------------------------------+---------------------------------------+61 rows in set (0.03 sec)

 看一下slow參數

mysql> show variables like ‘%slow%‘;+---------------------------+--------------------------------+| Variable_name             | Value                          |+---------------------------+--------------------------------+| log_slow_admin_statements | OFF                            || log_slow_slave_statements | OFF                            || slow_launch_time          | 2                              || slow_query_log            | OFF                            || slow_query_log_file       | /data/mysql/localhost-slow.log |+---------------------------+--------------------------------+5 rows in set (0.00 sec)

 global slow

mysql> show global status like ‘%slow%‘;+---------------------+-------+| Variable_name       | Value |+---------------------+-------+| Slow_launch_threads | 0     || Slow_queries        | 0     |+---------------------+-------+

 

一、關於一些參數的解釋

1、slow_launch_time：如果建立線程的時間超過該秒數，伺服器增加Slow_launch_threads狀態變數。
2、slow_query_log：是否記錄慢查詢。用long_query_time變數的值來確定“慢查詢”。
3、slow_query_log_file：慢記錄檔路徑
4、long_query_time：慢日誌執行時間長度（秒），超過設定的時間才會記日誌
5、log-slow-admin-statements：一些管理指令，也會被記錄。比如OPTIMEZE TABLE, ALTER TABLE等等
6、log-queries-not-using-indexes：MySQL會將沒有使用索引的查詢記錄到slow query日誌中。無論它執行有多快，查詢語句沒有使用索引，都會被記錄。有的時候，有些沒有使用引索的查詢非常快(例如掃描很小的表)，但也有可能導致伺服器變慢，甚至還會使用大量的磁碟空間。

 

二、配置

#將下列配置放到my.cnf中

[mysqld]slow_query_log_file = /var/lib/mysql/slow-queries.log  log_slow_queries = ONlong_query_time = 1log-queries-not-using-indexeslog-slow-admin-statements

我們也可以登入之後進行配置

set global slow_query_log=on;set global slow_query_log_file = /var/lib/mysql/slow-queries.log  ;set global long_query_time=1;set gloabl log_slow_admin_statements=on;set global  log_queries_not_using_indexes = on;

 查看日誌

[[email protected] config]$ sudo  tail -f /var/lib/mysql/dev-slow.logSET timestamp=1437572901;show warnings;# Time: 150722 21:48:49# [email protected]: root[root] @ localhost []# Query_time: 0.021936  Lock_time: 0.000121 Rows_sent: 1  Rows_examined: 5294SET timestamp=1437572929;select sql_no_cache  id,bid,pic,cateid,title,tag,indextitle,dateline,summary from acc_info_article  where  status=1 and  find_in_set("84",bid)  order by sort asc  limit 1;/usr/libexec/mysqld, Version: 5.5.29-log (MySQL Community Server (GPL)). started with:Tcp port: 3306  Unix socket: /var/lib/mysql/mysql.sock

 說明

第一行：執行時間第二行：執行使用者第三行（重要）Query_time SQL執行的時間,越長則越慢Lock_time 在MySQL伺服器階段(不是在儲存引擎階段)等待表鎖時間Rows_sent 查詢返回的行數Rows_examined 查詢檢查的行數

1、日誌不能說明一切問題，可能跟鎖表、系統繁忙的偶發性有關，

a、鎖表，導致查詢處於等態狀態，lock_time顯示了查詢等待鎖被翻譯的時間
b、資料或索引沒有被緩衝,常見於第一次啟動伺服器或者伺服器沒有調優
c、備份資料庫，I/O變慢，
d、同時運行了其它的查詢，減少了當前查詢，
e、當然，如果某條SQL語句經常查詢慢那基本可以判斷是可以再次最佳化的

2、不要開啟log-queries-not-using-indexes（沒有索引查詢記錄功能）

a、這個功能實際用處不大，就是記錄SQL查詢的時候，沒有索引的通通記錄
b、雖然索引對查詢的速度有影響，但要看資料量大小
c、因為開啟了這個功能以後，select * from blog這樣的查詢也會被記錄在日誌中，很快記錄檔就會被垃圾資訊給充滿，從而影響主要的查詢慢日誌記錄的查看

 

三、日誌分析、工欲善其事必先利其器

主要推薦兩種方式

1、mysqldumpslow

[[email protected]_data]#mysqldumpslow  slow-query.log                                 Reading mysql slow query log from slow-query.log                            Count: 2 Time=11.00s (22s) Lock=0.00s (0s) Rows=1.0 (2), root[root]@mysql    select count(N) from t_user;                                                mysqldumpslow -s c -t 10 /database/mysql/slow-query.log                      這會輸出記錄次數最多的10條SQL語句，其中：-s, 是表示按照何種方式排序，c、t、l、r分別是按照記錄次數、時間、查詢時間、返回的記錄數來排序，ac、at、al、ar，表示相應的倒敘；-t, 是top n的意思，即為返回前面多少條的資料；-g, 後邊可以寫一個正則匹配模式，大小寫不敏感的；mysqldumpslow -s r -t 10 /database/mysql/slow-log                                 得到返回記錄集最多的10個查詢。mysqldumpslow -s t -t 10 -g "left join" /database/mysql/slow-log       得到按照時間排序的前10條裡面含有左串連的查詢語句。使用mysqldumpslow命令可以非常明確的得到各種我們需要的查詢語句，對MySQL查詢語句的監控、分析、最佳化是MySQL最佳化非常重要的一步。開啟慢查詢日誌後，由於日誌記錄操作，在一定程度上會佔用CPU資源影響mysql的效能，但是可以階段性開啟來定位效能瓶頸。

 2、pt-query-digest

下載安裝

[[email protected] ~]# https://www.percona.com/get/pt-query-digest[[email protected] ~]# chmod u+x pt-query-digest

 參數解釋

--create-review-table  當使用--review參數把分析結果輸出到表中時，如果沒有表就自動建立。--create-history-table  當使用--history參數把分析結果輸出到表中時，如果沒有表就自動建立。--filter  對輸入的慢查詢按指定的字串進行匹配過濾後再進行分析--limit限制輸出結果百分比或數量，預設值是20,即將最慢的20條語句輸出，如果是50%則按總回應時間佔比從大到小排序，輸出到總和達到50%位置截止。--host  mysql伺服器位址--user  mysql使用者名稱--password  mysql使用者密碼--history 將分析結果儲存到表中，分析結果比較詳細，下次再使用--history時，如果存在相同的語句，且查詢所在的時間區間和曆史表中的不同，則會記錄到資料表中，可以通過查詢同一CHECKSUM來比較某類型查詢的曆史變化。--review 將分析結果儲存到表中，這個分析只是對查詢條件進行參數化，一個類型的查詢一條記錄，比較簡單。當下次使用--review時，如果存在相同的語句分析，就不會記錄到資料表中。--output 分析結果輸出類型，值可以是report(標準分析報告)、slowlog(Mysql slow log)、json、json-anon，一般使用report，以便於閱讀。--since 從什麼時間開始分析，值為字串，可以是指定的某個”yyyy-mm-dd [hh:mm:ss]”格式的時間點，也可以是簡單的一個時間值：s(秒)、h(小時)、m(分鐘)、d(天)，如12h就表示從12小時前開始統計。--until 截止時間，配合—since可以分析一段時間內的慢查詢。

 用法

(1)直接分析慢查詢檔案:pt-query-digest  slow.log > slow_report.log(2)分析最近12小時內的查詢：pt-query-digest  --since=12h  slow.log > slow_report2.log(3)分析指定時間範圍內的查詢：pt-query-digest slow.log --since ‘2014-04-17 09:30:00‘ --until ‘2014-04-17 10:00:00‘> > slow_report3.log(4)分析指含有select語句的慢查詢pt-query-digest--filter ‘$event->{fingerprint} =~ m/^select/i‘ slow.log> slow_report4.log(5) 針對某個使用者的慢查詢pt-query-digest--filter ‘($event->{user} || "") =~ m/^root/i‘ slow.log> slow_report5.log(6) 查詢所有所有的全表掃描或full join的慢查詢pt-query-digest--filter ‘(($event->{Full_scan} || "") eq "yes") ||(($event->{Full_join} || "") eq "yes")‘ slow.log> slow_report6.log(7)把查詢儲存到query_review表pt-query-digest  --user=root –password=abc123 --review  h=localhost,D=test,t=query_review--create-review-table  slow.log(8)把查詢儲存到query_history表pt-query-digest  --user=root –password=abc123 --review  h=localhost,D=test,t=query_ history--create-review-table  slow.log_20140401pt-query-digest  --user=root –password=abc123--review  h=localhost,D=test,t=query_history--create-review-table  slow.log_20140402(9)通過tcpdump抓取mysql的tcp協議資料，然後再分析tcpdump -s 65535 -x -nn -q -tttt -i any -c 1000 port 3306 > mysql.tcp.txtpt-query-digest --type tcpdump mysql.tcp.txt> slow_report9.log(10)分析binlogmysqlbinlog mysql-bin.000093 > mysql-bin000093.sqlpt-query-digest  --type=binlog  mysql-bin000093.sql > slow_report10.log(11)分析general logpt-query-digest  --type=genlog  localhost.log > slow_report11.log官方文檔：http://www.percona.com/doc/percona-toolkit/2.2/pt-query-digest.html

 

mysql中的慢查詢日誌