最近线上系统经常告警dubbo线程池打满报错如下:
172.28.152.53/Caused by: java.util.concurrent.RejectedExecutionException: Thread pool is EXHAUSTED! Thread Name: DubboServerHandler-172.28.149.131:20880, Pool Size: 500 (active: 500, core: 500, max: 500, largest: 500), Task: 71795841 (completed: 71795342), Executor status:(isShutdown:false, isTerminated:false, isTerminating:false), in dubbo://172.28.149.131:20880!
对这个告警做了协查,记录一下,给大家一个参考。
dubbo线程池打满后,会立即生成一个线程dump文件,这里先去服用器上拿文件,立即生成一个线程dump文件需要配置一下启动参数
-Ddubbo.application.dump.directory=/data/dataLogs/jetty/dump
以后发生 dubbo线程池打满就到以到/data/dataLogs/jetty/dump下找文件,另外大家也可以通过jstack jmap等命令分析,我们因为投产使用不了,这里大家自行学习。
拿到dump文件后,打开看看
足足有2W多行,这么一行行看也没问题,这里推荐个分析工具:Smart Java thread dump analyzer - thread dump analysis in seconds
上传文件后,生产一个分析结果页面,很好用,如下图。
上图BLOCKED 的线程有2个,点进去看一下明细
综合业务和线程栈分析: 我们做了一个日志打印的aop,在方法入口切入,添加一个uuid生成的TraceID,通过MDC将日志串起来,我们使用java的UUID对象的randomUUID()生成id,randomUUID底层使用SecureRandom,像注释里讲了,多线程并发时,会BLOCK,所以性能不是很高。
解决办法:
我自己写一个方法:
package com.test.java8;
import java.util.UUID;
import java.util.concurrent.atomic.AtomicLong;
public class MyUUID {
// static final AtomicLong counter = new AtomicLong(System.nanoTime());
static final AtomicLong counter = new AtomicLong(System.currentTimeMillis());
public static String getUUID() {
return String.valueOf(counter.getAndIncrement());
}
public static String getUuid() {
return UUID.randomUUID().toString().replace("-", "");
}
public static void main(String[] args) {
int rCount = 100000000;
System.out.println("开始随机数生成测试!");
Long begin = System.currentTimeMillis();
for (int i = 0; i < rCount; i++) {
MyUUID.getUUID();
// System.out.println(MyUUID.getUUID());
}
System.out.printf("完成随机数生成,用时" + (System.currentTimeMillis() - begin) + "ms");
System.out.println("-----------------------------------------------------------------");
// Long begin2 = System.currentTimeMillis();
// for (int i = 0; i < rCount; i++) {
// MyUUID.getUuid();
// }
// System.out.printf("完成随机数生成,用时" + (System.currentTimeMillis() - begin2) + "ms");
// System.out.println(MyUUID.getUUID());
// System.out.println(MyUUID.getUuid());
}
}
注意!:不保证集群唯一的,这里因为主要是Trace 所以问题不大。如果有集群唯一的需求不要用我这个方法,可以参考SnowFlake等算法。
至此这个dump就分析完了。
那边在这次协查中,还有一个dump锁在了另外一个地方,贴一下图:
通过分析:
项目中使用的是logback的实现,项目配置的是AsyncAppender异步打印,异步打印日志会被存放在一个SynchronousQueue,然后再由消费线程来消费打印,以提升系统性能(建议大家生产一定要用异步),SynchronousQueue是阻塞队列,由于请求量大,打印的日志又多,最终导致消费速度跟不上,后面的添加队列都阻塞了,业务线程都夯在这里。
解决方案:
1.删除一些多余,无用日志(打印日志确实也很耗性能),打印尽量精简(我们通过此方法解决)。
2.升级日志框架(考虑中),目前log4j2看起来是不错的选择,官方也给了一些性能比较数据Log4j – Performance,log4j2的异步消息存储不是阻塞队列,是通过Disruptor高性能队列实现性能更强劲。更有美团在2016年将使用log4j2作为内部规范(高性能队列——Disruptor - 美团技术团队),哈哈,看来我们的步子还是有点慢了!
也做了一个集成log4j2的demo,仅供参考:GitHub - kevinmails/h2-test
牺牲了午休时间,用心总结,觉得有用的话,收藏转发,哈哈!