MySQL的慢日志線上問題及優(yōu)化方案

MySQL 慢日志（slow log）是 MySQL DBA 及其他開發(fā)、運維人員需經(jīng)常關注的一類信息。使用慢日志可找出執(zhí)行時間較長或未走索引等 SQL 語句，為進行系統(tǒng)調(diào)優(yōu)提供依據(jù)。

本文將結合一個線上案例，分析如何正確設置 MySQL 慢日志參數(shù)和使用慢日志功能，并介紹下網(wǎng)易云 RDS 對 MySQL 慢日志功能的增強。

MySQL 參數(shù)組功能

網(wǎng)易云 RDS 實例提供了參數(shù)組管理功能，可通過參數(shù)管理界面查看絕大部分常用的 MySQL 系統(tǒng)參數(shù)，用戶可了解當前運行值和建議值：

用戶還可通過參數(shù)管理頁面對所列的參數(shù)進行修改，點擊 “修改參數(shù)” 按鈕進行在線設置，點擊 “保存修改” 即可一鍵完成 MySQL 主從節(jié)點的參數(shù)修改： 

查看參數(shù)管理界面不難發(fā)現(xiàn)，與慢查詢相關的參數(shù)比較多，那么，這些參數(shù)都是如何起作用的呢，相互關系又是如何，滿足什么條件的 SQL 語句才會記錄到慢日志中？只有了解這些才能更好地利用慢日志進行系統(tǒng)調(diào)優(yōu)和問題定位。

下面，我們以這個線上案例為依托，介紹下該如何正確配置慢日志參數(shù)：

有用戶報告，他們使用的多個 RDS 5.7 版本實例慢日志異常，明明執(zhí)行了一分多鐘的 SQL 語句，卻沒有記錄到慢日志中。還提供了用于復現(xiàn)的 SQL 語句。

慢日志參數(shù)正確配置姿勢

首先，我們需要確認該實例是否開啟了慢日志功能，默認情況下，MySQL 慢日志功能是關閉的。慢日志開關參數(shù)為 slow_query_log，可在 mysqld 啟動命令行或配置文件中顯式指定，若指定 slow_query_log=1 或不指定值，則表示開啟慢日志，賦值為 0 表示關閉。用戶可以在運行時動態(tài)開啟和關閉。

網(wǎng)易云 RDS 實例默認開啟慢日志功能，我們確認了該用戶未關閉實例的慢日志開關。

接下來，需確認慢日志記錄位置，MySQL 使用 log_output 參數(shù)指定以文件（FILE）還是以表 (TABLE) 的方式來保存慢日志。需要強調(diào)的是，僅指定 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 數(shù)據(jù)目錄。

網(wǎng)易云 RDS 實例不允許用戶修改日志文件路徑，但可以配置 log_output 參數(shù)，通過查詢，確認該實例以文件方式記錄慢日志，查看日志文件確認沒有用戶所述的 SQL 語句。

由于用戶提供了復現(xiàn)語句，我們執(zhí)行了其 SQL 語句，確實 1 分多鐘才返回，通過 explain 命令發(fā)現(xiàn)其未走索引，掃描了較多的記錄數(shù)，再次查看慢日志仍沒有記錄該 SQL 語句。

MySQL 會記錄滿足執(zhí)行時間超過 long_query_time 秒，掃描記錄數(shù)超過 min_examined_row_limit 行的 SQL 語句。

long_query_time 參數(shù)最小值和默認值分別為 1 和 10s，該參數(shù)可以精確到微秒（ms）。如果選擇將慢日志記錄到文件中，那么所記錄的時間精確到微秒，如果記錄到慢日志表（mysql.slow_log）中，那么僅精確到秒，微秒部分被忽略。

網(wǎng)易云 RDS 實例允許用戶設置這兩個參數(shù)值，那么是不是用戶調(diào)整了上述兩個閾值，導致無法滿足記錄條件呢，進一步查詢發(fā)現(xiàn)也不是問題原因所在。

我們注意到 MySQL 還有個名為 log_queries_not_using_indexes 的參數(shù)用于控制是否記錄未走索引的 SQL 查詢，代碼如下：

重點關注箭頭所指內(nèi)容，如果查詢未走索引或者索引無效，且相關參數(shù)開啟，那么 warn_no_index 設置為 true，若同時滿足掃描記錄數(shù)超過閾值，也會像慢查詢一樣被記錄，那么是不是該參數(shù)未開呢？結果仍是否定的。

問題原因之所在

由于數(shù)據(jù)庫實例中可能有較多不走索引的 SQL 語句，若開啟 log_queries_not_using_indexes，則存在日志文件或表容量增長過快的風險，此時可通過設置 log_throttle_queries_not_using_indexes 來限制每分鐘寫入慢日志中的不走索引的 SQL 語句個數(shù)，該參數(shù)默認為 0，表示不開啟，也就是說不對寫入 SQL 語句條數(shù)進行控制。

啟用后，系統(tǒng)會在第一條不走索引的查詢執(zhí)行后開啟一個 60s 的窗口，在該窗口內(nèi)，僅記錄最多 log_throttle_queries_not_using_indexes 條 SQL 語句。超出部分將被抑制，在時間窗結束時，會打印該窗口內(nèi)被抑制的慢查詢條數(shù)以及這些慢查詢一共花費的時間。下一個統(tǒng)計時間窗并不是馬上創(chuàng)建，而是在下一條不走索引的查詢執(zhí)行后開啟。

對應到該線上問題，log_throttle_queries_not_using_indexes 被設置為 10，在日志文件中看到周期性打印了如下內(nèi)容：

