张彦程(张昱)

前言

本篇文章，和大家分享一下之前发生在生产环境的一次问题排查与分析过程，这个问题本身并没有特别复杂，但需要排查的同学足够的细心谨慎，能从监控及日志中提取关键信息，一步步缩小问题范围并最终定位到问题点，这个问题点一般都可以具体到一行确定的代码，即问题代码。但”问题代码“往往并不一定是”错误代码“，由于运行时因为一些其他因素，导致这行看上去完全正确的代码，运行出了不符合预期的结果，而这个结果也可能是偶发的，即它没有固定的发生条件，比如发生时间、发生节点和发生数据等等，这也是大部分疑难故障难以直接通过review代码的方式来定位的原因。

因此，我们排查问题时，切勿想当然，而是要严格基于现有的数据”大胆假设小心求证“，并适当使用排除法，真相一定只有一个。

问题反馈

某天，业务开发同学A，在研发群里反馈，交易系统（trade）依赖下游的一个dubbo服务S（用户系统 ustone）最近一段时间偶发调用超时（这里说明一下，单次的dubbo调用超时并不会直接导致上游报错，dubbo会进行failover重试到其他节点，如果其他节点服务正常，可以正确响应，则上游就不会出问题），并提供了最近一次报错调用双方的服务节点IP。经过初步沟通，该问题是发生了多次，研发才反馈出来，并没有确定的发生条件。而且下游开发同学查看自己的业务日志记录的执行时间很短（<50ms），绝对不会触发超时，所以矛盾就出现了。

排查

链路分析

登录到问题机器上，找到dubbo超时的报错日志，拿到traceId。traceId为我司使用的全链路监控工具pinpoint生成的链路调用ID，该ID在调用的入口处网关服务内生成，并一路透传到各个下游服务节点，且会记录在日志中。通过此ID在

pinpoint的链路查询页面，查看到的调用详情中，有单个方法的调用耗时为2019ms，这说明长耗时没监控到了，超时确实发生了（生产一般dubbo超时配置为1000ms）。但这个监控中有个明显的异常点，就是那个gap 2021

关于pinpoint gap含义，用一张图简单说明一下：

定位耗时节点

目前，公司内部使用dubbo作为RPC框架，并扩展了一个filter（YtTraceFilter）记录每个dubbo调用的开始时间、执行耗时、结果状态、接口信息等等，贴下伪代码：

public class YtTraceFilter implements Filter {
 
    @Override
    public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
        RpcContext context = RpcContext.getContext();
        long start = System.currentTimeMillis();
        boolean isConsumer = context.isConsumerSide();
        boolean isProvider = context.isProviderSide();
 
        //记录调用信息
        DubboTraceData dubboTraceData = new DubboTraceData();
        dubboTraceData.setProtocolVersion(url.getParameter(CommonConstants.DUBBO));
        dubboTraceData.setAppName(url.getParameter(CommonConstants.APPLICATION_KEY));
        dubboTraceData.setInterfaceName(url.getPath());
        dubboTraceData.setInvokeMethod(RpcUtils.getMethodName(invocation));
        dubboTraceData.setNodeIp(NetUtil.getLocalIP());
        dubboTraceData.setStartTime(start);
        dubboTraceData.setTimestamp(start);
        dubboTraceData.setInterfaceAndMethod(dubboTraceData.getInterfaceName() +
        ...
 
        Result result;
        try {
            result = invoker.invoke(invocation);
 
            dubboTraceData.setStatus(KeyConstants.STATUS_OK);
            recordLog(dubboTraceData, start);
            return result;
        } catch (RpcException e) {
            if (e.isTimeout()) {
                dubboTraceData.setStatus(KeyConstants.STATUS_TIMEOUT);
            } else {
                dubboTraceData.setStatus(KeyConstants.STATUS_FAIL);
            }
            recordLog(dubboTraceData, start);
            throw e;
        } finally {
            ...
        }
    }
 
    private void recordLog(DubboTraceData dubboTraceData, long start) {
        dubboTraceData.setProcessTime(System.currentTimeMillis() - start);
        logStore.store(dubboTraceData.toJsonString());
    }
}

其中result = invoker.invoke(invocation);这代码，就是dubbo框架执行实际调用的入口，对于provider侧，可以理解从这个invoke进入才是调用实际的dubbo service。可以看到，不论是否调用成功，都会以json形式记录dubboTraceData的信息到日志里，因此到问题的下游ustone - 172.16.60.193机器上，查看当前trace对应的上述log：

