今天帶著同事一起分析了一個(gè)常見的MySQL慢日志報(bào)警，從分析的過程希望帶給大家一些啟示和反思。
報(bào)警信息類似：
PROBLEM P5 Endpoint:xxxx Metric:mysql.slow_queries Tags:idc=IDC1,port=4306,service=test diff(#1): 335>300 Note:[[warning]SQL語句執(zhí)行效率慢] Max:3, .....
看到這條報(bào)警信息，可以明確一個(gè)任務(wù)，此時(shí)數(shù)據(jù)庫中存在大量的慢日志，條數(shù)為335，超出了閾值設(shè)置的300
當(dāng)然打開日志來分析的時(shí)候，會(huì)發(fā)現(xiàn)比想象的要復(fù)雜一些，因?yàn)槁罩疚募赡苡袔装僬咨踔粮螅治稣麄€(gè)文件顯然是不可行的，所以我們需要過濾條件，把慢日志限定在一個(gè)較小的范圍內(nèi)來分析。
這里我們可以使用mysqldumpslow來做一個(gè)簡單的分析，推薦更好的一款工具是pt-query-digest。
如下是慢日志的頭部：
可以明顯看到在1分鐘的時(shí)間里SQL執(zhí)行的整體情況，1分鐘內(nèi)有400多的SQL執(zhí)行。但是仔細(xì)看指標(biāo)“Exec time”會(huì)有一個(gè)明顯的問題，那就是這個(gè)時(shí)長指標(biāo)其實(shí)很低，總數(shù)才881ms,顯然是不符合我們理解中的慢日志閾值的。
所以我們可以得到一個(gè)基本的印象，這個(gè)指標(biāo)是和一個(gè)慢日志相關(guān)的參數(shù)：log_queries_not_using_indexes 相關(guān)，這個(gè)參數(shù)意思是如果SQL沒有使用索引則會(huì)計(jì)入慢日志。
為了做進(jìn)一步驗(yàn)證，我們往下看profile.
看profile信息的時(shí)候我們要按照重點(diǎn)來把握，即那些明顯的性能SQL占比通常很高。如果檢查前兩個(gè)表會(huì)發(fā)現(xiàn)，根據(jù)現(xiàn)在的條件，這兩條SQL的where條件部分是沒有相關(guān)的索引的。
第一個(gè)SQL有點(diǎn)意思。
UPDATE SELECT dic_push_dao_assistant tem_selectAssDAO。。。
這是什么意思，我們可以詳細(xì)的Query ID的解析來得到。對于update語句會(huì)轉(zhuǎn)義成等價(jià)的select語句
update `dic_push_dao_assistant` set `state` = 1 where `id` in ( select `id` from `tem_selectAssDAO` )G # Converted for EXPLAIN # EXPLAIN /*!50100 PARTITIONS*/ select `state` = 1 from `dic_push_dao_assistant` where `id` in ( select `id` from `tem_selectAssDAO` )G
當(dāng)然這個(gè)語句本身是有些粗糙，完全可以進(jìn)一步優(yōu)化。
我們再分析一下第2條SQL，問題是很明顯的，即相關(guān)的SQL缺少索引而走了全表掃描。
但是建議還是做下補(bǔ)充，可能這些信息是在慢日志之外，就是建表語句：
從這里我們可以清晰的看出，這個(gè)表只有2190條記錄，目前的掃描基本就是少數(shù)幾個(gè)頁就搞定了，但是自增列已經(jīng)到了1000萬左右，可以看出這個(gè)表的變更是極為頻繁的，那么是否存在碎片呢。驗(yàn)證的方式我們可以直接查看對應(yīng)的物理文件，可以看到2000條記錄大概占用了20M左右的空間，這能不能說明有碎片呢。
# ll *cccd*
-rw-r----- 1 mysql mysql 70494 Nov 20 09:37 dic_fsm_cccd_info.frm
-rw-r----- 1 mysql mysql 26214400 Feb 27 17:50 dic_fsm_cccd_info.ibd
驗(yàn)證方式其實(shí)也不難，我們在另外一個(gè)庫中模擬創(chuàng)建一個(gè)表補(bǔ)充數(shù)據(jù)即可，大概是10M左右。
# ll *cccd*
-rw-r----- 1 mysql mysql 70494 Feb 27 23:47 dic_fsm_cccd_info.frm
-rw-r----- 1 mysql mysql 10485760 Feb 27 23:48 dic_fsm_cccd_info.ibd
所以目前來看這個(gè)表是存在碎片的，說明大量的數(shù)據(jù)是寫入了庫中，然后很可能做了delete操作，導(dǎo)致數(shù)據(jù)總量變化不大，按照這種方式是存在隱患的。
從自增列來看，很可能數(shù)據(jù)會(huì)出現(xiàn)較大的增長，就會(huì)導(dǎo)致這個(gè)操作馬上成為瓶頸，這條SQL一分鐘執(zhí)行了144次，算是比較頻繁了,所以從目前的情況來看，這個(gè)表很可能成為性能的瓶頸，所以需要建議業(yè)務(wù)評估添加相關(guān)的索引。而之前根據(jù)業(yè)務(wù)的反饋，說這個(gè)庫經(jīng)常會(huì)有一些操作的延遲，也不難理解了。
我們在這里處理應(yīng)該得出什么結(jié)論呢？
1）關(guān)閉參數(shù)log_queries_not_using_indexes
2）對相關(guān)的表進(jìn)行分析，根據(jù)條件和頻率創(chuàng)建相應(yīng)的索引
其實(shí)到了這里，我們的分析還是不夠深入，我們可以發(fā)掘出更多的信息，那就是可以提供給業(yè)務(wù)方一個(gè)更全面的信息列表，比如那些表中的索引是冗余索引，那些表走了全表掃描需要考慮添加索引。
這里需要正確引用sys schema,比如：
通過如上的信息可以發(fā)現(xiàn)我們需要重點(diǎn)考慮前面的幾個(gè)表，走了全表掃描，產(chǎn)生了較大的延遲。
而稍后的解決方法，其實(shí)是通過對于業(yè)務(wù)的反饋優(yōu)化，在業(yè)務(wù)添加了相關(guān)索引之后，還是建議打開參數(shù)：log_queries_not_using_indexes ，這對于一些業(yè)務(wù)場景的監(jiān)控其實(shí)也是有效的。
如此一來，我們對慢日志的分析也告一段落，如果對于每條報(bào)警信息我們都認(rèn)真對待，其實(shí)相應(yīng)技術(shù)能力的提升也會(huì)很快。
其實(shí)行業(yè)里有一個(gè)常見的“偽需求“，就是開發(fā)同學(xué)經(jīng)常需要關(guān)注慢日志，從工作的角色和分工來看，他們得到慢日志之后的分析和處理常常和問題的本質(zhì)相左，換句話說，他們得到慢日志，是希望通過分析日志來發(fā)現(xiàn)一些明顯的性能問題，通過這種信息檢索的方式，來快速定位問題，但是實(shí)際上得到日志之后的分析結(jié)果是不可控的，可能10分鐘，可能分析不出來。
而這個(gè)工作其實(shí)是應(yīng)該作為運(yùn)維的前置工作來完成的，既然開發(fā)對于慢日志的處理不專業(yè)，勢必需要DBA來提供專業(yè)的建議，而如果我們能夠通過一種透明自助的方式來提供分析和有效建議，對于開發(fā)同學(xué)來說，其實(shí)他們需要的不是慢日志，而是你的數(shù)據(jù)服務(wù)能力。
