利用 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 有關的内容

歡迎參加征文活動，還有獎品拿哦~