一次Namenode的RPC延迟故障排查引发的深入思考

前言

12月1日，多个省份的HDFS集群出现NameNodeRPC延迟高的问题，当时通宵了一个晚上，模糊的确认是存在频繁的du或者count操作导致的，后来也确认这个操作的发起方是开发人员用python写的采集脚本，统计数据量用的，会执行du命令，这次故障感觉还是挺有意思的，记录一下。

正文

问题排查

初步定位

过程的截图并不是记得很全，能列多少列多少吧。12月1日晚上20点左右接到电话，让协助查一下省集群任务跑不动的情况，当时看了下计算资源这些，并没发现异常的任务或者资源占用，可是任务就是跑不动。而且运行时间很久，按照经验当时就是怀疑是不是HDFS有点问题，于是看了下RPC情况，延迟高的吓人：

当时第一反应是查网络情况，确认网络都是正常的，也不存在丢包现象。NameNode的GC情况也很正常，整体来说，除了RPC高，就没有异常的指标了。于是整了30分钟的堆栈信息，看了下火焰图，感觉很可能是du或者count这种操作导致，但是并没有找到具体的操作，再加上HDFS的审计日志被关了，更是无从下手：

临时恢复

当天晚上我们把调度程序、计算任务等依次停了，然后又重启，依旧是没有找到问题的症结，由于当时依旧熬了一个通宵了，实在顶不住了，就没在继续看，交给乙方的厂商继续去排查；
emmm，没想到这事情一拖就是2天，这两天时间里，停了一些业务，任务倒是能够跑一些，但是集群整体可以看得出来还是不正常，RPC延迟一直居高不下：

定位可疑进程

于是和厂商人员协商，再停一次业务，彻底找到进程，这次不光停调度服务，要把所有访问的服务都停了，包括监控服务等，在停到一个数据量统计的监控服务的时候，发现RPC延迟出现了巨大的变化。

RPC监控图示中存在断点的原因是正好这个时候也把我的监控停了，20:20我们把嫌疑进程重启了一下，发现RPC再次冲高，而在20:30左右我们停了嫌疑进程后，RPC延迟立刻降低了：
经过和开发人员确认，得知这个监控脚本回执行du -h的操作，但是理论上来说一个du命令不该会产生这么大的影响，临时的解决方案自然是停了采集脚本，问题原因却是还没找到

问题分析

本来这个事情我已经没在管了，后来某天，采集脚本的开发部门的一个成员找我，让我有时间看看脚本哪里有问题，他们是5分钟获取一次指标，正常来说不会出现这种问题，我就答应了，也算是自己学习下。

问题脚本分析

脚本的主函数如下：

def main():
    myname = socket.getfqdn(socket.gethostname())
    myip = socket.gethostbyname(myname)
    path = "/home/redpeak/location/jiajie/"
    info = pd.read_csv(path+"qzj_ip.csv",dtype=str)
    nn = info["nn1"].loc[info["ip"]==myip].iloc[0]
    try:
        port = int(9162)
        REGISTRY.register(NameNodeCollector("http://"+nn+":8088/cluster?user.name=admin", 'redpeak'))
        # REGISTRY.register(ResourceManagerNodeCollector(args.url, args.cluster))

        start_http_server(port)
        while True:
            time.sleep(300)
    except KeyboardInterrupt:
        print(" Interrupted")
        exit(0)

其实问题脚本的主要逻辑就是自己写了个prometheus的collect，然后就启用了一个http服务，看起来开发人员的逻辑确实是想300秒更新一次指标，但是按照他的逻辑我去写了一个测试的脚本：

from prometheus_client.core import GaugeMetricFamily, CounterMetricFamily, REGISTRY
from prometheus_client import start_http_server
from time import sleep
from random import random
class CustomCollector(object):
    def collect(self):
        G=GaugeMetricFamily('my_gauge', 'Help text', value=random())
        yield G
        print(G)
        c = CounterMetricFamily('my_counter_total', 'Help text', labels=['foo'])
        c.add_metric(['bar'], 1.7)
        c.add_metric(['baz'], 3.8)
        yield c
        print(c)
        # sleep模拟一下du延迟
        sleep(10)

