環境資訊:
系統版本: CentOS release 6.10
配置:虛機、64G記憶體、16C邏輯CPU
版本:5.7.12-log MySQL Community Server (GPL)
pt-query-digest mysql-slow.log --since '2020-11-01 00:01:00' --until '2020-11-09 10:00:00' >slow_report1.log
以上的慢SQL,平均執行時間為123s,看着是很簡單的SQL,基本邏輯是:查詢t_test_info表id大于等于它本身最大的id乘以個随機數取整,同時區域編号為5400的資料,根據id排序後,取第一行資料。t_test_info的資料量為6w+,并不是非常大。
表結構如下:
對應的執行計劃:
UNCACHEABLE SUBQUERY:對于外層的主表,一個子查詢的結果不能被緩存,每次都需要計算(耗時操作)
發現這執行計劃存在問題,idx_ctime這個索引是ctime列的,整個SQL都未出現ctime這一列,難道是優化器選錯索引?考慮ingore index(idx_ctime) 去幹預,發現它就選擇了idx_con_id這個索引,忽略考慮ingore index(idx_ctime) 去幹預,發現它就選擇了idx_con_id索引又會選擇下一個。是以從執行計劃來看,雖然是使用了索引,但filtered過濾的是100%的資料,跟全表掃描沒啥差別。
這裡也考慮說select * 全字段資料,換成select id減少SQL執行階段Sending data的時間,執行時間也是一樣的,沒有差別。
FORMAT=JSON格式的執行計劃,檢視資源消耗情況,根據SQL的邏輯,看資源消耗是正常的(先進行子查詢外部的查詢,得到一個結果集63713行資料,然後這個結果的每一行在跟select子查詢的結果集進行比對)
開啟optimizer_trace,對該sql執行的過程進行跟蹤分析:
同時使用pstask進行記錄堆棧資訊
這裡的19175 是根據performance_schema.threads查詢該SQL對應的THREAD_OS_ID。
通過pt-pmp對trace資訊彙總 pt-pmp /tmp/pstack_1110.log:

/tmp/pstack_1110.log 部分資訊
根據pt-pmp的統計,以上的次數多達237次。這裡感覺是陷入某内部函數循環裡面,需要多次判斷取值才能傳回。要想找到根因,隻能看源碼了,個人能力有限,先記錄下來,有大神感興趣可以研究一下。
到這裡,我考慮将rand函數換成一個常量,檢視執行計劃并執行,發現是不一樣的,執行時間也是毫秒級。
為進一步猜想是随機函數作為子查詢的bug(也可能是UNCACHEABLE SUBQUERY問題,我更傾向這個原因,能力有限,還無法定論,大神可以指正一下),那麼在目前版本5.7.12上可能存在,在别的版本已經修複,于是我在測試環境找了個8.0.20版本的庫,建構了相同表結構,并造了相同數量的資料。
先對比了執行計劃,發現執行計劃是一樣的, 8.0.20版本的執行計劃:
不同的是,在8.0.20的環境上,執行時間大概是0.03秒,差了幾萬倍,差别太大了。
回到5.7.12環境上,我根據SQL實作的邏輯,進行了改寫,避免rand函數作為子查詢,按照子查詢改寫為join的思路如下:
以上SQL在5.7.12環境上毫秒級就可以出結果,但該SQL會産生笛卡爾積,如果資料量很大,性能也會下降。并非合适的解決方案。
于是再按照避免rand函數作為子查詢思路,拆分成兩個SQL,先擷取一個随機數,以傳參的方式,進行查詢,這種在代碼層也相對較好實作。
在8.0以上版本,可以考慮使用with as的方式建構個臨時表的方式進行改寫,5.7不支援該文法。
後記,後續參考了官方資料,更傾向是執行計劃走UNCACHEABLE SUBQUERY這個原因導緻的
https://dev.mysql.com/doc/refman/5.7/en/explain-output.html
https://dev.mysql.com/doc/refman/5.7/en/query-cache-operation.html
同時參考《MySQL:查詢字段數量多少對查詢效率的影響》