search

apache / dubbo

The java implementation of Apache Dubbo. An RPC and microservice framework.
https://dubbo.apache.org/
Apache License 2.0
40.5k stars 26.43k forks source link

Dubbo调用超时，服务端历史统计的处理耗时很短且找不到对应超时上下文的超时日志 #1784

Closed Jaskey closed 4 years ago

Jaskey commented 6 years ago

A调用服务B，超时时间1秒，从某些请求来看超时了两次，重试了两次，第三次成功了，耗时仅4ms。

客户端有类似日志：

2018-05-11 00:00:14.741 [T_Common_DispatchExecutor_43] WARN  com.alibaba.dubbo.rpc.cluster.support.FailoverClusterInvoker -  [DUBBO] Although retry the method push in the service com.oppo.push.open.basic.api.service.BroadcastService was successful by the provider 10.12.
26.124:9000, but there have been failed providers [10.12.26.137:9000] (1/6) from the registry 10.12.26.154:2181 on the consumer 10.12.26.102 using the dubbo version 2.5.3. Last error is: Invoke remote method timeout. method: push, provider: dubbo://10.12.26.137:9000/com
.oppo.push.open.basic.api.service.BroadcastService?accesslog=false&anyhost=true&application=push-open-platform-gateway-server&check=false&default.delay=-1&default.service.filter=-exception&default.timeout=1000&delay=-1&dubbo=2.5.3&interface=com.oppo.push.open.basic.api.
service.BroadcastService&loadbalance=random&logger=slf4j&methods=revokePushMessage,revokeSmsMessage,push&pid=31597&push.retries=2&revision=3.0.2-SNAPSHOT&side=consumer&timestamp=1525937532890&transporter=netty, cause: Waiting server-side response timeout by scan timer. 
start time: 2018-05-11 00:00:13.710, end time: 2018-05-11 00:00:14.738, client elapsed: 0 ms, server elapsed: 1028 ms, timeout: 1000 ms, request: Request [id=2395465, version=2.0.0, twoway=true, event=false, broken=false, data=RpcInvocation [methodName=push, parameterTy
pes=[class com.oppo.push.open.basic.api.domain.PushTask], arguments=[PushTask[taskId=5af46c8da609e97b6dc17380, messageId=5af4655dad99497f2345ccda, messageCategory=3, messageType=1, taskStatus=5, target=PushTarget{id='5af46c8da609e97b6dc17381', type=REGISTRATION_ID, valu
e='6187cd138ad2dbceee7f044c2409d4f1;ab5721987d21dcf5e863b58e165f144a;827f4ff3b5d31cce9e441b045eb985c9;e17854797bb4f0e7b14178cbde596c88;CN_647982d13860dde6876cdf0e37165c76;93624a57d555510bcf27cda47d5a06f9;eb3ebc3a53b12ef304de95b3e1852c60;5b752dc47cbca9721239885a062814c2;
c69bd502aee453f0b78517bc9cb4548d;cc35de8b5edbff28dbaf55e4f60ad20a;CN_1239d29db4f5db54cc1bef51df3f3acc;CN_f6fd0448d1c6281da6ffa50df4d26f38;CN_2c2dc12e3c567ad81a00ca9cdca564e3;CN_d92b53c07de3e70883552295ece900f1;CN_b1cedf2537fd52e91fa29b5fb3c4eb47;525fb9de1d18e21c15479a0a
7f59b163;CN_debc0d6366f27dea1a45862020687f1a;d5bbb9bae7102ad0d69b3aeb138c4ff4;aac05d1a20d073343917c68798f9be2f;817898207275b2dbeefb6e9398f06b50;203e1b8c0de742605ecb166b6a92d9ce;8c6a4f0925ba3a1d92e3640d00507ade;fc3e47ab8ca527d964fae84ab5db00d7;d9c2ecf8051093bf7eb7818bbe5
5ec8f;c7894071806e5a6540a5380b1763e91b;b56b7a3e247258034876b9a8522b0dab;8b17b0c449bffa08407a4401f33b988f;789ca011db0844d01932fb8da2553a03;735e6aae28a3f2d5752e65f277bea9c3;e2cfca07e576a0285ab8f50dbaa3a947;8428d377795b069d9dfe033e880ed627;0939eab473c0311b5dd5567f5d191487;
ec2ff892fbc28fdf0008d532a2c48560;e3df5c83de7f985e73d4e58d4d15225d;CN_c5af7007e71c23771b29eb0713cde7e2;ef91ece8b7e44a13fb31015f8f20b25b;CN_57b78f69e35ce1f8c1fcb27e36758fca;CN_d58cb83cdd32f108f84ff6eae662712f;CN_5564f22ea67f3391fc0f37b23d68ade0;e2b842e3aea81c7e7784fae318e
bfb8a;2315554dca29eac7100d823f262c2b6f;18c0676bc2300630bad171d72353de0b;116c0728d4d8bed6aa80ba78a77620c1;11c37c408a7c88cf80e7bca695228c05;643413c1adad5e72df94594017797078;CN_c8dedeeeacdc24e9194386929e5367a7;CN_77a3fc33b094c592bad79d1aa95761af;4b9ceaaac2fbca88c01c3976c4a
c7849;0a1c506ef41acca7bf4c01a758ece6cb;66c0c30821c399e06bb63cfd630b2016;2a5efb3ee633035f5d3700dc744b97d2;07348c108d514773761a828499877ce4;4532d9d99307e6b3634fdfc06aecbb09;6aae440b59761d2ed4e425206f276dc7', effectiveValue='null', unsubscribeValue='null', deviceId='null'}
, appId=nJNKY574F2C4TWrAqYobsa3X, creator=null, messageTitle=null, createTime=Fri May 11 00:00:13 CST 2018, updateTime=Fri May 11 00:00:13 CST 2018], finishTime=null], extFields={}]], attachments={path=com.oppo.push.open.basic.api.service.BroadcastService, interface=com
.oppo.push.open.basic.api.service.BroadcastService, timeout=1000, version=0.0.0}]], channel: /10.12.26.102:49081 -> /10.12.26.137:9000, dubbo version: 2.5.3, current host: 10.12.26.102
com.alibaba.dubbo.rpc.RpcException: Invoke remote method timeout. method: push, provider: dubbo://10.12.26.137:9000/com.oppo.push.open.basic.api.service.BroadcastService?accesslog=false&anyhost=true&application=push-open-platform-gateway-server&check=false&default.delay
=-1&default.service.filter=-exception&default.timeout=1000&delay=-1&dubbo=2.5.3&interface=com.oppo.push.open.basic.api.service.BroadcastService&loadbalance=random&logger=slf4j&methods=revokePushMessage,revokeSmsMessage,push&pid=31597&push.retries=2&revision=3.0.2-SNAPSH
OT&side=consumer&timestamp=1525937532890&transporter=netty, cause: Waiting server-side response timeout by scan timer. start time: 2018-05-11 00:00:13.710, end time: 2018-05-11 00:00:14.738, client elapsed: 0 ms, server elapsed: 1028 ms, timeout: 1000 ms, request: Reque
st [id=2395465, version=2.0.0, twoway=true, event=false, broken=false, data=RpcInvocation [methodName=push, parameterTypes=[class com.oppo.push.open.basic.api.domain.PushTask], arguments=[PushTask[taskId=5af46c8da609e97b6dc17380, messageId=5af4655dad99497f2345ccda, mess
ageCategory=3, messageType=1, taskStatus=5, target=PushTarget{id='5af46c8da609e97b6dc17381', type=REGISTRATION_ID, value='6187cd138ad2dbceee7f044c2409d4f1;ab5721987d21dcf5e863b58e165f144a;827f4ff3b5d31cce9e441b045eb985c9;e17854797bb4f0e7b14178cbde596c88;CN_647982d13860d
de6876cdf0e37165c76;93624a57d555510bcf27cda47d5a06f9;eb3ebc3a53b12ef304de95b3e1852c60;5b752dc47cbca9721239885a062814c2;c69bd502aee453f0b78517bc9cb4548d;cc35de8b5edbff28dbaf55e4f60ad20a;CN_1239d29db4f5db54cc1bef51df3f3acc;CN_f6fd0448d1c6281da6ffa50df4d26f38;CN_2c2dc12e3c
567ad81a00ca9cdca564e3;CN_d92b53c07de3e70883552295ece900f1;CN_b1cedf2537fd52e91fa29b5fb3c4eb47;525fb9de1d18e21c15479a0a7f59b163;CN_debc0d6366f27dea1a45862020687f1a;d5bbb9bae7102ad0d69b3aeb138c4ff4;aac05d1a20d073343917c68798f9be2f;817898207275b2dbeefb6e9398f06b50;203e1b8
c0de742605ecb166b6a92d9ce;8c6a4f0925ba3a1d92e3640d00507ade;fc3e47ab8ca527d964fae84ab5db00d7;d9c2ecf8051093bf7eb7818bbe55ec8f;c7894071806e5a6540a5380b1763e91b;b56b7a3e247258034876b9a8522b0dab;8b17b0c449bffa08407a4401f33b988f;789ca011db0844d01932fb8da2553a03;735e6aae28a3f
2d5752e65f277bea9c3;e2cfca07e576a0285ab8f50dbaa3a947;8428d377795b069d9dfe033e880ed627;0939eab473c0311b5dd5567f5d191487;ec2ff892fbc28fdf0008d532a2c48560;e3df5c83de7f985e73d4e58d4d15225d;CN_c5af7007e71c23771b29eb0713cde7e2;ef91ece8b7e44a13fb31015f8f20b25b;CN_57b78f69e35ce
1f8c1fcb27e36758fca;CN_d58cb83cdd32f108f84ff6eae662712f;CN_5564f22ea67f3391fc0f37b23d68ade0;e2b842e3aea81c7e7784fae318ebfb8a;2315554dca29eac7100d823f262c2b6f;18c0676bc2300630bad171d72353de0b;116c0728d4d8bed6aa80ba78a77620c1;11c37c408a7c88cf80e7bca695228c05;643413c1adad5
e72df94594017797078;CN_c8dedeeeacdc24e9194386929e5367a7;CN_77a3fc33b094c592bad79d1aa95761af;4b9ceaaac2fbca88c01c3976c4ac7849;0a1c506ef41acca7bf4c01a758ece6cb;66c0c30821c399e06bb63cfd630b2016;2a5efb3ee633035f5d3700dc744b97d2;07348c108d514773761a828499877ce4;4532d9d99307e
6b3634fdfc06aecbb09;6aae440b59761d2ed4e425206f276dc7', effectiveValue='null', unsubscribeValue='null', deviceId='null'}, appId=nJNKY574F2C4TWrAqYobsa3X, creator=null, messageTitle=null, createTime=Fri May 11 00:00:13 CST 2018, updateTime=Fri May 11 00:00:13 CST 2018], f
inishTime=null], extFields={}]], attachments={path=com.oppo.push.open.basic.api.service.BroadcastService, interface=com.oppo.push.open.basic.api.service.BroadcastService, timeout=1000, version=0.0.0}]], channel: /10.12.26.102:49081 -> /10.12.26.137:9000
        at com.alibaba.dubbo.rpc.protocol.dubbo.DubboInvoker.doInvoke(DubboInvoker.java:99)
        at com.alibaba.dubbo.rpc.protocol.AbstractInvoker.invoke(AbstractInvoker.java:144)
        at com.alibaba.dubbo.rpc.listener.ListenerInvokerWrapper.invoke(ListenerInvokerWrapper.java:74)
        at com.alibaba.dubbo.rpc.protocol.dubbo.filter.FutureFilter.invoke(FutureFilter.java:53)
        at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
        at com.alibaba.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java:75)
        at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
        at com.oppo.trace.dubbo.DubboConsumerTraceFilter.invoke(DubboConsumerTraceFilter.java:37)
        at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
        at com.alibaba.dubbo.rpc.filter.ConsumerContextFilter.invoke(ConsumerContextFilter.java:48)
        at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:91)
        at com.alibaba.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:53)
        at com.alibaba.dubbo.rpc.cluster.support.FailoverClusterInvoker.doInvoke(FailoverClusterInvoker.java:77)
        at com.alibaba.dubbo.rpc.cluster.support.AbstractClusterInvoker.invoke(AbstractClusterInvoker.java:227)
        at com.alibaba.dubbo.rpc.cluster.support.wrapper.MockClusterInvoker.invoke(MockClusterInvoker.java:72)
        at com.alibaba.dubbo.rpc.proxy.InvokerInvocationHandler.invoke(InvokerInvocationHandler.java:52)
        at com.alibaba.dubbo.common.bytecode.proxy0.push(proxy0.java)
        at com.oppo.push.open.platform.gateway.action.notification.NotificationBroadcastAction.doExecute(NotificationBroadcastAction.java:105)
        at com.oppo.push.open.platform.gateway.action.AbstractAction.execute(AbstractAction.java:51)
        at com.oppo.push.httpframework.Action.ActionCallable$1.exec(ActionCallable.java:39)
        at com.oppo.push.httpframework.Action.ActionCallable$1.exec(ActionCallable.java:36)
        at com.oppo.push.httpframework.common.TraceTemplate.rootExec(TraceTemplate.java:24)
        at com.oppo.push.httpframework.Action.ActionCallable.run(ActionCallable.java:36)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask.run(FutureTask.java:262)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
