MySQL慢日誌功能分析及優化加強

 

 

MySQL慢日誌（slow log）是MySQL DBA及其餘開發、運維人員需常常關注的一類信息。使用慢日誌可找出執行時間較長或未走索引等SQL語句，爲進行系統調優提供依據。本文結合線上案例分析如何正確設置MySQL慢日誌參數和使用慢日誌功能，並介紹網易雲RDS對MySQL慢日誌功能加強。

 

MySQL參數組功能

網易雲RDS實例提供了參數組管理功能，可經過參數管理界面查看絕大部分經常使用的MySQL系統參數，用戶能夠了解當前運行值和建議值，以下所示：

 

用戶還可經過參數管理頁面對所列的參數進行修改，點擊「修改參數」按鈕在線設置，點擊「保存修改」便可一鍵完成MySQL主從節點的參數修改，以下圖：

 

查看參數管理界面不難發現，與慢查詢相關的參數較多，這些參數是如何起做用的呢，相互關係又是如何，知足什麼條件的SQL語句纔會記錄到慢日誌中？只有瞭解了這些才能更好地利用慢日誌進行系統調優和問題定位。咱們以一個線上案例爲依託來介紹如何正確配置慢日誌參數：用戶報告他們使用的多個RDS 5.7版本實例慢日誌異常，明明執行了一分多鐘的SQL語句，卻沒有記錄到慢日誌中。還提供了用於復現的SQL語句。

 

慢日誌參數正確配置姿式

首先，咱們需確認該實例是否開啓了慢日誌功能，默認狀況下，MySQL慢日誌功能是關閉的。慢日誌開關參數爲slow_query_log，可在mysqld啓動命令行或配置文件中顯式指定，若指定slow_query_log=1或不指定值，則表示開啓慢日誌，賦值爲0表示關閉。用戶能夠在運行時動態開啓和關閉。網易雲RDS實例默認開啓慢日誌功能，咱們確認了該用戶未關閉實例的慢日誌開關。

 

接下來，需確認慢日誌記錄位置，MySQL使用log_output參數指定以文件（FILE）仍是表(TABLE)的方式來保存慢日誌，須要強調的是，僅指定log_output而將slow_query_log置爲0並不會記錄慢日誌，也就是說slow_query_log纔是慢日誌的開關。若使用文件形式記錄慢日誌，則可經過slow_query_log_file指定文件名，若是用戶沒有顯式指定slow_query_log_file，則MySQL將其初始化爲host_name-slow.log，host_name即爲運行mysqld的主機名，慢日誌文件默認位於MySQL數據目錄。網易雲RDS實例不容許用戶修改日誌文件路徑，但能夠配置log_output參數，經過查詢，確認該實例以文件方式記錄慢日誌，查看日誌文件確認沒有用戶所述的SQL語句。

 

因爲用戶提供了復現語句，咱們執行了其SQL語句，確實1分多鐘才返回，經過explain命令發現其未走索引，掃描了較多的記錄數，再次查看慢日誌仍沒有記錄該SQL語句。MySQL會記錄知足執行時間超過long_query_time秒，掃描記錄數超過min_examined_row_limit行的SQL語句。long_query_time參數最小值和默認值分別爲1和10s，該參數能夠精確到微秒（ms）。若是選擇將慢日誌記錄到文件中，那麼所記錄的時間精確到微秒，若是記錄到慢日誌表（mysql.slow_log）中，那麼僅精確到秒，微秒部分被忽略。網易雲RDS實例容許用戶設置這兩個參數值，那麼是否是用戶調整了上述兩個閾值，致使沒法知足記錄條件呢，進一步查詢發現也不是問題緣由所在。

 

咱們注意到MySQL還有個名爲log_queries_not_using_indexes的參數用於控制是否記錄未走索引的SQL查詢，代碼以下：

 

重點關注箭頭所指內容，若是查詢未走索引或者索引無效，且相關參數開啓，那麼warn_no_index設置爲true，若同時知足掃描記錄數超過閾值，也會像慢查詢同樣被記錄，那麼是否是該參數未開呢？結果還是否認的。

 

問題緣由之所在

因爲數據庫實例中可能有較多不走索引的SQL語句，若開啓log_queries_not_using_indexes，則存在日誌文件或表容量增加過快的風險，此時可經過設置log_throttle_queries_not_using_indexes來限制每分鐘寫入慢日誌中的不走索引的SQL語句個數，該參數默認爲0，表示不開啓，也就是說不對寫入SQL語句條數進行控制。啓用後，系統會在第一條不走索引的查詢執行後開啓一個60s的窗口，在該窗口內，僅記錄最多log_throttle_queries_not_using_indexes條SQL語句。超出部分將被抑制，在時間窗結束時，會打印該窗口內被抑制的慢查詢條數以及這些慢查詢一共花費的時間。下一個統計時間窗並非立刻建立，而是在下一條不走索引的查詢執行後開啓。對應到該線上問題，log_throttle_queries_not_using_indexes被設置爲10，在日誌文件中看到週期性打印了以下內容：

 