这个日志里，包含了某次dubbo调用的几乎全部的关键信息，各个字段也很好理解，这里就不多做解释了。其中processTime表示filter记录的dubbo调用耗时，耗时2026ms，说明YtTraceFilter记录到的在ustone内部执行的时间确实是比较长的，和pinpoint监控的时间贴合，因此可以定位到耗时发生在ustone侧，排除掉trade应用内、网络层的原因。其实，这一点仔细看pp的链路图也可以推断出来。

定位耗时代码

log记录的startTime：1613803316217 → 2021-02-20 14:41:56.217，这个时间紧跟trade机器记录的最后一次时间14:41:56 216，说明在startTime记录之前耗时还没有发生，所以，结合YtTraceFilter#invoke的代码，是可以确定耗时发生的

long start = System.currentTimeMillis(); 这行代码之后的。由于实际的业务代码执行耗时又是非常短的，这个前面已经提到，是小于50ms的，显然和这个2026m不符合，因此可以初步确定耗时是发生在框架内部。

再仔细看pp记录的ustone的调用耗时

这个pinpoint span，它的类是AbstractProxyInvoker，其实就是pinpoint的dubbo插件，记录的result = invoker.invoke(invocation);这行的方法调用记录，执行时间是14:41:58 237，这个信息很关键，说明在该行方法开始执行时，耗时已经发生过了

综上，进一步缩小了耗时代码的发生范围，即发生在YtTraceFilter#invoke方法中，long start = System.currentTimeMillis(); 之后，result = invoker.invoke(invocation);之前。

至此，问题就相对简单了，逐行分析YtTraceFilter#invoke的代码，推断耗时应该是dubboTraceData.setNodeIp(NetUtil.getLocalIP());也就是NetUtil.getLocalIP()的调用，之所以这样推断，是因为除此行之外，其他代码都是从对象中存取值，都是内存操作，不可能发生长耗时。

另外，我们假设是这个地方的问题，那么就说明，这个耗时问题将是无差别的（filter特性，它是对所有接口都生效的），也就是该节点的任何接口调用都可能发生此问题。然后，去查看监控上该节点的接口耗时统计TOP图，确实看到多个接口都存在长耗时，这点也可以变相说明对问题推断是正确的

验证
NetUtil.getLocalIP()内部非常简单，就只有一行代码：InetAddress.getLocalHost().getHostAddress()，因此只要在172.16.60.193这台问题机器上，打印一下这个耗时，就可以验证

测试代码：

public class Test {
    public static void main(String[] args) throws Exception {
        while (true) {
            long start = System.currentTimeMillis();
            String ip = java.net.InetAddress.getLocalHost().getHostAddress();
            long end = System.currentTimeMillis();
            System.out.println("ip: " + ip + ", cost: " + (end - start) + "ms");
            Thread.sleep(1000);
        }
    }
}

如上，每隔1s打印一下InetAddress.getLocalHost()耗时，执行一段时间，观察输出结果大概如下，会看到时不时会有一次超过2000ms的，至此问题得证

ip: 172.16.60.193, cost: 0ms
ip: 172.16.60.193, cost: 1ms
ip: 172.16.60.193, cost: 1ms
ip: 172.16.60.193, cost: 0ms
ip: 172.16.60.193, cost: 2018ms
ip: 172.16.60.193, cost: 1ms
ip: 172.16.60.193, cost: 1ms
ip: 172.16.60.193, cost: 0ms
ip: 172.16.60.193, cost: 2002ms
ip: 172.16.60.193, cost: 0ms

修复

问题代码为获取本机IP设置到nodeIp字段，这个本机IP其实dubbo context中已经有了，不需要再获取，直接取dubbo context保存的值即可。因此，修改如下

然后就是将上述修复代码，打包，推进出问题的业务方升级即可

后续

到这里，聪明的你，一定会问：jdk的InetAddress.getLocalHost()是正常的调用，为什么会慢呢？

关于这点，网上有很多类似的问题反应，但似乎都没有一个明确的结论，只知道和dns解析有关（getLocalHost内部有一个通过本机hostname解析出IP的步骤，这个会走dns解析服务），这里简单贴一下后来运维同学的排查结论：

故障发生时，问题机器的dns解析顺序为：files→ dns→ myhostname。其中files指/etc/hosts文件，我司所有ecs机器都没有配置hosts，就会走到dns，走阿里云提供的的dns解析服务，猜测可能是走该服务导致的解析耗时，因此对解析顺序进行了调整，统一改为：files→ myhostname→ dns，修改后测试也未再发现有解析慢的情况了

对于本篇的案例，如果应用升级了修复的代码，不论底层dns是否调整，问题都不会再发生。