Caused by: com.alibaba.dubbo.remoting.TimeoutException: Waiting server-side response timeout by scan timer. start time: 2018-05-11 00:00:13.710, end time: 2018-05-11 00:00:14.738, client elapsed: 0 ms, server elapsed: 1028 ms, timeout: 1000 ms, request: Request [id=2395
465, version=2.0.0, twoway=true, event=false, broken=false, data=RpcInvocation [methodName=push, parameterTypes=[class com.oppo.push.open.basic.api.domain.PushTask], arguments=[PushTask[taskId=5af46c8da609e97b6dc17380, messageId=5af4655dad99497f2345ccda, messageCategory
=3, messageType=1, taskStatus=5, target=PushTarget{id='5af46c8da609e97b6dc17381', type=REGISTRATION_ID, value='6187cd138ad2dbceee7f044c2409d4f1;ab5721987d21dcf5e863b58e165f144a;827f4ff3b5d31cce9e441b045eb985c9;e17854797bb4f0e7b14178cbde596c88;CN_647982d13860dde6876cdf0e
37165c76;93624a57d555510bcf27cda47d5a06f9;eb3ebc3a53b12ef304de95b3e1852c60;5b752dc47cbca9721239885a062814c2;c69bd502aee453f0b78517bc9cb4548d;cc35de8b5edbff28dbaf55e4f60ad20a;CN_1239d29db4f5db54cc1bef51df3f3acc;CN_f6fd0448d1c6281da6ffa50df4d26f38;CN_2c2dc12e3c567ad81a00c
a9cdca564e3;CN_d92b53c07de3e70883552295ece900f1;CN_b1cedf2537fd52e91fa29b5fb3c4eb47;525fb9de1d18e21c15479a0a7f59b163;CN_debc0d6366f27dea1a45862020687f1a;d5bbb9bae7102ad0d69b3aeb138c4ff4;aac05d1a20d073343917c68798f9be2f;817898207275b2dbeefb6e9398f06b50;203e1b8c0de742605e
cb166b6a92d9ce;8c6a4f0925ba3a1d92e3640d00507ade;fc3e47ab8ca527d964fae84ab5db00d7;d9c2ecf8051093bf7eb7818bbe55ec8f;c7894071806e5a6540a5380b1763e91b;b56b7a3e247258034876b9a8522b0dab;8b17b0c449bffa08407a4401f33b988f;789ca011db0844d01932fb8da2553a03;735e6aae28a3f2d5752e65f2
77bea9c3;e2cfca07e576a0285ab8f50dbaa3a947;8428d377795b069d9dfe033e880ed627;0939eab473c0311b5dd5567f5d191487;ec2ff892fbc28fdf0008d532a2c48560;e3df5c83de7f985e73d4e58d4d15225d;CN_c5af7007e71c23771b29eb0713cde7e2;ef91ece8b7e44a13fb31015f8f20b25b;CN_57b78f69e35ce1f8c1fcb27e
36758fca;CN_d58cb83cdd32f108f84ff6eae662712f;CN_5564f22ea67f3391fc0f37b23d68ade0;e2b842e3aea81c7e7784fae318ebfb8a;2315554dca29eac7100d823f262c2b6f;18c0676bc2300630bad171d72353de0b;116c0728d4d8bed6aa80ba78a77620c1;11c37c408a7c88cf80e7bca695228c05;643413c1adad5e72df945940
17797078;CN_c8dedeeeacdc24e9194386929e5367a7;CN_77a3fc33b094c592bad79d1aa95761af;4b9ceaaac2fbca88c01c3976c4ac7849;0a1c506ef41acca7bf4c01a758ece6cb;66c0c30821c399e06bb63cfd630b2016;2a5efb3ee633035f5d3700dc744b97d2;07348c108d514773761a828499877ce4;4532d9d99307e6b3634fdfc0
6aecbb09;6aae440b59761d2ed4e425206f276dc7', effectiveValue='null', unsubscribeValue='null', deviceId='null'}, appId=nJNKY574F2C4TWrAqYobsa3X, creator=null, messageTitle=null, createTime=Fri May 11 00:00:13 CST 2018, updateTime=Fri May 11 00:00:13 CST 2018], finishTime=n
ull], extFields={}]], attachments={path=com.oppo.push.open.basic.api.service.BroadcastService, interface=com.oppo.push.open.basic.api.service.BroadcastService, timeout=1000, version=0.0.0}]], channel: /10.12.26.102:49081 -> /10.12.26.137:9000
        at com.alibaba.dubbo.remoting.exchange.support.DefaultFuture.returnFromResponse(DefaultFuture.java:188)
        at com.alibaba.dubbo.remoting.exchange.support.DefaultFuture.get(DefaultFuture.java:110)
        at com.alibaba.dubbo.remoting.exchange.support.DefaultFuture.get(DefaultFuture.java:84)
        at com.alibaba.dubbo.rpc.protocol.dubbo.DubboInvoker.doInvoke(DubboInvoker.java:96)
        ... 27 common frames omitted

