为什么 SOFA RPC 调用30s还不超时？

原创

AlifinTamSRE 2020-09-19 19:47:28 ©著作权

文章标签 RPC 运维排查 getLocalHostName 文章分类 运维

©著作权归作者所有：来自51CTO博客作者AlifinTamSRE的原创作品，如需转载，请与作者联系，否则将追究法律责任

为什么 SOFA RPC 调用30s还不超时？

背景

最近帮客户处理了一个诡异的 RPC 调用问题，想跟大家分享一下。关于 SOFA RPC，请参考我们的官网。

问题现象

客户使用 REST 接口触发 RPC 的调用，发现每次 RPC 调用都需要30秒的时间，最终的 RPC 调用结果是成功的。从业务日志来看，开始处理业务和结束业务之间确实花了30秒。

问题分析

RPC 调用花了30秒调用成功，这本身是一件诡异的事情。因为默认 SOFA RPC 的框架 RPC 超时时间是3秒。下面的代码显式的设置了超时时间，设置成了默认值。

<sofa:reference jvm-first="false" id="rpcService" interface="com.sofa.rpc.facade.demo.RpcService">
    <sofa:binding.bolt>
        <sofa:global-attrs timeout="3000" />
    </sofa:binding.bolt>
</sofa:reference>

我们首先确定了代码中确实没有更改 SOFA RPC 框架的默认超时时间。所以，理论上 RPC 调用超过3秒，RPC 客户端就应该报错了。那么，我们来看看这30秒到底发生了什么！

直击框架核心

我们知道 SOFA RPC 调用的超时时间是3秒，我们首先需要确认 SOFA RPC 框架到底花了多少时间。根据业务日志的时间点（2020-01-21 10:41:34），查看 RPC 的 digest 日志： /home/admin/logs/tracelog/rpc-client-digest.log。我们发现 RPC 执行的时间才54ms。这证明实际上 RPC 调用是很快的！那么时间到底去哪里了？

2020-01-21 10:42:04.186,xxx_app,0a014046157957449410610155674,0,com.xxx.xxx.service.xxxService:1.0,$genericInvoke,bolt,sync,xxx.xxx.xxx.72:12222,xxx,,,,,00,2296B,889B,54ms,0ms,0ms,54ms,http-nio-8080-exec-10,REGISTRY,,,,xxx.xxx.xxx.72,12222,,,

难道时间花在获得 RPC provider 的地址上了？于是，我们查看 RPC 客户端的注册中心寻址日志，/home/admin/logs/rpc/rpc-registry.log。我们发现该接口的地址在三秒前就返回了。所以也不是寻址的问题。

2020-01-21 10:41:31,330 INFO  ObserverNotifyThread-2-thread-5  com.alipay.sofa.rpc.registry.dsr.DsrSubscribeCallback - RPC-00204: Receive RPC service addresses: service[com.xxx.xxx.service.xxxService:1.0@DEFAULT]
  usable target addresses[3]

怀疑业务代码

基于上述的证据，我们有理由怀疑是业务代码自身的问题。我们要求客户检查业务代码。客户在业务代码中添加了很多日志，显式的打印业务处理和 RPC 调用时间，结果证明时间还是消失在调用 RPC 的过程中。以下是客户 SOFA RPC 调用的具体代码。

  GenericObject result = (GenericObject)serviceName.$genericInvoke(methodName, argTypes, args);

看到这个结果，我们百思不得其解：RPC 的超时时间是3s，但是实际上这次调用花了30s而没有超时（因为实际执行 RPC 的时间才54ms）。那么，时间到底去哪里了？

逆向推导

从结果来逆向推导，genericInvoke 应该包含了很多处理方法，而在调用真正的 RPC 方法之前肯定调用了其他处理方法做了其他事情，那么到底做了什么事情？假如你阅读代码的话，会发现你会被淹没在汪洋代码里面，我们需要其他更有效的方式排查此类问题。这30秒给人的感觉就是“卡”在了某个地方。这时候，我们需要想，在这种情况下，什么日志或者工具能帮助我们进一步逼近真相？这时候，jstack 登场了。jstack 可以帮助我们获得某一个时刻某个进程里面所有线程的调用堆栈。假如某个线程卡在什么方法上的话，通过多抓几次 jstack 的方式，我们能清楚的看到卡住的方法。所以我们让客户在重现问题的时候每隔5s收集一次 jstack $PID >stack.log，至少收集4个日志。$PID需要使用业务应用的 java 进程 ID 替换。皇天不负有心人，从这几个 jstack 日志中，我们通过 genericInvoke 快速定位到相应的线程，发现卡在了 OS的方法 getLocalHostName 上（几个 jstack 日志都卡在 getLocalHostName 上）。同时，从调用堆栈来看，线程当时是在初始化 RPC 的 tracer，也就是还没有开始 RPC 调用，所以不会有 RPC 调用超时发生。

"http-nio-8080-exec-10" #28 daemon prio=5 os_prio=0 tid=0x00007f54604e5000 nid=0x175c runnable [0x00007f53ef1f6000]
   java.lang.Thread.State: RUNNABLE
	at java.net.Inet4AddressImpl.getLocalHostName(Native Method)
	at java.net.InetAddress.getLocalHost(InetAddress.java:1475)
	at sun.management.VMManagementImpl.getVmId(VMManagementImpl.java:140)
	at sun.management.RuntimeImpl.getName(RuntimeImpl.java:59)
	at com.alipay.common.tracer.core.utils.TracerUtils.getPID(TracerUtils.java:139)
	at com.alipay.common.tracer.core.generator.TraceIdGenerator.getTraceId(TraceIdGenerator.java:49)
	at com.alipay.common.tracer.core.generator.TraceIdGenerator.generate(TraceIdGenerator.java:54)
	at com.alipay.common.tracer.core.SofaTracer$SofaTracerSpanBuilder.createRootSpanContext(SofaTracer.java:296)
	at com.alipay.common.tracer.core.SofaTracer$SofaTracerSpanBuilder.start(SofaTracer.java:285)
	at com.alipay.sofa.rpc.tracer.sofatracer.RpcSofaTracer.startRpc(RpcSofaTracer.java:143)
	at com.alipay.sofa.rpc.tracer.Tracers.startRpc(Tracers.java:102)
	at com.alipay.sofa.rpc.event.SofaTracerSubscriber.onEvent(SofaTracerSubscriber.java:35)
	at com.alipay.sofa.rpc.event.EventBus.handleEvent(EventBus.java:153)
	at com.alipay.sofa.rpc.event.EventBus.post(EventBus.java:123)
	at com.alipay.sofa.rpc.client.ClientProxyInvoker.invoke(ClientProxyInvoker.java:80)
	at com.alipay.sofa.rpc.api.GenericService_proxy_0.$genericInvoke(GenericService_proxy_0.java)
	at com.xxx.xxx.xxx.util.SofaUtil.invokeService(SofaUtil.java:32)
	at com.xxx.xxx.xxx.controller.xxxxxxxxController.xxxxxxxxController002(xxxxxxxxController.java:425)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)

那么这个 getLocalHostName 方法到底在干什么呢？通过网络搜索，发现这个函数其实就是去查找本机的HostName，IP。CentOS 查找的顺序是这样的：/etc/hosts 文件，DNS，myhostname（只返回本机配置的公共IP地址）。由于客户这边 DNS 配置错误，导致一直卡在该方法 DNS 超时，所以造成了该问题。同时，经过客户确认，这几台机器并不依赖DNS寻址。所以我们的解决方案很简单：在 /etc/hosts 中添加了 IP 与主机名的映射。