者：溫正湖
 
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 是個很關鍵的引數，設定不當會無法正常記錄不走索引的慢查詢，導致慢日誌功能部分失效。所以，使用者首先需儘可能避免出現大量不走索引的 SQL 語句，可以通過 RDS 健康檢查功能進行優化，再次，若出現慢日誌中存在上述提示，應該調大 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 選項開啟。