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

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

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

MySQL 參數(shù)組功能

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

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

InnoSQL 慢日志功能增強(qiáng)

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

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

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

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

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

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

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

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

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

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