有以下两个奇怪的地方：

  1. 从报超时的服务端上看，找不到对应的超时的warn日志
  2. 从我们内部服务端统计的耗时来看，此接口从来没有大于100ms的。

以下是我的分析：

猜测和dubbo 服务端进入业务线程前的排队有关，但是我们没有设置queue的长度，所以默认应该是不排队的，线程池耗尽应该抛出的异常不是timeout。

即使排队了，但是服务端没有找到此上下文的超时日志，感觉像完全没有收到此请求？

会不会是直接网络上丢了包？如果网络上传输就失败了，异常会是超时么？此请求是一个对象，转换为JSON后有几K。

求解答

bert82503 commented 3 years ago

这个问题有解决方案了吗,我们在最近使用的过程中也遇到了 客户端调用超时,服务端完全正常,偶现. 大概率不是网络问题,我们对客户端压测,停止后 服务端服务正常, 客户端调用一直超时,然后过来几个小时之后就自动恢复了.现在每天会爆几千个这样的异常,概率不大.

最好结合分布式链路追踪，或通过Arthas看服务端处理耗时占比最大在哪个阶段，或者看下服务端有没对应时间的异常日志

bert82503 commented 3 years ago

我们也遇到过，这种奇怪的现象曾经也怀疑过各种 IO情况，但最后定位是线程池不足，请求压根无法进入dubbo线程池，dubbo框架也没有打印异常，当然请求入参出参也没打印，客户的表现就是超时。