確實符合上面描述的現象，用戶的慢日誌應該是被抑制了，彙總到了359裏面去。咱們嘗試將log_throttle_queries_not_using_indexes設置爲0，再執行對應的SQL語句，果真在日誌文件中記錄了相應的SQL語句。這個線上問題彷佛已經定位到了，就是系統產生的不走索引的慢日誌太多，而設置的log_throttle_queries_not_using_indexes過小，致使沒法正常記錄用戶未走索引的慢日誌。但還有一個疑惑點沒有解決，那就是log_throttle_queries_not_using_indexes爲0時，每分鐘並無打印超過10條慢日誌，更沒有throttle提示的359條這麼多，那麼設置爲10的時候用戶提供的那條SQL語句應該被記錄到慢日誌中才對啊，爲什麼沒有記錄，緣由何在？其實，仔細看下MySQL記錄不走索引的日誌的代碼邏輯能夠找到答案：

 

上圖是記錄慢日誌的主邏輯，是否記錄日誌由函數log_slow_applicable控制，該函數先前已分析了一部分，咱們進一步看該函數的其餘相關內容，見下圖紅框：

 

suppress_logging是個決定性的變量，只有它爲false，該SQL語句纔可能被記錄。其結果就跟log_throttle_queries_not_using_indexes相關，咱們進一步看下log_throttle_qni.log相關實現，以下圖：

 

eligible即爲warn_no_index，inc_log_count()函數在1分鐘內不走索引的語句總數超過log_throttle_queries_not_using_indexes時返回值爲true，只有warn_no_index和inc_log_count()返回值都爲true，suppress_current才爲true，而suppress_current即爲suppress_logging。

 

經過對上述2個截圖內容進行分析，能夠解答以前的疑惑點：log_throttle_queries_not_using_indexes統計的是全部不走索引的語句，其中有些語句由於不知足掃描記錄數的約束而不會記錄到慢日誌中，這就是爲何該值爲10的時候，慢日誌文件中並無10條記錄。由於這10條中有8條SQL語句因爲掃描記錄數太少並無被記錄。

 

這也解惑了上圖中359這個數字，它這個時間窗內不走索引的SQL語句總數。因此，log_throttle_queries_not_using_indexes是個很關鍵的參數，設置不當會沒法正常記錄不走索引的慢查詢，致使慢日誌功能部分失效。

 

InnoSQL慢日誌功能加強

還有部分RDS實例用戶問咱們，爲何個人SQL語句執行時間沒有超過所設置的long_query_time，並且走了索引，但仍是被記錄到慢日誌中，是否是出Bug了？其實這不是Bug，而是由於網易雲RDS使用的InnoSQL（網易維護的MySQL開源分支）版本對慢日誌作了優化，除了考察SQL語句的執行時間外，還關注該查詢所需的磁盤頁面（Disk Page）數，由於所需的頁面數目過多，也可能會對系統負載形成較大影響。爲了可以量化統計，咱們收集了SQL查詢所需讀取的總頁面數和這些頁面中實際進行IO的次數，分別記錄爲logical_reads和physical_reads，前者包括命中InnoDB Buffer Pool和未命中須要進行IO的頁面請求。經過引入slow_query_type和long_query_io兩個參數爲用戶提供該功能。前者可設置爲0/1/2/3。1表示啓用基於執行時間來記錄慢日誌，2表示基於搜索總頁面數來記錄慢日誌，3是1和2的合集。因此在InnoSQL中，SQL查詢只需知足執行時間夠長或所需總頁面數夠多便可記錄到慢日誌中。代碼實現片斷以下：

 

頁面數閾值經過long_query_io參數來衡量，用戶可動態設置，若是總頁面數m_logical_reads超過了該值，即便執行時間未超標，也會被記錄。相應的，RDS實例慢日誌表結構和慢日誌文件輸出內容也增長了新的字段。

 

上圖即爲InnoSQL版的slow_log表結構，其中，logical_reads和physical_reads爲InnoSQL增長字段。一樣的，慢日誌文件的輸出內容也增長了兩個字段，以下所示：

 

 

補充

除了以上詳細描述的內容外，MySQL慢日誌模塊還有以下幾個特性值得關注：

一、 進行慢日誌統計及慢日誌中所記錄的時間並不包括該SQL語句開始執行前獲取鎖所需等待的時間；

二、 MySQL在SQL語句執行完且所持有的鎖均已釋放後纔將其寫入慢日誌中，因此慢日誌中的SQL語句記錄順序並不能準確反映這些SQL語句的實際執行順序；

三、 每條慢日誌都包含一個時間戳，若寫入文件中，log_timestamps 參數用於將慢日誌時間戳轉化爲指定時區的時間。但該參數對於mysql.slow_log表中的慢日誌不起做用；

四、 可經過設置log_slow_slave_statements來開啓MySQL從庫的慢日誌功能；ALTER TABLE, ANALYZE TABLE, CHECK TABLE, CREATE INDEX, DROP INDEX, OPTIMIZE TABLE, and REPAIR TABLE等表管理操做也可以被記錄到慢日誌中，可經過log_slow_admin_statements選項開啓。