文章來源：愛可生雲數據庫
做者：洪斌css
DBA應該對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
發生了什麼git
版本號：MySQL 5.5.40github
日誌中持續輸出線程等待數據字典鎖，位置是dict0dict.c line 305，等待時間超過了900s。
持有鎖的線程是 139998697924352 ，其十六進制是7f53fca8a700。sql
--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 748 a writer (thread id 139998697924352) has reserved it in mode exclusive number of readers 0, waiters flag 1, lock_word: 0 Last time read locked in file dict0dict.c line 302 Last time write locked in file /pb2/build/sb_0-13157587-1410170252.03/rpm/BUILD/mysql-5.5.40/mysql-5.5.40/storage/innobase/dict/dict0dict.c line 305
檢查下持鎖線程 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 178 a writer (thread id 139998697924352) has reserved it in mode wait exclusive number of readers 1, waiters flag 1, lock_word: ffffffffffffffff Last time read locked in file btr0sea.c line 1057 Last time write locked in file /pb2/build/sb_0-13157587-1410170252.03/rpm/BUILD/mysql-5.5.40/mysql-5.5.40/storage/innobase/btr/btr0sea.c line 1134
接下來看下兩處鎖結構分別在哪一個函數內：markdown
1.dict0dict.c line 305在dict_table_stats_lock函數內
2.btr0sea.c line 1134在btr_search_drop_page_hash_index函數內app
什麼狀況會調用這些函數？函數
啓用 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 0 Dictionary memory allocated 4289681 Buffer pool size 1048576 Free buffers 0 Database pages 1040831 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) trx0undo.ic:171 -> 1 140617682765568:(1) ha_innodb.cc:14791 -> 620 140617389913856:(58) 140202719565568:(58) 140202716903168:(57) 140477029533440:(56) 140617407219456:(55) 140477035656960:(52) 140477035124480:(29) 140477108467456:(29) 140477025539840:(26) 140477031130880:(25) 140477027669760:(22) 140617634944768:(21) 140617634146048:(21) 140477019948800:(21) 140477026604800:(20) 140477022078720:(18) 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) 140617634146048:(33) 140617639675648:(32) 140617397102336:(28) 140617639409408:(23) 140617635743488:(21) 140617637811968:(18) 140617638610688:(16) 140617399232256:(12) 140617638344448:(10) 140617638078208:(10) 140477033793280:(10) 140477029267200:(10) 140617397368576:(9) 140617635211008:(6) 140617393641216:(5) 140617637545728:(3) 140617402693376:(2) 140477037254400:(1) dict0dict.cc:1239 -> 136 140477122623232:(50) 140617392842496:(35) 140202726487808:(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:(1) 140617682765568 -> 29 srv0srv.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 aml deleting from reference tables
統計寫線程持有 S 鎖狀況：
****These writer threads at last time reads locked **** 140477173069568 -> 243 row0purge.cc:861:(243) 140617682765568 -> 24 row0purge.cc:861:(24) 140616681907968 -> 1 trx0undo.ic:190:(1)
統計寫線程持有 X 鎖狀況：
****These writer threads at last time write locked **** 140477173069568 -> 243 dict0stats.cc:2366:(243) 140617682765568 -> 24 dict0stats.cc:2366:(24) 140616681907968 -> 1 buf0flu.cc:1198:(1)
經過過後日誌分析，有可能出現線程的事務信息沒有輸出到日誌中的狀況，沒法獲知事務具體執行了什麼操做。應對這種狀況，小程序加入了事中採集事務信息。
用法是這樣的：
hongbin@MBP ~> mysqldba -uxxx -pxxx doctor -w
它會監視目標 mysql 的錯誤日誌，一旦出現「a writer (thread id 140616681907968) has reserved it in mode」 關鍵字就查詢 ps 中的事務信息，並保存下來。
以上只是小程序一個用法，做爲一個爲DBA服務的小程序，還有其餘功能等你去發現。歡迎與我交流你的想法。
https://github.com/kevinbin/m...