“最后定位是线程池不足”，这个是否是在服务端的日志中发现了Thread pool is EXHAUSTED! 故障呢？

“Thread pool is EXHAUSTED!”日志我们遇到大部分都是出现在提供者端，消费者端也遇到过一两次。当dubbo工作者的线程池满了时，有定时检测任务会默认每隔十分钟输出JStack.log文件

bert82503 commented 3 years ago

我想问一下有没有人解决？我们生产也是偶尔的超时，链路监控没有上，希望有碰到过然后解决的出来解答一下。我们线上dubbo线程池满的报错会有，不是因为线程池满报的这个超时

这个需要具体问题具体分析，是否有当时对应的异常日志或通过Arthas追踪 下面是我在前东家负责dubbo时排查的dubbo问题整理，抛砖引玉 https://github.com/edwardlee03/issue-case/tree/master/dubbo

bert82503 commented 3 years ago

我想问一下有没有人解决？我们生产也是偶尔的超时，链路监控没有上，希望有碰到过然后解决的出来解答一下。我们线上dubbo线程池满的报错会有，不是因为线程池满报的这个超时

个别应用，还是所有应用都存在这个问题？若个别应用的话，看看当时有没异常日志，能否找些一些破案的线索

bert82503 commented 3 years ago

线上的问题已经定位到是因为5分钟执行一次的定时任务操作大对象，导致过一段时间那个服务节点要执行GC。这个时候请求过来只能等GC结束导致dubbo请求超时。