REGISTRY.register(CustomCollector())
start_http_server(9163)
while True:
    sleep(300)

脚本内容很简单，就是注册一个Gauge指标，每次刷新都是一个随机数，然后我运行脚本，从浏览器去访问url直接看指标值，然后我发现一个严重的问题，貌似我每请求一次，这个值就变一次，也就是说如果我一秒发10次请求，就跑10次？那要是du命令不就完了。为了进一步验证我的想法，跟踪了一下线程：

程序没有获取到请求的时候，这里只有两个常驻的线程，然后我在浏览器开始请求，同时观察线程数：

这尼玛直接就炸了好吧。

问题原因分析

好了，现在很明显，脚本是有bug的：我们环境的prometheus是15秒去获取一次监控指标，若是上次在15秒能没获取到指标，du就还在后台跑，而这个时候，prometheus已经开始下一次的指标获取，由调用了一次，在遇到HDFS繁忙的时候，大量du命令积压，铁定会出现这个问题，而对于一些HDFS不繁忙的省份来说，由于每次请求能够快速返回结果，就不会出现这种情况，所以RPC延迟只在个别省份出现，但是这个隐患在全国都存在。

代码分析

问题的原因已经定位到了，接下来看看为什么这个代码会产生这种问题，我写了一个测试代码，也是获取HDFS指定路径的数据量大小，调的du命令，不过我是设置的Gauge指标：

测试代码

from prometheus_client import Gauge,start_http_server
import time
import os
hdfs_exporter_capacityTotal=Gauge("hdfs_exporter_capacityTotal","Space for HDFS configuration.",['provincecode','provincename','type'])

start_http_server(8003)
cmd="'hadoop fs -du -h hdfs://x/x/x/x/x/x/x/x/*"
while True:
    f=os.popen(cmd)
    shuchu = f.read().replace('\n',' ').split(' ')
    suchu=float(shuchu[0])
    hdfs_exporter_capacityTotal.labels(provincecode='province',provincename='provincename',type='servertype').set(suchu)
    time.sleep(15)

我这段代码就是15秒刷新一次指标，而不是每次访问都回去刷新指标那就只有去看看prometheus_client的源码了；

prometheus_client分析

测试代码

这段代码主要就是模仿官方的测试代码写的，主要就是相观察每次刷新web的时候，是怎么一个函数调用关系：

import random
import time
from prometheus_client import Gauge,start_http_server
from prometheus_client.core import GaugeMetricFamily, CounterMetricFamily, REGISTRY

hdfs_exporter_capacityTotal=Gauge("hdfs_exporter_capacityTotal","Space for HDFS configuration.",['provincecode','provincename','type'])

start_http_server(8003)

def random_gauge():
    time.sleep(2)
    return random.random()

class CustomCollector(object):
    def collect(self):
        G=GaugeMetricFamily('my_gauge', 'Help text', value=random_gauge())
        yield G
        print(G)
        c = CounterMetricFamily('my_counter_total', 'Help text', labels=['foo'])
        c.add_metric(['bar'], 1.7)
        c.add_metric(['baz'], 3.8)
        yield c
        print(c)

REGISTRY.register(CustomCollector())


while True:
    suchu=random.random()
    hdfs_exporter_capacityTotal.labels(provincecode='province',provincename='provincename',type='servertype').set(suchu)
    time.sleep(15)

直接使用Gauge和自定义Gauge，每次访问8003端口只有自定义的Gauge方法会被调用，看起来要从start_http_server方法入手，跟踪这个方法，根据我们的调试结果，定位到process_request方法：

def process_request(self, request, client_address):
    """Start a new thread to process the request."""
    if self.block_on_close:
        vars(self).setdefault('_threads', _Threads())
    t = threading.Thread(target = self.process_request_thread,
                         args = (request, client_address))
    t.daemon = self.daemon_threads
    self._threads.append(t)
    t.start()

找到启动的线程了：


这验证了每次请求会多启动一个线程，多个请求发过来，线程就会启动很多，而我的函数之所以不会产生这个问题，是因为我的业务逻辑是由while True控制的，无论发送多少次get请求，并没有绑定对应的方法。