利用 Arthas 解決啟動(dòng) StandbyNameNode 加載 EditLog 慢的問(wèn)題

公司新搭 HDFS 集群，namenode做ha，但是在啟動(dòng) StandbyNamenode 節(jié)點(diǎn)的時(shí)候出現(xiàn)奇怪的現(xiàn)象：空集群加載 Editlog 很慢，每次重啟幾乎耗時(shí)都在二三十分鐘

為了方便大家理解，大致說(shuō)下 StandbyNamenode（以下簡(jiǎn)稱(chēng) SNN）啟動(dòng)過(guò)程：

• SNN 啟動(dòng)時(shí)，如果本地沒(méi)有 FSImage會(huì)去 ANN（ActiveNamenode）拉取 FSImage
• 如果本地有 FSImage，則會(huì)根據(jù) transactionId 去 JournalNode 拉取 gap 的 editlog，在本地做合并

問(wèn)題就出在第 2 步，在從 JournalNode 拉取 EditLog 過(guò)程中出現(xiàn)固定 15s 延遲。一般來(lái)說(shuō)，空集群幾乎沒(méi)有操作， editlog 不會(huì)太大，不應(yīng)該出現(xiàn)每次從 JournalNode 拉取 EditLog 都耗費(fèi) 15s 的時(shí)間，日志如下（為了方便觀(guān)察截取部分日志）：

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.首先通過(guò)日志初步定位代碼，粗略定位耗時(shí)方法

trace org.apache.hadoop.hdfs.server.namenode.FSEditLogLoader loadFSEdits

2.上面的結(jié)果只能確定大致耗時(shí)方法塊，不能精確定位實(shí)際耗時(shí)方法，如果要精確定位，需要一層一層展開(kāi)，其中還涉及回調(diào)函數(shù)、native 函數(shù)；為了可以更方便的定位代碼，我們先執(zhí)行 profiler start，觀(guān)察下耗時(shí)函數(shù)調(diào)用

profiler start/stop

3.繼續(xù)追蹤函數(shù)

trace org.apache.hadoop.hdfs.server.namenode.EditLogFileInputStream$URLLog$1 run

4.因?yàn)檫^(guò)程中涉及了 jdk 函數(shù)追蹤，我們需要設(shè)置 options unsafe true

trace --skipJDKMethods false sun.net.www.http.HttpClient parseHTTPHeader trace --skipJDKMethods false java.net.SocketInputStream socktRead '#cost > 10000'

5.我們最后通過(guò)調(diào)用棧確認(rèn)代碼執(zhí)行路徑

stack *SocketInputStream socketRead "#cost > 10000"

發(fā)現(xiàn)由于 StandbyNameNode 的網(wǎng)絡(luò)讀取數(shù)據(jù)造成阻塞，到此已經(jīng)碰到 native 函數(shù)，在 java 層面已經(jīng)沒(méi)有有效方法進(jìn)行分析。

這時(shí)我看到 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`](https://www.oschina.net/action/GoToLink?url=http%3A%2F%2Fcbdp-online1.sdns.financial.cloud%3A8480%2FgetJournal%3Fjid%3Dhdfs-ha%26%3BsegmentTxId%3D213700%26storageInfo%3D-64%3A272699407%3A1603893889358%3ACID-aa8ec1b5-a501-4195-9299-e14abefbdc11%26inProgressOk%3Dtrue)`' to transaction ID 184269

同時(shí)想起了 @赫炎 提出的思路，有可能是在 JournalNode 端讀取 EditLog 文件的時(shí)候有阻塞。

6.我們?cè)?JournalNode 側(cè)追蹤代碼調(diào)用耗時(shí)

trace --skipJDKMethods false org.apache.hadoop.hdfs.qjournal.server.GetJournalEditServlet doGet '#cost > 10000'

發(fā)現(xiàn)在調(diào)用 java.net.InetSocketAddress.getHostName 處耗時(shí) 15s，至此找到了罪魁禍?zhǔn)住?/p>

結(jié)論：

經(jīng)分析發(fā)現(xiàn)在在開(kāi)啟 Kerberos 的情況下，JournalNode 側(cè)響應(yīng) getEditLog 接口調(diào)用時(shí)會(huì)進(jìn)入方法 isValidRequestor，此時(shí)會(huì)去解析 SecondNameNode 的 hostName，據(jù)此搜索對(duì)應(yīng)的 principal

dns 域名解析服務(wù)不能獲取 SecondNameNode 的默認(rèn)地址 0.0.0.0:9868，也即不能解析 0.0.0.0 的 hostName，此處超時(shí) 15s 返回，這樣每次通過(guò) URLLog 獲取 JournalNode的EditLog 時(shí)，總會(huì)有額外耗時(shí) 15s，導(dǎo)致 SNN 加載 EditLog 變慢。

為了驗(yàn)證猜想，在每個(gè) JournalNode 節(jié)點(diǎn) hosts 文件配置 0.0.0.0 0.0.0.0，重啟 SNN，速度提升了 20 倍

參考鏈接：https://my.oschina.net/u/3874284/blog/4763265

總結(jié)

以上是生活随笔為你收集整理的利用 Arthas 解决启动 HDFS StandbyNameNode 加载 EditLog 慢的问题的全部?jī)?nèi)容，希望文章能夠幫你解決所遇到的問(wèn)題。

如果覺(jué)得生活随笔網(wǎng)站內(nèi)容還不錯(cuò)，歡迎將生活随笔推薦給好友。