赞👍。大对象应该触发Full GC引起应用停顿(STW)，这个case是提供者端应用超时了。通过时间线结合系统监控指标综合怀疑分析

shuohao commented 2 years ago

除了网络问题，还可能有其他原因么，我司也出现了这种短时抖动，服务端完全是没有延迟的报错

可能的原因： 1.请求阻塞在工作者队列里排队，消耗了大部分时间； 2.API.jar升级引起类不兼容加载不到，频繁加载某一个类会引起阻塞，可以看下ClassLoader源码。dubbo新版本已修复这个问题。 3.较长时间的GC停顿

"请求阻塞在工作者队列里排队，消耗了大部分时间 " 这个通过什么来证明呢? 我们服务也遇到这问题，我猜测就是排队了 我想扩容你能解决 但是没有找到证据

hexufeng commented 2 years ago

所以，这个问题最终没有答案，还被close掉了？

kimmking commented 2 years ago

总结一下，如果出现消费端超时，但是服务端处理时间短，那么有这么几种可能： 1）网络问题：tcpddump/wireshark抓包去判断。 2）dubbo线程池满导致排队：监控两头的线程池状态，以及全链路信息，链路可以拼出来。 3）JVM停顿问题：包括GC的停顿和其他safepoint停顿，特别是后面这个STW停顿，很多人不知道，建议都打印出来。 4）统计不准：服务端有时候我们觉得很快，实际上也慢，只是日志或者其他监控信息不全。

Jaskey commented 2 years ago

总结一下，如果出现消费端超时，但是服务端处理时间短，那么有这么几种可能： 1）网络问题：tcpddump/wireshark抓包去判断。 2）dubbo线程池满导致排队：监控两头的线程池状态，以及全链路信息，链路可以拼出来。 3）JVM停顿问题：包括GC的停顿和其他safepoint停顿，特别是后面这个STW停顿，很多人不知道，建议都打印出来。 4）统计不准：服务端有时候我们觉得很快，实际上也慢，只是日志或者其他监控信息不全。

