BA應該對InnoDB: Semaphore wait has lasted > 600 seconds. We intentionally crash the server because it appears to be hung. 一點點陌生，MySQL 線程srv_error_monitor_thread發現存在阻塞超過600s的latch鎖定時，如果連續10次偵測該鎖仍沒有釋放，就會觸發panic避免服務持續hang下去。
發生了什麼
版本號：MySQL 5.5.40
日誌中持續輸出執行緒等待數據字典鎖，位置是dict0dict.c line 305，等待時間超過了900s。
持有鎖的執行緒是 139998697924352 ，其十六進位是7f53fca8a700。
--Thread 139998393616128 has waited at dict0dict.c line 305 for 934.00 seconds the semaphore:X-lock on RW-latch at 0x105a1b8 created in file dict0dict.c line 748a writer (thread id 139998697924352) has reserved it in mode exclusivenumber of readers 0, waiters flag 1, lock_word: 0Last time read locked in file dict0dict.c line 302Last time write locked in file/pb2/build/pb2/build/sb sql-5.5 .40/mysql-5.5.40/storage/innobase/dict/dict0dict.c line 305
##
上鎖線程139998697924352 的事務資訊，查詢資料字典表上鎖線程139998697924352 的交易資訊，查詢資料字典表的操作。
---TRANSACTION 0, not started updating table statistics：MySQL thread id 14075, OS thread handle 0x7f53fca8a700, query id 110414021 21.14. TH DATA_FREE)/1024/1024 /1024) AS MY_DB_TOTAL_SIZE FROM information_schema.TABLES
檢查下持鎖執行緒139998697924352 是否有其他鎖定等待。
發現執行緒 139998697924352 ，self-lock 在 btr0sea.c line 1134，此鎖定結構和 AHI 相關。
--Thread 139998697924352 has waited at btr0sea.c line 1134 for 934.00 seconds the semaphore:X-lock (wait_ex) on RW-latch at 0x1eb06448 created in file btr0sea.c line 178a writer (thread id 139998697924352) has reserved it in mode wait exclusivenumber of readers 1, waiters flag 1, lock_word: ffffffffffffffffLast time read locked in file 13157587-1410170252.03/rpm/BUILD /mysql-5.5.40/mysql-5.5.40/storage/innobase/btr/btr0sea.c line 1134##接下來看下兩個鎖定結構分別在哪個函數內：
dict0dict.c line 305在dict_table_stats_lock函數內
btr0sea.c line 1134在btr_search_drop_page_hash_index函數內
##什麼情況會呼叫這些函數？
啟用 innodb_table_monitor，輸出日誌時呼叫 dict_table_stats_lock 上 X 鎖定，本案例未開啟。
啟用 innodb_stats_on_metadata 時，查詢資料字典表會觸發統計資料的更新操作，會呼叫 dict_table_stats_lock 上 X 鎖定。這與持鎖線程的事務資訊相符。
Adaptive hash index(AHI) 是 InnoDB 用來加速索引頁尋找的 hash 表結構。當頁面造訪次數滿足一定條件後，這個頁面的位址將存入一個 hash 表中，減少 B 樹查詢的開銷。
MySQL 5.5 版本 AHI 是由全域鎖定 btr_search_latch 維護 hash 表修改的一致性。
InnoDB buffer pool 狀態顯示 free buffer 基本上保持0空閒。 InnoDB buffer pool 驅逐資料頁時，會呼叫 btr_search_drop_page_hash_index 函數，從 AHI 清理該資料頁。
-----------------------------BUFFER POOL AND MEMORY-------- ---------------------Total memory allocated 17582522368; in
additional pool allocated 0Dictionary memory allocated 4289681
Buffer pool size 1048576
Free buffers 0
#Free buffers 0
#Free buffers page
##Old database pages 384193
Modified db pages 0
#
#小結
AHI 的全域鎖定btr_search_latch 常常會是競爭熱點影響效能，5.7版本後有所改善與InnoDB buffer 一樣做了多實例拆分。本案例在開啟Innodb_stats_on_metadata 參數，查詢元資料資訊時觸發統計資訊更新，上鎖資料字典，阻塞了大量業務操作，又由於buffer pool 空間不足，導致表格驅逐舊頁觸發AHI 的btr_search_latch 鎖定競爭，最終導致信號量超時crash。
>> 彩蛋 <<
在動輒幾兆的日誌中分析Semaphore crash，尋找鎖定、執行緒、事務之間的關係，相當令人抓狂的。借助 sed、awk、grep 三大法寶，雖有效率提升，但仍不夠高效。
為了偷懶寫了一個小程序，幫助DBA快速梳理出這些關係。
它的用法是這樣的：
hongbin@MBP ~> mysqldba doctor -f /Users/hongbin/workbench/mysqld_safe.log
#目標版本，查程式碼時找對應版本：
MySQL Server Version: '5.7.16-log'
出現在日誌中出現的semaphore crash 次數和mysql 啟動次數，如果啟動次數大於crash 次數說明可能是正常啟動或其他crash 造成：
********** MySQL service start count ******* ***
MySQL Semaphore crash -> 3 times ["2018-08-13 23:12:18" "2018-08-14 12:13:43" "2018 -08-16 13:42:36"]
MySQL Service start -> 3 times ["2018-08-13 23:12:59" "2018-08-14 12:15:20" "2018-08-16 13:46:37"]
執行緒主要在等待哪些RW-latch，內容包括：鎖定位置、出現次數、執行緒id (出現次數)，重點關注出現次數較多的：
********** Which thread waited lock **********row0purge.cc:861 - > 58 140477266503424:(57) 140617703745280:(1)gi.cc:14791 -> 1 140477035656960:1 1 140477035656960:11 2765568:(1)ha_innodb.cc:14791 -> 620 140617389913856:(58) 140202719565568:(58) 140202716903168:(57) 140477029533440:(568:(57) 140477029533440:(56) 140617407250506:506 2) 140477035124480:(29) 140477108467456:(29) 140477025539840:(26) 140477031130880:(25) 140477027669760:(22) 140617634944768:(21) 140617634146048:(21) 1404770199948800:(21) 14047770262800:00 8) 140477018883840:(16) 140477038585600:(15) 140477028734720:(10) 140477022877440:(9) 140477034325760:(1) 140477031663360:(1)srv0srv.cc:1968 -> 208 140477276993280:(185) 140617714235136:(23)ha_innodb.cc:5510 -> 601 140617398167296:(57) 140617409615616:(55) 140617392043776: (53) 140477110597376:(52) 140617395771136:(50) 140617636275968:(45) 140617632548608:(40) 145) 140617632548608:(40) 14064634066461108:(463140646311406467210646721146467) 8:(32) 140617397102336:(28) 140617639409408:(23) 140617635743488:(21) 140617637811968: (18) 140617638610688:(16) 140617399232256:(12) 140617638344448:(10) 140617638078208:(10) 140472304047201908:(10) 140472014047201909302 0:(10) 140617397368576:(9) 140617635211008:(6) 140617393641216:(5) 140617637545728: (3) 140617402693376:(2) 140477037254400:(1)dict0dict.cc:1239 -> 136 140477122623232:(50) 136 140477122623232:(50) 140617482061746:2061746202061746 (26) 140477123688192:(12) 140477038851840:(5) 140477030065920:( 4) 140617634412288:(4)row0trunc.cc:1835 -> 1 140477109798656:(1)
上述鎖定被寫線程持有X 鎖，重點關注出現較多鎖定，重點是出現較多的多個線程。
##********** Which writer threads block at **********
140616681907968 -> 1 trx0undo.ic:171:(1)140477173069568 -> 243 srv0srv.cc:1968:(185) row0purge.cc:861:(57) row0trunc.cc:1835:17685626767676760000760262696960002996000099900009900009900007900007255:000296076029000072572296000725:260296725:2670296725:260000725725:006825:(7682/69672962分 -89625:760296725:(7602996725:(7); .cc: 1968:(23) ha_innodb.cc:5510:(5) row0purge.cc:861:(1)
寫執行緒對應的交易訊息，也可能存在日誌記錄沒有輸出交易訊息：
********** These writer threads trx state **********MySQL thread id 83874, OS thread handle 140477173069568, query id 13139674 10.0.1.146 a deleting from reference tables
統計寫入線程持有S 鎖定情況：
****These writer threads at last time reads locked ****
140477173069568 -> 243 row0purge.cc:861:(243)140617682765568 -> 24 row0purge.cc682765568 -> 2 undo.ic:190:(1 )
統計寫入線程持有X 鎖定情況：
****These writer threads at last time write locked ****
#140477173069568 -> 243 dict0stats.cc:2366:(243)140617682765568 -> cc:1198:(1)
透過事後日誌分析，有可能出現執行緒的交易資訊沒有輸出到日誌中的情況，無法獲知事務具體執行了什麼操作。應對這種情況，小程式加入了事中採集事務資訊。 用法是這樣的：
hongbin@MBP ~> mysqldba -uxxx -pxxx doctor -w##它會監視目標mysql 的錯誤日誌，一旦出現“a writer (thread id 140616681907968) has reserved it in mode” 關鍵字就查詢ps 中的事務信息，並保存下來。
以上只是小程序一個用法，作為一個為DBA服務的小程序，還有其他功能等你去發現。歡迎與我交流你的想法。
更多SQL的相關技術文章，請造訪
SQL教學欄位進行學習！
以上是記一次MySQL semaphore crash的分析的詳細內容。更多資訊請關注PHP中文網其他相關文章！
