利用 Arthas 解決啟動 StandbyNameNode 載入 EditLog 慢的問題
作者 | yhf20071
【Arthas 官方社群正在舉行徵文活動，參加即有獎品拿~點選投稿】
公司新搭 HDFS 叢集，namenode做ha，但是在啟動 StandbyNamenode 節點的時候出現奇怪的現象：空叢集載入 Editlog 很慢，每次重啟幾乎耗時都在二三十分鐘
為了方便大家理解，大致說下 StandbyNamenode（以下簡稱 SNN）啟動過程：
- SNN 啟動時，如果本地沒有 FSImage會去 ANN（ActiveNamenode）拉取 FSImage
- 如果本地有 FSImage，則會根據 transactionId 去 JournalNode 拉取 gap 的 editlog，在本地做合併
問題就出在第 2 步，在從 JournalNode 拉取 EditLog 過程中出現固定 15s 延遲。一般來說，空叢集幾乎沒有操作， editlog 不會太大，不應該出現每次從 JournalNode 拉取 EditLog 都耗費 15s 的時間，日誌如下（為了方便觀察擷取部分日誌）：
2020-11-04 18:27:27,577 INFO namenode.RedundantEditLogInputStream (RedundantEditLogInputStream.java:nextOp(177)) - Fast-forwarding stream 'http://cbdp-online1.sdns.fin ancial.cloud:8480/getJournal?jid=hdfs-ha&segmentTxId=213656&storageInfo=-64%3A272699407%3A1603893889358%3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11&inProgressOk=true' to transaction ID 184269 2020-11-04 18:27:42,582 INFO namenode.FSEditLogLoader (FSEditLogLoader.java:loadEditRecords(289)) - replaying edit log: 1/44 transactions completed. (2%) 2020-11-04 18:27:42,583 INFO namenode.FSImage (FSEditLogLoader.java:loadFSEdits(162)) - Edits file http://cbdp-online1.sdns.financial.cloud:8480/getJournal?jid=hdfs-ha &segmentTxId=213656&storageInfo=-64%3A272699407%3A1603893889358%3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11&inProgressOk=true, http://cbdp-online2.sdns.financial.cloud:8 480/getJournal?jid=hdfs-ha&segmentTxId=213656&storageInfo=-64%3A272699407%3A1603893889358%3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11&inProgressOk=true, http://cbdp-onli ne3.sdns.financial.cloud:8480/getJournal?jid=hdfs-ha&segmentTxId=213656&storageInfo=-64%3A272699407%3A1603893889358%3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11&inProgres sOk=true of size 5981 edits # 44 loaded in 15 seconds ...... 2020-11-04 18:27:42,583 INFO namenode.RedundantEditLogInputStream (RedundantEditLogInputStream.java:nextOp(177)) - Fast-forwarding stream 'http://cbdp-online1.sdns.financial.cloud:8480/getJournal?jid=hdfs-ha&;segmentTxId=213700&storageInfo=-64%3A272699407%3A1603893889358%3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11&inProgressOk=true' to transaction ID 184269 2020-11-04 18:27:57,588 INFO namenode.FSEditLogLoader (FSEditLogLoader.java:loadEditRecords(289)) - replaying edit log: 1/53 transactions completed. (2%) 2020-11-04 18:27:57,589 INFO namenode.FSImage (FSEditLogLoader.java:loadFSEdits(162)) - Edits file http://cbdp-online1.sdns.financial.cloud:8480/getJournal?jid=hdfs-ha&;segmentTxId=213700&storageInfo=-64%3A272699407%3A1603893889358%3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11&inProgressOk=true, http://cbdp-online2.sdns.financial.cloud:8480/getJournal?jid=hdfs-ha&;segmentTxId=213700&storageInfo=-64%3A272699407%3A1603893889358%3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11&inProgressOk=true, http://cbdp-online3.sdns.financial.cloud:8480/getJournal?jid=hdfs-ha&;segmentTxId=213700&storageInfo=-64%3A272699407%3A1603893889358%3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11&inProgressOk=true of size 7088 edits # 53 loaded in 15 seconds
1.首先通過日誌初步定位程式碼，粗略定位耗時方法
trace org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader loadFSEdits
2.上面的結果只能確定大致耗時方法塊，不能精確定位實際耗時方法，如果要精確定位，需要一層一層展開，其中還涉及回撥函式、native 函式；為了可以更方便的定位程式碼，我們先執行 profiler start，觀察下耗時函式呼叫
profiler start/stop
3.繼續追蹤函式
trace org.apache.hadoop.hdfs.server.namenode.EditLogFileInputStream$URLLog$1 run
4.因為過程中涉及了 jdk 函式追蹤，我們需要設定 options unsafe true
trace --skipJDKMethods false sun.net.www.http.HttpClient parseHTTPHeader
trace --skipJDKMethods false java.net.SocketInputStream socktRead '#cost > 10000'
5.我們最後通過呼叫棧確認程式碼執行路徑
stack *SocketInputStream socketRead "#cost > 10000"
發現由於 StandbyNameNode 的網路讀取資料造成阻塞，到此已經碰到 native 函式，在 java 層面已經沒有有效方法進行分析。
這時我看到 StandbyNameNode 的日誌：
2020-11-04 18:27:42,583 INFO namenode.RedundantEditLogInputStream (RedundantEditLogInputStream.java:nextOp(177)) - Fast-forwarding stream 'http://cbdp-online1.sdns.financial.cloud:8480/getJournal?jid=hdfs-ha&;segmentTxId=213700&storageInfo=-64%3A272699407%3A1603893889358%3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11&inProgressOk=true' to transaction ID 184269
同時想起了 @赫炎 提出的思路，有可能是在 JournalNode 端讀取 EditLog 檔案的時候有阻塞。
6.我們在 JournalNode 側追蹤程式碼呼叫耗時
trace --skipJDKMethods false org.apache.hadoop.hdfs.qjournal.server.GetJournalEditServlet doGet '#cost > 10000'
發現在呼叫 java.net.InetSocketAddress.getHostName 處耗時 15s，至此找到了罪魁禍首。
結論：
- 經分析發現在在開啟 Kerberos 的情況下，JournalNode 側響應 getEditLog 介面呼叫時會進入方法 isValidRequestor，此時會去解析 SecondNameNode 的 hostName，據此搜尋對應的 principal
- dns 域名解析服務不能獲取 SecondNameNode 的預設地址 0.0.0.0:9868，也即不能解析 0.0.0.0 的 hostName，此處超時 15s 返回，這樣每次通過 URLLog 獲取 JournalNode的EditLog 時，總會有額外耗時 15s，導致 SNN 載入 EditLog 變慢。
為了驗證猜想，在每個 JournalNode 節點 hosts 檔案配置 0.0.0.0 0.0.0.0，重啟 SNN，速度提升了 20 倍
不得不說，Arthas 作為動態追蹤除錯 java 程序的神器，真的很方便開發人員定位問題。贊一個！