第一点是很玄学的地方，因为其他服务同样的网络通常没问题， 第二点应该大部分都不存在，因为dubbo默认线程池默认是没有队列的，核数一满就直接爆了。

zibuyu0528 commented 2 years ago

碰到一样的问题了，请问下后来解决了吗

lijiajia02 commented 2 years ago

也遇到类似情况，哪位大神给出最终的解决方案，我们大多超时存在: client elapsed: 310 ms

lijiajia02 commented 2 years ago

也遇到类似情况，哪位大神给出最终的解决方案，我们大多超时存在: client elapsed: 310 ms

我们用的dubbo接口异步调用，改为同步调用后，无超时现象

kimmking commented 1 year ago

总结一下，如果出现消费端超时，但是服务端处理时间短，那么有这么几种可能： 1）网络问题：tcpddump/wireshark抓包去判断。 2）dubbo线程池满导致排队：监控两头的线程池状态，以及全链路信息，链路可以拼出来。 3）JVM停顿问题：包括GC的停顿和其他safepoint停顿，特别是后面这个STW停顿，很多人不知道，建议都打印出来。 4）统计不准：服务端有时候我们觉得很快，实际上也慢，只是日志或者其他监控信息不全。

目前来看，在虚拟机或容器，问题3的因素非常大。 比如GC就是一类safepoint。 JVM内部存在大量的safepoint，都会造成JVM的STW暂停。 绝大部分时间，这个暂停都很快，但是就是有少量的几种情况下，会很慢。 此时如果不调整GClog配置，我们从各类监控和日志，是根本发现不了这个事儿的。

Melody12ab commented 1 year ago

请教，这个问题有体系的排查思路或解决方案吗

kimmking commented 1 year ago

请检查gc或safepoint暂停。

Bigface Monster @.***> 于2023年2月10日周五 16:59写道：

请教，这个问题有体系的排查思路或解决方案吗

— Reply to this email directly, view it on GitHub https://github.com/apache/dubbo/issues/1784#issuecomment-1425444758, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAGFEVBTBUGO4YRPTUPWKELWWX7NXANCNFSM4E7NTLBA . You are receiving this because you were mentioned.Message ID: @.***>

hexufeng commented 1 year ago

所以，这个问题最终没有答案，还被close掉了？

我最终解决了我们遇到的问题，下面分享下我们遇到的现象和解决过程

现象：每次服务发布后dubbo provider 会在发布后的十几分钟内不再响应，consumer端异常显示provider端的dubbo线程池被打满，类似这样的错误信息

Thread pool is EXHAUSTED! ...

但我们监控平台在服务provider侧监控不到任何有用的信息，GC等其他一切正常、dubbo服务方法rt也最多几百ms、连错误信息都没有，但consumer端监控到了错误信息和一些超时信息。通过对provider端线程池的监控发现DubboServerHandler线程池的数量从发布后到无响应线程数一直增加，直到满为止，时间吻合。

于是，我们判定每次发布后无响应，客户端同时也会有一些报超时的错误 的现象，是由于provider端的线程池被打满导致的。

排查：通过配置增大provider端线程池，无用。从AbortPolicyWithReport类（DubboServerHandler线程池的拒绝策略实现）中发现，线程池满后dubbo会调用一个方法

dumpJStack();

查看该方法内部发现确实dump了堆栈信息，于是我们从服务器上找到了该日志文件，下载后通过jstack分析，发现线程池打满时刻，DubboServerHandler线程池中的所有线程均RUNNING状态，表明未发生死锁，排查发现有非常多的同一个接口调用，于是问题明了了： 该接口对应的底层数据库查询数据量太大，查询很慢，当发布的时候用户着急重复刷新页面提交该查询请求，导致不断积累又不返回，线程池很快被占满。

最后的疑问： 为何发布后发布的机器会被打满而未发布的其他机器却没事？按理说负载均衡后请求路由会均分到所有可用的机器上，但我们遇到的现象是被发布的机器偶发这种现象，集群里未被发布的机器却没事。

AlbumenJ commented 1 year ago

为何发布后发布的机器会被打满而未发布的其他机器却没事？按理说负载均衡后请求路由会均分到所有可用的机器上，但我们遇到的现象是被发布的机器偶发这种现象，集群里未被发布的机器却没事。

这个需要检查你的业务逻辑，通常是有缓存需要重新加载或者是 JVM C2 编译

tnessn commented 1 year ago

我最近也遇到这个问题 通过arms监控服务端接口最大耗时也就300多ms 客户端配置的是3s超时 有以下两种情况： 1.开启arms监控客户端就会不间断的报超时，所以平时不开监控 2.不开arms监控的情况下 出现的概率比较低 也会偶尔出现一下

bert82503 commented 12 months ago

除了网络问题，还可能有其他原因么，我司也出现了这种短时抖动，服务端完全是没有延迟的报错

