1. 现象:
服务重启后,首次a调用b,发现有点耗时,正常1s内返回,但是却5s后才返回。而且非常奇怪的是查看日志发现b服务5s后才收到请求并打印日志。
2.排查过程
首先怀疑gc问题导致了停顿,因为之前遇到过一次,所以这次想当然了。但是服务刚启动后其实没有fullgc的,而且通过jstat -gc命令也验证gc耗时非常短。
然后问题不断的重现,排查却陷入了停顿。
然后走入了误区,在开发环境不断的跑代码测试,问题无法重现(开发环境为windows,测试环境为linux容器)
后来思考了一下,怀疑可能网络问题导致,于是通过tcpdump抓包看看,发现b确实实时收到了报文,但是卡了5s才返回数据。初步结论应该是应用的问题了。
再次查看应用逻辑,不存在卡顿问题,忽然想起某个版本开始加了自定义的dubbo filter,也就是从这个版本开始出现了问题。查看filter代码,打印日志时,日志内容加了调用RpcContext.getContext().getRemoteHostName()获取ip地址,后来去掉后问题解决。
之前看到网上说其方法获取ip地址时有问题,比较慢,后面再研究一下。
3.后记
跟踪getRemoteHostName方法,发现最后调用的是InetAddress.getHostName()方法: 根据ip获取机器名称或域名。
该方法需要调用dns进行解析,耗时较长,如果dns没有找到会返回ip。流程大概是这样: b服务收到a服务的ip后,根据ip调用dns解析机器名,但是解析失败了,所以最后返回了ip。
为什么解析失败了呢?我们测试环境使用的是k8s,对应的ip、域名都是k8s管理的,dns中肯定是没有的,所以会因超时而失败,从而最终导致了5s超时。但开发环境是windows,且在域中,所以耗时很短,并且可以获取到域名,所以没有问题。