前言

眾所周知，在HDFS集群中，NameNode服務是其中的核心服務，NameNode的性能處理效率的高低直接影響著其對外提供的服務能力，鑒于過往筆者已經寫過諸多NameNode優化系列的文章，本文筆者來聊聊另外與NameNode相關的服務JournalNode（簡稱JN）服務，JournalNode是在HDFS HA模式下用來做共享editlog的存盤的，別看JN服務功能單一，但是其所造成的影響可以很大，NN寫JN editlog慢不僅會影響Standby NN的最新狀態的同步，而且還會影響Active NN的正常RPC處理效率，因為在NN處理RPC寫請求的時候，在每次請求處理完畢，會寫一條對應的transaction log資訊，本文筆者來簡單分享一次最近發生在作業中的NN寫JN transaction出現延時的問題，主要給大家分享分享里面問題排查的思路程序，給大家帶來一些參考意義，

背景

問題的背景很簡單，平時正在正常運行的HDFS集群，突然有一天頻繁的發生了JN lag（即Active NN寫JN editlog出現延時現象）的情況，然后我們觀察到了此現象，開始了問題的排查，

JN lag的樣例截圖

上圖中最后一個JN出現xx txns/xxms behind字樣的即為lag的JN，

在JN lag問題排查之前，我們首先羅列出了所有可能導致此情況發生的原因：

• 1）JN服務本身問題，如code bug的問題，
• 2）NN服務問題，寫此JN的邏輯出現問題，
• 3）JN所在機器的硬體層面出現問題，比如磁盤，網路問題，
• 4）JN受所在機器其它服務的影響，

JN lag的問題大致上逃不出上面提到的這4種情況，后面，筆者開始進行逐一情況的排查，

問題追蹤排查分析

排查一：JN服務本身問題

要排查是否是JN服務本身的問題，基本會使用到的手段無非jstack打個thread dump，判斷是否出現死鎖或者操作hung住的情況，另外行程的GC情況也是需要去觀察和留意的，這步排查完畢，沒有看到明顯的例外，

另外對于JN服務本身，我們還看了JN的log和它自身暴露的一些JMX指標，log里沒有看到有用的資訊，但是出問題的JN JMX指標和正常的JMX指標存在略微差異，

 # Lag JN的JMX指標
 {
    "name" : "Hadoop:service=JournalNode,name=RpcActivityForPort8485",
    "modelerType" : "RpcActivityForPort8485",
    "tag.port" : "8485",
    ...
    "RpcQueueTimeNumOps" : 46466784,
    "RpcQueueTimeAvgTime" : 0.03773584905660377,
    "RpcLockWaitTimeNumOps" : 46466784,
    "RpcLockWaitTimeAvgTime" : 0.0,
    "RpcProcessingTimeNumOps" : 46466784,
    "RpcProcessingTimeAvgTime" : 0.02342225113858165,
    ...
    "RpcSlowCalls" : 32251,
    "NumOpenConnections" : 6,
    "CallQueueLength" : 0,
    "ReadCallQueueLength" : 0,
    "WriteCallQueueLength" : 0
  }
# 正常JN的JMX指標
 {
    "name" : "Hadoop:service=JournalNode,name=RpcActivityForPort8485",
    "modelerType" : "RpcActivityForPort8485",
    "tag.port" : "8485",
    ...
    "RpcQueueTimeNumOps" : 6193612644,
    "RpcQueueTimeAvgTime" : 1.3103095828670942E-4,
    "RpcLockWaitTimeNumOps" : 6193612644,
    "RpcLockWaitTimeAvgTime" : 0.0,
    "RpcProcessingTimeNumOps" : 6193612644,
    "RpcProcessingTimeAvgTime" : 0.059417520460616005,
    ...
    "RpcSlowCalls" : 2706685,
    "NumOpenConnections" : 6,
    "CallQueueLength" : 0,
    "ReadCallQueueLength" : 0,
    "WriteCallQueueLength" : 0
  }

通過對上面JMX的指標對比，我們還是能夠得到一些相當有用的資訊的，首先是JN RPC的process time處理時間上，2個JN的時間是在一個數量級上的，甚至出問題的JN的process time更快，

為了進一步不是JN服務本身的問題，我們決定重啟JN服務，來觀察是否JN lag現象能夠消失，結果不幸的是，JN lag依然存在，因此基本排除是JN服務自身的問題，

排查二：NN 服務問題

經過推理一結論，既然NN寫editlog出現lag現象的target JN沒問題，那么是否有可能是源頭NN寫的問題呢？