可能的原因： 1.请求阻塞在工作者队列里排队，消耗了大部分时间； 2.API.jar升级引起类不兼容加载不到，频繁加载某一个类会引起阻塞，可以看下ClassLoader源码。dubbo新版本已修复这个问题。 3.较长时间的GC停顿

"请求阻塞在工作者队列里排队，消耗了大部分时间 " 这个通过什么来证明呢? 我们服务也遇到这问题，我猜测就是排队了 我想扩容你能解决 但是没有找到证据

对线程池进行监控，透出线程池的状态指标(线程各状态的数据，队列的数据) @shuohao

fffscd commented 9 months ago

补充一个问题点，最近发现整体响应耗时耗费在序列化上，利用arthas监控可以发现：

trace com.alibaba.com.caucho.hessian.io.Deserializer readObject -n 5 --skipJDKMethod false

这里耗时很久，然后整体升级dubbo到2.6.2解决

auroraslot commented 6 months ago

我这边大概率是和GC相关，场景也是容器启动后不久访问出现这个问题

bert82503 commented 6 months ago

补充一个问题点，最近发现整体响应耗时耗费在序列化上，利用arthas监控可以发现：

trace com.alibaba.com.caucho.hessian.io.Deserializer readObject -n 5 --skipJDKMethod false

这里耗时很久，然后整体升级dubbo到2.6.2解决

响应数据大小是多少？有循环引用么？

fffscd commented 6 months ago

补充一个问题点，最近发现整体响应耗时耗费在序列化上，利用arthas监控可以发现：

trace com.alibaba.com.caucho.hessian.io.Deserializer readObject -n 5 --skipJDKMethod false

这里耗时很久，然后整体升级dubbo到2.6.2解决

响应数据大小是多少？有循环引用么？

没有，就是客户端是 2.5.X 然后提供者是2.6.X 2边版本不一致导致的

chency147 commented 2 weeks ago

我这边也遇到类似的问题，使用的版本 2.7.12（consumer和provider都是此版本）。 问题表现为 provider 侧的日志和指标显示请求处理都正常，但是consumer侧报请求超时，触发重试。

报错的堆栈关键词如下。

org.apache.dubbo.rpc.RpcException: Invoke remote method timeout. method: XXXXX, provider: dubbo://打码打码打码:20880/XXXXXX
....
at org.apache.dubbo.rpc.protocol.AsyncToSyncInvoker.invoke(AsyncToSyncInvoker.java:70)
at org.apache.dubbo.rpc.listener.ListenerInvokerWrapper.invoke(ListenerInvokerWrapper.java:78)
at com.alibaba.dubbo.rpc.Invoker$CompatibleInvoker.invoke(Invoker.java:55)
....

经过排查，发现是版本 [2.7.7, 2.7.15] 区间的 bug 造成的。 这些 dubbo 版本会在 Provider 侧的 IO 线程中使用到 Hessian2ObjectOutput，Hessian2ObjectOutput 对象会包含一个 Hessian2Output 对象并且使用 ThreadLocal 进行缓存，Hessian2Output 又会维护一个 IdentifyIntMap，每次复用到 Hessian2Output 对象时，会对这个 IdentifyIntMap 进行遍历操作。 见：https://github.com/apache/dubbo-hessian-lite/blob/master/hessian-lite/src/main/java/com/alibaba/com/caucho/hessian/io/Hessian2Output.java 的 init 方法，最终会调用到 IdentifyIntMap 的 clear() 方法。 image 记住这个 for 循环。

这个 IdentifyIntMap 是 Hessian2 序列化时辅助计算（大概是此作用）的，当序列化的内容较大（尤其是嵌套比较深的时候），这个 IdentifyIntMap 会进行扩容，扩容规则是 当前总容量的 1/4，小于等于使用量时，扩容为当前总容量的 4倍 。 见：https://github.com/apache/dubbo-hessian-lite/blob/master/hessian-lite/src/main/java/com/alibaba/com/caucho/hessian/util/IdentityIntMap.java put方法 image

map的容量会不断撑大，每次使用又会遍历它重置，它又是运行在 netty 的 io 线程上，所以一旦map的容量超过某个阈值时，io线程就会拥塞，如下所示。 image 注意：程序里运行的Hession2类库版本和上述截图不一致，所以行数有偏差，但是逻辑是一样的，都是卡在for循环遍历。

heap dump 结果，发现这个 map 的元素已经被撑大到 400w+ 。 image

等于是出现故障时 IO线程 已经水泄不通了。 排查同期的 provider 侧 内存占用，开始故障后老年代持续增长，说明响应淤积住了。

