gRPC11# 超时问题定位

开发 后端
在发布卡点过程中,有同学反馈在发布过程中存在偶发性超时情况。集中在上下游服务较多节点的服务,几十个上百个节点的服务较多。不是必然出现,一批服务偶尔有一个节点出现。

[[434974]]

一、超时现象反馈

在发布卡点过程中,有同学反馈在发布过程中存在偶发性超时情况。集中在上下游服务较多节点的服务,几十个上百个节点的服务较多。不是必然出现,一批服务偶尔有一个节点出现。刚出现的前几例由于没有触发线程dump一直定位不到哪里的问题。

RPC框架中服务端线程池默认使用线程超过80%会触发线程dump,方便观察运行状态。直到有两个服务触发了dump才把这个谜底揭开。

二、超时现象跟踪

链路日志: 客户端AppXXXService调用服务Appxxx发生超时,长达50秒。

服务消费方报错信息:

客户端等待中取消请求,发生调用时间为:2021-11-02 22:11:59.148

耗时监控曲线:该服务基本上在同一时间段发起向下游的服务均发生超时。

服务端队列监控:队列显示瞬间增加很多任务

磁盘IO和CPU都有上升

线程dump情况,通信线程调用到了SynchronizationContext,底层的work通信线程怎么调用到了获取节点的业务方法去了。

三、问题根因

RPC框架中代码中有使用SynchronizationContext,此处与gRPC共用。

SynchronizationContext使用的queue是ConcurrentLinkedQueue队列,被单线程串行执行。

问题原因:再回到上面的线程栈,业务节点发现事件和gRPC底层通信共用了SynchronizationContext造成阻塞,和线程错乱执行。

 

问题解决:不再和gRPC共用SynchronizationContext,如果使用单独实例化一个即可。该问题通过测试同学通过故障注入的方式得以复现。

 

责任编辑:武晓燕 来源: 瓜农老梁
相关推荐

2023-10-16 23:06:26

2022-09-20 10:41:32

接口优化网络

2023-03-01 10:42:58

gRPC服务端设置

2014-03-18 13:27:55

Redis数据存储

2010-11-25 11:15:11

MySQL查询超时

2010-10-14 09:15:20

MySQL查询

2021-07-14 18:21:38

负载均衡K8SgRPC

2010-01-05 09:36:40

ADO超时

2020-04-23 11:43:55

MySQL数据库SQL

2021-06-04 06:20:47

systemd定位工具系统运维

2009-03-24 10:45:39

MySQL5连接超时数据库

2023-07-17 18:42:47

gRPCDemo项目

2018-03-01 08:56:20

存储能力定位

2019-11-05 08:24:34

JavaOOM快速定位

2017-09-10 17:00:42

服务器数据包丢弃

2013-11-04 11:42:26

Windows 8.1Bing

2022-12-07 10:56:23

线程池监控执行超时

2017-08-08 15:05:55

工具定位数据库

2023-01-03 10:30:00

Java工具

2022-02-20 21:35:43

MySQLDDL阻塞
点赞
收藏

51CTO技术栈公众号