簡介：為什么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: RUNNABLEat 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技術學院釘釘圈子，和更多云上人交流關于云平臺的那些事。

原文鏈接：https://developer.aliyun.com/article/783846?

版權聲明：本文內容由阿里云實名注冊用戶自發貢獻，版權歸原作者所有，阿里云開發者社區不擁有其著作權，亦不承擔相應法律責任。具體規則請查看《阿里云開發者社區用戶服務協議》和《阿里云開發者社區知識產權保護指引》。如果您發現本社區中有涉嫌抄襲的內容，填寫侵權投訴表單進行舉報，一經查實，本社區將立刻刪除涉嫌侵權內容。 與50位技術專家面對面20年技術見證，附贈技術全景圖

總結

以上是生活随笔為你收集整理的为什么SOFA RPC调用30s还不超时？的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。