问题解决：provider侧升级到 2.7.16 即以上版本就能修复这个问题，此版本开始移除了对 Hessian2ObjectOutput 对象的线程级缓存。

5889 引入

10231 修复

遗留问题：为什么 provider 侧的指标都正常？ 根据官方的线程模型示意图：https://cn.dubbo.apache.org/en/docs3-v2/java-sdk/advanced-features-and-usage/performance/threading-model/provider/ image

dubbo 线程处理好业务之后，是将 response 对象丢给 IO线程处理，IO线程处理 serialize 过程（即序列化，本次的故障点），业务逻辑处理和 IO输出异步化了。所以我们基于 dubbo 线程的 filter 的指标采集，以及在 dubbo 线程中所做的日志打印，完全感知不到异常。

ririliu commented 3 days ago

我这边也遇到类似的问题，使用的版本 2.7.12（consumer和provider都是此版本）。 问题表现为 provider 侧的日志和指标显示请求处理都正常，但是consumer侧报请求超时，触发重试。

报错的堆栈关键词如下。

org.apache.dubbo.rpc.RpcException: Invoke remote method timeout. method: XXXXX, provider: dubbo://打码打码打码:20880/XXXXXX
....
at org.apache.dubbo.rpc.protocol.AsyncToSyncInvoker.invoke(AsyncToSyncInvoker.java:70)
at org.apache.dubbo.rpc.listener.ListenerInvokerWrapper.invoke(ListenerInvokerWrapper.java:78)
at com.alibaba.dubbo.rpc.Invoker$CompatibleInvoker.invoke(Invoker.java:55)
....

经过排查，发现是版本 [2.7.7, 2.7.15] 区间的 bug 造成的。 这些 dubbo 版本会在 Provider 侧的 IO 线程中使用到 Hessian2ObjectOutput，Hessian2ObjectOutput 对象会包含一个 Hessian2Output 对象并且使用 ThreadLocal 进行缓存，Hessian2Output 又会维护一个 IdentifyIntMap，每次复用到 Hessian2Output 对象时，会对这个 IdentifyIntMap 进行遍历操作。 见：https://github.com/apache/dubbo-hessian-lite/blob/master/hessian-lite/src/main/java/com/alibaba/com/caucho/hessian/io/Hessian2Output.java 的 init 方法，最终会调用到 IdentifyIntMap 的 clear() 方法。 image 记住这个 for 循环。

这个 IdentifyIntMap 是 Hessian2 序列化时辅助计算（大概是此作用）的，当序列化的内容较大（尤其是嵌套比较深的时候），这个 IdentifyIntMap 会进行扩容，扩容规则是 当前总容量的 1/4，小于等于使用量时，扩容为当前总容量的 4倍 。 见：https://github.com/apache/dubbo-hessian-lite/blob/master/hessian-lite/src/main/java/com/alibaba/com/caucho/hessian/util/IdentityIntMap.java put方法 image

map的容量会不断撑大，每次使用又会遍历它重置，它又是运行在 netty 的 io 线程上，所以一旦map的容量超过某个阈值时，io线程就会拥塞，如下所示。 image 注意：程序里运行的Hession2类库版本和上述截图不一致，所以行数有偏差，但是逻辑是一样的，都是卡在for循环遍历。

heap dump 结果，发现这个 map 的元素已经被撑大到 400w+ 。 image

等于是出现故障时 IO线程 已经水泄不通了。 排查同期的 provider 侧 内存占用，开始故障后老年代持续增长，说明响应淤积住了。

问题解决：provider侧升级到 2.7.16 即以上版本就能修复这个问题，此版本开始移除了对 Hessian2ObjectOutput 对象的线程级缓存。

5889 引入 #10231 修复

遗留问题：为什么 provider 侧的指标都正常？ 根据官方的线程模型示意图：https://cn.dubbo.apache.org/en/docs3-v2/java-sdk/advanced-features-and-usage/performance/threading-model/provider/ image

dubbo 线程处理好业务之后，是将 response 对象丢给 IO线程处理，IO线程处理 serialize 过程（即序列化，本次的故障点），业务逻辑处理和 IO输出异步化了。所以我们基于 dubbo 线程的 filter 的指标采集，以及在 dubbo 线程中所做的日志打印，完全感知不到异常。

感谢大佬的这篇回复，搜关键字进来发现是一模一样的问题，省了N个小时的排查，分析的也相当完整，一般真的不太会想到是io线程的一些动作引起的

bert82503 commented 2 days ago

感谢大佬的这篇回复，搜关键字进来发现是一模一样的问题，省了N个小时的排查，分析的也相当完整，一般真的不太会想到是io线程的一些动作引起的

我们已经使用dubbo-3.2.16，在尝试dubbo-3.3.1的虚拟线程，包括JDK-21的ZGC。😄