確實符合上面描述的現(xiàn)象，用戶的慢日志應該是被抑制了，匯總到了 359 里面去。我們嘗試將 log_throttle_queries_not_using_indexes 設置為 0，再執(zhí)行對應的 SQL 語句，果然在日志文件中記錄了相應的 SQL 語句。

這個線上問題似乎已經(jīng)定位到了，就是系統(tǒng)產(chǎn)生的不走索引的慢日志太多，而設置的 log_throttle_queries_not_using_indexes 太小，導致無法正常記錄用戶未走索引的慢日志。但還有一個疑惑點沒有解決，那就是 log_throttle_queries_not_using_indexes 為 0 時，每分鐘并沒有打印超過10條慢日志，更沒有 throttle 提示的 359 條這么多，那么設置為 10 的時候用戶提供的那條 SQL 語句應該被記錄到慢日志中才對啊，為何沒有記錄，原因何在？其實，仔細看下 MySQL 記錄不走索引的日志的代碼邏輯可以找到答案：

上圖是記錄慢日志的主邏輯，是否記錄日志由函數(shù) log_slow_applicable 控制，該函數(shù)先前已分析了一部分，我們進一步看該函數(shù)的其他相關內(nèi)容，見下圖紅框：

Suppress_logging 是個決定性的變量，只有它為 false，該 SQL 語句才可能被記錄。其結果就跟 log_throttle_queries_not_using_indexes 相關，我們進一步看下 log_throttle_qni.log 相關實現(xiàn)，如下圖：

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

通過對上述 2 個截圖內(nèi)容進行分析，可以解答之前的疑惑點：

log_throttle_queries_not_using_indexes 統(tǒng)計的是所有不走索引的語句，其中有些語句因為不滿足掃描記錄數(shù)的約束而不會記錄到慢日志中，這就是為什么該值為 10 的時候，慢日志文件中并沒有 10 條記錄。因為這 10 條中有 8 條 SQL 語句由于掃描記錄數(shù)太少并沒有被記錄。

這也解惑了上圖中 359 這個數(shù)字，它是這個時間窗內(nèi)不走索引的 SQL 語句總數(shù)。所以，log_throttle_queries_not_using_indexes 是個很關鍵的參數(shù)，設置不當會無法正常記錄不走索引的慢查詢，導致慢日志功能部分失效。所以，用戶首先需盡可能避免出現(xiàn)大量不走索引的 SQL 語句，可以通過 RDS 健康檢查功能進行優(yōu)化，再次，若出現(xiàn)慢日志中存在上述提示，應該調(diào)大 log_throttle_queries_not_using_indexes 的值，以便以進一步分析問題。

InnoSQL 慢日志功能增強

還有部分 RDS 實例用戶問我們，為什么我的 SQL 語句執(zhí)行時間沒有超過所設置的 long_query_time，而且走了索引，但還是被記錄到慢日志中，是不是出 Bug 了？其實這不是 Bug，而是因為網(wǎng)易云 RDS 使用的 InnoSQL（網(wǎng)易維護的 MySQL 開源分支）版本對慢日志做了優(yōu)化，除了考察 SQL 語句的執(zhí)行時間外，還關注該查詢所需的磁盤頁面（Disk Page）數(shù)，因為所需的頁面數(shù)目過多，也可能會對系統(tǒng)負載造成較大影響。為了能夠量化統(tǒng)計，我們收集了 SQL 查詢所需讀取的總頁面數(shù)和這些頁面中實際進行 IO 的次數(shù)，分別記錄為 logical_reads和physical_reads，前者包括命中 InnoDB Buffer Pool 和未命中需要進行 IO 的頁面請求。

通過引入 slow_query_type 和 long_query_io 兩個參數(shù)為用戶提供該功能。前者可設置為 0/1/2/3?！?” 表示啟用基于執(zhí)行時間來記錄慢日志，“2” 表示基于搜索總頁面數(shù)來記錄慢日志，“3” 是 “1” 和 “2” 的合集。所以在 InnoSQL 中，SQL 查詢只需滿足執(zhí)行時間夠長或所需總頁面數(shù)夠多即可記錄到慢日志中。代碼實現(xiàn)片段如下：

頁面數(shù)閾值通過 long_query_io 參數(shù)來衡量，用戶可動態(tài)設置，如果總頁面數(shù) m_logical_reads 超過了該值，即使執(zhí)行時間未超標，也會被記錄。相應的，RDS 實例慢日志表結構和慢日志文件輸出內(nèi)容也增加了新的字段。

上圖即為 InnoSQL 版的 slow_log 表結構，其中，logical_reads 和 physical_reads 為 InnoSQL 增加字段。同樣的，慢日志文件的輸出內(nèi)容也增加了兩個字段，如下所示：

除了以上詳細描述的內(nèi)容外，MySQL 慢日志模塊還有如下幾個特性值得關注：

○ 進行慢日志統(tǒng)計及慢日志中所記錄的時間并不包括該 SQL 語句開始執(zhí)行前獲取鎖所需等待的時間；

○ MySQL 在 SQL 語句執(zhí)行完且所持有的鎖均已釋放后才將其寫入慢日志中，所以慢日志中的 SQL 語句記錄順序并不能準確反映這些 SQL 語句的實際執(zhí)行順序；

○ 每條慢日志都包含一個時間戳，若寫入文件中，log_timestamps 參數(shù)用于將慢日志時間戳轉化為指定時區(qū)的時間。但該參數(shù)對于 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 選項開啟。

您可能感興趣的文章:

聲明：本網(wǎng)頁內(nèi)容旨在傳播知識，若有侵權等問題請及時與本網(wǎng)聯(lián)系，我們將在第一時間刪除處理。TEL:177 7030 7066 E-MAIL:11247931@qq.com