MySQL中慢日志線(xiàn)上問(wèn)題及優(yōu)化的示例分析

這篇文章將為大家詳細講解有關(guān)中慢日志線(xiàn)上問(wèn)題及優(yōu)化的示例分析，小編覺(jué)得挺實(shí)用的，因此分享給大家做個(gè)參考，希望大家閱讀完這篇文章后可以有所收獲。

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

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

MySQL 參數組功能

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

用戶(hù)還可通過(guò)參數管理頁(yè)面對所列的參數進(jìn)行修改，點(diǎn)擊 “修改參數” 按鈕進(jìn)行在線(xiàn)設置，點(diǎn)擊 “保存修改” 即可一鍵完成 MySQL 主從節點(diǎn)的參數修改： 

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

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

有用戶(hù)報告，他們使用的多個(gè) RDS 5.7 版本實(shí)例慢日志異常，明明執行了一分多鐘的 SQL 語(yǔ)句，卻沒(méi)有記錄到慢日志中。還提供了用于復現的 SQL 語(yǔ)句。

慢日志參數正確配置姿勢

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

網(wǎng)易云 RDS 實(shí)例默認開(kāi)啟慢日志功能，我們確認了該用戶(hù)未關(guān)閉實(shí)例的慢日志開(kāi)關(guān)。

接下來(lái)，需確認慢日志記錄位置，MySQL 使用 log_output 參數指定以文件（FILE）還是以表 (TABLE) 的方式來(lái)保存慢日志。需要強調的是，僅指定 log_output 而將 slow_query_log 置為 0 并不會(huì )記錄慢日志，也就是說(shuō) slow_query_log 才是慢日志的開(kāi)關(guān)。若使用文件形式記錄慢日志，則可通過(guò) slow_query_log_file 指定文件名，如果用戶(hù)沒(méi)有顯式指定 slow_query_log_file，則 MySQL 將其初始化為 host_name-slow.log，host_name 即為運行 mysqld 的主機名，慢日志文件默認位于 MySQL 數據目錄。

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

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

MySQL 會(huì )記錄滿(mǎn)足執行時(shí)間超過(guò) long_query_time 秒，掃描記錄數超過(guò) min_examined_row_limit 行的 SQL 語(yǔ)句。

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

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

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

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

問(wèn)題原因之所在

由于數據庫實(shí)例中可能有較多不走索引的 SQL 語(yǔ)句，若開(kāi)啟 log_queries_not_using_indexes，則存在日志文件或表容量增長(cháng)過(guò)快的風(fēng)險，此時(shí)可通過(guò)設置 log_throttle_queries_not_using_indexes 來(lái)限制每分鐘寫(xiě)入慢日志中的不走索引的 SQL 語(yǔ)句個(gè)數，該參數默認為 0，表示不開(kāi)啟，也就是說(shuō)不對寫(xiě)入 SQL 語(yǔ)句條數進(jìn)行控制。

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

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

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

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

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

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

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

通過(guò)對上述 2 個(gè)截圖內容進(jìn)行分析，可以解答之前的疑惑點(diǎn)：

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

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

In 慢日志功能增強

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

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

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

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

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

○ 進(jìn)行慢日志統計及慢日志中所記錄的時(shí)間并不包括該 SQL 語(yǔ)句開(kāi)始執行前獲取鎖所需等待的時(shí)間；

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

○ 每條慢日志都包含一個(gè)時(shí)間戳，若寫(xiě)入文件中，log_timestamps 參數用于將慢日志時(shí)間戳轉化為指定時(shí)區的時(shí)間。但該參數對于 mysql.slow_log 表中的慢日志不起作用；

○ 可通過(guò)設置 log_slow_slave_statements 來(lái)開(kāi)啟 MySQL 從庫的慢日志功能；

○ ALTER TABLE, ANALYZE TABLE, CHECK TABLE, CREATE INDEX, DROP INDEX, OPTIMIZE TABLE, and REPAIR TABLE 等表管理操作也能夠被記錄到慢日志中，可通過(guò) log_slow_admin_statements 選項開(kāi)啟。