我們簡單看了下NN的log，沒有發現與此強相關的例外資訊，另外我們發現了額外的一個資訊點：所有HDFS Federation NN往問題JN上寫的editlog都出現了lag的情況，這就再次表明了lag問題還是出在了JN這個機器本身上，但這次懷疑的目標從JN服務本身轉移到了JN機器層面的問題上了，

排查三：JN機器硬體層面問題

問題倘若真發生在機器層面上，排查的難度毫無疑問會加大許多，畢竟術業有專攻，不過，做大大資料的工程師，一些簡單的排查還是可以做一做的，

這里我們做了簡單的分析，用iostat命令觀察機器的ioutil, iowait指標看看磁盤的性能，發現磁盤讀寫本身沒有多少問題，繼而看看是否存在網路的問題，

針對網路連接這類的問題排查，除了最為常見測驗連通性的ping，telnet命令，這里給大家推薦另外2個極為管用的工具命令：

• 第一個，mtr命令，mtr不僅可以用來測驗與目標地址的連通性，丟包率，它還能夠顯示packet在每一跳上的丟包率，
• 第二個，traceroute命令，traceroute命令能夠直接展示在每一跳上的時間耗時，

這里我們做了總共正反兩組的對比測驗：

• NN向所有JN的mtr, traceroute測驗，以檢測NN對于其所屬JN的網路連通性情況，
• 問題JN，正常JN向NN的的mtr, traceroute測驗，以檢測JN到NN的網路連通性情況，

經過測驗，我們沒有發現丟包達到情況，但是發現了一個明顯的差異在于JN到NN的測驗，如下圖所示：

[ lag_jn]$ traceroute NN_node
traceroute to xxxx, 30 hops max, 60 byte packets
xxxx  8.132 ms  8.127 ms  8.174 ms
 
 
[ normal_jn]$  traceroute NN_node
traceroute to xxxx, 30 hops max, 60 byte packets
xxxx  0.107 ms  0.094 ms  0.087 ms

上面圖示結果表明，發送同樣數量的packets，lag jn的耗時遠遠大于正常JN的耗時，后續，我們馬上聯系了網路組的同學，請求幫助分析問題JN是否存在網路層面類似交換機上的問題，

網路組的同學在除錯的程序中，也發現了這里的latency問題，不過他們還額外檢測到一個例外的情況：問題JN的網路介面的帶寬處于一個幾乎被打滿的情況，如下圖：

另外更為重要的一點是，帶寬開始出現例外飆升的時間點和JN lag問題開始出現的時間是完全匹配的，

問題分析到這里，我們關注的焦點鎖定在了這些例外的traffic流量上了，首先JN服務本身editlog寫的量是很小的，肯定不會造成這么大的流量改變，于是我們逐級懷疑是此機器上的其它服務造成的，即上面的推論四，

推論四：JN受所在機器其它服務的影響

我們重新梳理了下此JN所在機器上部署的各個服務，其中最為重量級的服務是YARN的RM服務，是否是RM在近端時間服務了更多的application請求，導致了traffic的上漲呢？在RM中涉及到網路資料傳輸影響最大的是getApplications這類的API call，隨后我們對此call的頻率做了一個分析統計，類似如下log的記錄統計，

2020-12-29 04:01:21,687 WARN org.apache.hadoop.ipc.Server: Slow RPC : getApplications took 5MILLISECONDS to process from client org.apache.hadoop.yarn.api.ApplicationClientProt
ocolPB.getApplications from xx.xx.xx.xx Call#2471092 Retry#0
2020-12-29 04:01:21,692 WARN org.apache.hadoop.ipc.Server: Slow RPC : getApplications took 4MILLISECONDS to process from client org.apache.hadoop.yarn.api.ApplicationClientProt
ocolPB.getApplications from xx.xx.xx.xx Call#2471093 Retry#0

后續我們發現RM的getApplications確實比上個月同期增長了一倍之多，通過尋找里面出現的高頻率的source ip地址找到了對應的業務部門，進行溝通了解后，確實是他們的業務流量在近期有了部分的調整，造成了大量getApplications call的增加，進而大幅度地導致RM機器traffic的上漲，

總結

問題分析至此，最終有了一個完美的答案，事后在回顧此問題的排查，假如事先我們就考慮懷疑是否可能是其他服務影響導致的，也許我們就能夠更加早地發現問題了，但是話說回來，其他情況的分析其實也是更加堅定了是推論四的可能性的，