简介： 为什么 SOFA RPC 调用 30s 还不超时？
1. 背景
最近帮客户解决了一个诡异的 RPC 调用问题，想跟大家分享一下。对于 SOFA RPC，请参考官网 [1]。
2. 问题景象
客户应用 REST 接口触发 RPC 的调用，发现每次 RPC 调用都须要 30 秒的工夫，最终的 RPC 调用后果是胜利的。从业务日志来看，开始解决业务和完结业务之间的确花了 30 秒。
3. 问题剖析
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 秒到底产生了什么！
3.1 直击框架外围
咱们晓得 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]3.2 狐疑业务代码
基于上述的证据，咱们有理由狐疑是业务代码本身的问题。咱们要求客户查看业务代码。客户在业务代码中增加了很多日志，显式的打印业务解决和 RPC 调用工夫，后果证实工夫还是隐没在调用 RPC 的过程中。以下是客户 SOFA RPC 调用的具体代码。
GenericObject result = (GenericObject)serviceName.$genericInvoke(methodName, argTypes, args);看到这个后果，咱们百思不得其解：RPC 的超时工夫是 3s，然而实际上这次调用花了 30s 而没有超时（因为理论执行 RPC 的工夫才 54ms）。那么，工夫到底去哪里了？
3.3 逆向推导
从后果来逆向推导，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 与主机名的映射。
参考文档
[1]SOFA RPC：https://help.aliyun.com/document\_detail/149865.html?spm=a2c4g.11186623.6.560.178c5fb01GxG9Z
咱们是阿里云智能寰球技术服务 -SRE 团队，咱们致力成为一个以技术为根底、面向服务、保障业务零碎高可用的工程师团队；提供业余、体系化的 SRE 服务，帮忙广大客户更好地应用云、基于云构建更加稳固牢靠的业务零碎，晋升业务稳定性。咱们冀望可能分享更多帮忙企业客户上云、用好云，让客户云上业务运行更加稳固牢靠的技术，您可用钉钉扫描下方二维码，退出阿里云 SRE 技术学院钉钉圈子，和更多云上人交换对于云平台的那些事。
版权申明： 本文内容由阿里云实名注册用户自发奉献，版权归原作者所有，阿里云开发者社区不领有其著作权，亦不承当相应法律责任。具体规定请查看《阿里云开发者社区用户服务协定》和《阿里云开发者社区知识产权爱护指引》。如果您发现本社区中有涉嫌剽窃的内容，填写侵权投诉表单进行举报，一经查实，本社区将立即删除涉嫌侵权内容。