利用 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，至此找到了罪魁禍首。

結論：

1. 經分析發現在在開啟 Kerberos 的情況下，JournalNode 側響應 getEditLog 接口調用時會進入方法 isValidRequestor，此時會去解析 SecondNameNode 的 hostName，據此搜索對應的 principal
2. 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 進程的神器，真的很方便開發人員定位問題。贊一個！

Arthas 徵文活動火熱進行中

Arthas 官方正在舉行徵文活動，如果你有：

• 使用 Arthas 排查過的問題
• 對 Arthas 進行源碼解讀
• 對 Arthas 提出建議
• 不限，其它與 Arthas 有關的內容

歡迎參加徵文活動，還有獎品拿哦~點擊投稿