一次HDFS JournalNode transaction lag问题分析排查

前言


众所周知,在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的上涨。

总结


问题分析至此,最终有了一个完美的答案。事后在回顾此问题的排查,假如事先我们就考虑怀疑是否可能是其他服务影响导致的,也许我们就能够更加早地发现问题了。但是话说回来,其他情况的分析其实也是更加坚定了是推论四的可能性的。

已标记关键词 清除标记
相关推荐
©️2020 CSDN 皮肤主题: 编程工作室 设计师:CSDN官方博客 返回首页