转载:https://blog.csdn.net/wsmalltiger/article/details/124236055
前言
我们一个核心应用,线上部署了4台机器(4c8g),某天晚上8点左右线上忽然出现dubbo线程池占满告警,上游应用error日志也疯狂报警,整个过程持续了4分钟左右系统自动恢复正常。
dubbo 默认200个线程池,报错日志信息:
03-26 20:22:32.740 ERROR 25110 --- [ThreadPoolMonitor-thread-1] c.*.*.c.scheduled.ScheduledContainer : [DUBBO] Pool status:OK, max:200, core:200, largest:200, active:0, task:260504, service port: 20881;Pool status:WARN, max:200, core:200, largest:200, active:200, task:5568440, service port: 20882, dubbo version: 3.2.3.8-RELEASE, current host: 10.*.*.7
03-26 20:23:32.740 ERROR 25110 --- [ThreadPoolMonitor-thread-1] c.*.*.c.scheduled.ScheduledContainer : [DUBBO] Pool status:OK, max:200, core:200, largest:200, active:0, task:261272, service port: 20881;Pool status:WARN, max:200, core:200, largest:200, active:200, task:5573570, service port: 20882, dubbo version: 3.2.3.8-RELEASE, current host: 10.*.*.7
03-26 20:24:32.740 ERROR 25110 --- [ThreadPoolMonitor-thread-1] c.*.*.c.scheduled.ScheduledContainer : [DUBBO] Pool status:OK, max:200, core:200, largest:200, active:0, task:262550, service port: 20881;Pool status:WARN, max:200, core:200, largest:200, active:200, task:5578245, service port: 20882, dubbo version: 3.2.3.8-RELEASE, current host: 10.*.*.7
03-26 20:25:32.740 ERROR 25110 --- [ThreadPoolMonitor-thread-1] c.*.*.c.scheduled.ScheduledContainer : [DUBBO] Pool status:OK, max:200, core:200, largest:200, active:0, task:264110, service port: 20881;Pool status:WARN, max:200, core:200, largest:200, active:200, task:5582899, service port: 20882, dubbo version: 3.2.3.8-RELEASE, current host: 10.*.*.7
一、问题分析
1、查看监控
公司的中间件监控系统做的比较完善,对dubbo框架的监控有进行定制化开发,并集成到统一运维平台,能够更加方便开发同学了解服务运行情况,出现问题时系统整体QPS流量:
对比前一天的系统QPS流量:
问题当天整体dubbo服务监控信息:
从上面监控信息中可以得出三个结论:
1、问题当天系统QPS流量开始相对平稳,下降的波动主要是由于问题期间dubbo线程池被占满导致无法处理其他请求,上升的波动是系统自动恢复后流量统计到同一时间上了,整体流量相比前一天流量没有明显增长;
2、Provider(服务端)平均RT上升较大,问题期间dubbo出现线程被长时间占用问题;
3、在RT上升机器,Consumer、Provider都有大量失败;
2、找到问题接口
查看dubbo接口RT监控,发现有一个接口问题期间平均RT达到 31秒多:
这么高的RT说明接口内部肯定出现了问题,继续查看接口RT耗时明细,最高RT将近达到 80秒:
3、分析接口
既然找到的问题接口,那么查看一下接口的日志信息,看看能否定位到原因:
日志使用spring AOP做的切面,针对系统接口耗时如果超过3秒,则会自动打印出固定格式的日志,方便后续对高RT接口进行优化。这里AOP的好处一下就表现出来了,根据日志轻松找到相关信息,继续正对一条请求查看日志明细:
看到这个日志原因基本就可以确定了:dubbo接口内部请求了某个http接口,而这个http接口耗时较长导致长时间占用dubbo线程不释放,最终引起dubbo线程池被占满。
4、问题验证
为什么http请求超时会导致dubbo线程长时间被占用呢?通过review接口代码,发现应用中使用了org. apache. http. impl. client. HttpClients工具类发送 http请求,继续 review 开源工具源码发现这个工具默认仅支持5个并发:
编写测试代码,验证一下超时是怎么形成的(为了模拟问题时的场景,请求的http接口内部会阻塞2秒):
for (int i = 0; i < 100; i++) {
new Thread(()->{
long tempTime = System.currentTimeMillis();
try {
String code = restfulServiceClient.get("http://10.*.*.88:7001/account/get?bId=" + bId + "&buyerId=" + buyerId, String.class);
} catch (Exception e) {
logger.error("请求超时:" , e);
}
long useTime = System.currentTimeMillis() - tempTime;
if (useTime < 1000 * 4) {
logger.info("i=" + index.incrementAndGet() + " 单次耗时:{} ms", useTime);
} else {
logger.error("i=" + index.incrementAndGet() + " 超时,单次耗时:{} ms", useTime);
}
}).start();
}
查看输出日志:
这下原因清楚了:由于http工具默认仅支持 5 个并发,且有线程池队列,当请求量超过 5 个的时候,多余的请求会在队列中堆积。前一批http请求结束之后其他的请求才会继续执行,越到后面线程等待时间会越长。所以对应实际业务场景中dubbo线程等待的时间也会越长,当这个队列到一定数量之后,就会引起dubbo默认200个线程池被占满的情况,从而引起整个应用服务的报错。
二、解决方案
知道了问题原因,解决方案就变得简单起来:
1、系统中依赖 http 接口迁移到 java dubbo接口(对应业务方已经有相关dubbo接口);
2、工具类封装并进行优化,调整到合适的并发执行数量,修改队列方式,设置超时超时时间(参数值根据业务场景具体分析);
3、问题接口接入限流降级框架,配置限流阈值,防止在高流量的情况下导致接口被打挂;
总结
1、使用开源框架时要了解相关的原理,默认值不一定适合所有的场景,需要根据自己的场景分析选择对应的配置。
2、对代码存在敬畏之心,复杂的业务代码中,一个看似不起眼的http请求出现问题,最终会导致整个dubbo服务不可用。
3、完善监控系统,及时主动发现问题,及时处理降低影响面。
————————————————
版权声明:本文为CSDN博主「smatiger」的原创文章,遵循CC 4.0 BY-SA版权协议,转载请附上原文出处链接及本声明。
原文链接:https://blog.csdn.net/wsmalltiger/article/details/124236055