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，且在域中，所以耗时很短，并且可以获取到域名，所以没有问题。
网友评论