问题现象及影响
gRPC在我司被广泛应用,之前在搭建gRPC服务时遇到了奇怪的问题,Client端在第一次调用Server端时回超时,但是第二次之后就基本正常了,这种情况会导致的问题是在该环境搭建的API服务,在启动后可能需要调用多次才能正常返回(gRPC存在调用链,调用超时会导致直接抛异常,本次请求会失败),并且存在潜在的数据不一致问题,这在一定程度上不能确保搭建的gRPC服务的稳定性和正确性。
gRPC服务的简单结构如下:

简单分析
由于搭建的环境位于办公网络,和线上服务环境有差异,首先想到的是网络问题,但是通过ping的方式看时间都在10ms以内,而目前我们使用的gRPC超时都在秒级别,觉得不是网络问题,需要通过按照上图中的每个点逐步分析。
详细分析(Step 1)
首先需要从Client找到发生超时的具体代码,这里通过jvisualvm对Client进行profile,找到如下热点代码:

图中红色框部分方法是公司框架对gRPC做的包装,在Client端创建ChannelInfo后对其进行预热,方式是通过调用HealthCheck服务,通过debug确认超时问题发生在这个调用HealthCheck.check方法。
注意,可以在测试代码前加一定的Sleep时间,方便在jvisualvm里attach进程并选择sampler
图中排在第一位的是测试代码入口方法,可排除
详细分析(Step 2)
怀疑是网络问题,因为从Server端的HealthCheck服务代码看不可能耗时这么久,因此在Client和Server端分别开启tcpdump抓包,通过对照HTTP2请求的发送和接收时间,发现网络延迟在8毫秒以内,因此不是网络问题,抓包情况入下图:

详细分析(Step 3)
现在看问题只有可能出现在Server端了,Cleint端发送的请求会被Server端的EventLoop boss线程select到,然后通过HTTP2解码,送到worker线程,两者的交界处是SerializingExecutor.execute,在这里boss线程Client端发送的请求加到队列,worker线程会从中拉取出请求并根据请求匹配到相应的服务执行调用。
直接在SerializingExecutor.execut处通过arthas的trace功能查看方法内每个调用的时间,非常幸运我们看到了这个方法的调用时间是秒级的而且匹配超时时间,通过进一步缩小范围发现耗时较多的是ProfileInterceptor里的一个调用,调用如下:

这个点明显就是Server端在用Client端的ip拿host的过程,这个的作用是记监控,问题就很明显了,DNS反解析出问题了
详细分析(Step 4)
查看Server机器的DNS配置 /etc/resolv.conf,配置如下:

尝试ping两个nameserver,发现192.168.43.27不能ping通,断定问题就出在Server和该nameserver网络不通,联系运维同学确认了是nameserver没有设置好,因为目前该环境都是在172的子网内,并没有在192.168子网内,将192从nameserver中删除后问题修复
总结
分析过程中Step 1和Step 2并没有耗费很多时间,Step 3耗费了一些时间,最开始想通过远程debug确定耗时点,但是由于同一个JVM中运行了N个服务,debug的时候不能刚好抓到超时的那个请求,走了一些弯路(当时还怀疑是不是Step 2出问题了)
其实后来发现有时候第一次不会超时,但是大部分时候会超时,应该是我大部分时候都rotate到不可访问的nameserver上去了
总的来说这个问题不是太复杂,但是个人觉得方法步骤都很正确,当时耗费了一些时间来查,所以记录一下
Reference
- arthas
- gRPC