欢迎你们关注公众号「JAVA前线」查看更多精彩分享文章,主要包括源码分析、实际应用、架构思惟、职场分享、产品思考等等,同时欢迎你们加我微信「java_front」一块儿交流学习java
咱们在以前一篇文章中用一个公式分析了为何DUBBO线程池为何会打满,在本文开始时咱们不妨先回顾一下这个公式:一个公司有7200名员工,天天上班打卡时间是早上8点到8点30分,每次打卡系统耗时5秒。请问RT、QPS、并发量分别是多少?linux
RT表示响应时间,问题已经告诉了咱们答案:web
RT = 5spring
QPS表示每秒查询量,假设签到行为平均分布:apache
QPS = 7200 / (30 * 60) = 4windows
并发量表示系统同时处理的请求数量:缓存
并发量 = QPS x RT = 4 x 5 = 20服务器
根据上述实例引出以下公式:微信
并发量 = QPS x RTmarkdown
若是系统为每个请求分配一个处理线程,那么并发量能够近似等于线程数。基于上述公式不难看出并发量受QPS和RT影响,这两个指标任意一个上升就会致使并发量上升。
可是这只是理想状况,由于并发量受限于系统能力而不可能持续上升,例如DUBBO线程池就对线程数作了限制,超出最大线程数限制则会执行拒绝策略,而拒绝策略会提示线程池已满,这就是DUBBO线程池打满问题的根源。
如今咱们分析一段正确的代码为何致使DUBBO线程池打满:MyCache是一个缓存工具,初始化时从不少文件中读取数据内容至内存,获取时直接从内存获取。
public class MyCache {
private static Map<String, String> cacheMap = new HashMap<String, String>();
static {
initCacheFromFile();
}
private static void initCacheFromFile() {
try {
long start = System.currentTimeMillis();
System.out.println("init start");
// 模拟读取文件耗时
Thread.sleep(10000L);
cacheMap.put("K1", "V1");
System.out.println("init end cost " + (System.currentTimeMillis() - start));
} catch (Exception ex) {
}
}
public static String getValueFromCache(String key) {
return cacheMap.get(key);
}
}
复制代码
public interface HelloService {
public String getValueFromCache(String key);
}
@Service("helloService")
public class HelloServiceImpl implements HelloService {
@Override
public String getValueFromCache(String key) {
return MyCache.getValueFromCache(key);
}
}
复制代码
<beans>
<dubbo:application name="java-front-provider" />
<dubbo:registry address="zookeeper://127.0.0.1:2181" />
<dubbo:protocol name="dubbo" port="9999" />
<dubbo:service interface="com.java.front.dubbo.demo.provider.HelloService" ref="helloService" />
</beans>
复制代码
public class Provider {
public static void main(String[] args) throws Exception {
String path = "classpath*:META-INF/spring/dubbo-provider.xml";
ClassPathXmlApplicationContext context = new ClassPathXmlApplicationContext(path);
System.out.println(context);
context.start();
System.in.read();
}
}
复制代码
<beans>
<dubbo:application name="java-front-consumer" />
<dubbo:registry address="zookeeper://127.0.0.1:2181" />
<dubbo:reference id="helloService" interface="com.java.front.dubbo.demo.provider.HelloService" timeout="10000" />
</beans>
复制代码
public class Consumer {
public static void main(String[] args) throws Exception {
ClassPathXmlApplicationContext context = new ClassPathXmlApplicationContext(new String[] { "classpath*:META-INF/spring/dubbo-consumer.xml" });
context.start();
System.out.println(context);
// 模拟大量请求
for (int i = 0; i < 1000; i++) {
new Thread(new Runnable() {
@Override
public void run() {
HelloService helloService = (HelloService) context.getBean("helloService");
String result = helloService.getValueFromCache("K1");
System.out.println(result);
}
}).start();
}
}
}
复制代码
咱们观察日志内容发现线程池打满信息:
NettyServerWorker-5-1 WARN support.AbortPolicyWithReport:
[DUBBO] Thread pool is EXHAUSTED! Thread Name: DubboServerHandler-1.1.1.1:9999, Pool Size: 200 (active: 200, core: 200, max: 200, largest: 200), Task: 201 (completed: 1),
Executor status:(isShutdown:false, isTerminated:false, isTerminating:false), in dubbo://1.1.1.1:9999!, dubbo version: 2.7.0-SNAPSHOT, current host: 1.1.1.1
复制代码
根据第一章节介绍的公式和代码片断,咱们不难推测大几率是由于RT上升致使线程池打满,但若是须要分析详细缘由还不能就此止步,还须要结合线程快照进行分析。线程快照还有一个做用就是若是线上服务器忽然报线程池打满错误,咱们不能马上定位问题代码位置,这就须要经过线程快照进行分析。
获取线程快照第一种方式是jstack命令,这个命令能够根据JAVA进程号打印线程快照,使用方法分为三个步骤,第一肯定JAVA进程号,第二打印线程快照,第三分析线程快照。
jps -l
复制代码
假设第一步获得JAVA进程号为5678
jstack 5678 > dump.log
复制代码
如今咱们就要分析快照文件dump.log,咱们固然能够直接打开快照文件进行分析,也能够借助工具进行分析,我一般一款IBM开发的免费线程快照分析工具:
IBM Thread and Monitor Dump Analyzer for Java
复制代码
https://public.dhe.ibm.com/software/websphere/appserv/support/tools/jca/jca469.jar
复制代码
java -jar jca469.jar
复制代码
咱们用这个工具打开dump.log文件,选择工具栏饼状图标分析线程状态:
咱们发现大量线程阻塞在HelloServiceImpl第48行,找到相应代码位置:
public class HelloServiceImpl implements HelloService {
// 省略代码......
@Override
public String getValueFromCache(String key) {
return MyCache.getValueFromCache(key); // 第48行
}
}
复制代码
咱们假设若是MyCache.getValueFromCache这个方法中存在耗时操做,那么线程应该阻塞在这方法的某一行,可是最终居然阻塞在HelloServiceImpl这个类,这说明是阻塞发生在MyCache这个类初始化上。咱们再回顾MyCache代码,发现确实是初始化方法消耗了大量时间,证实根据线程快照分析的正确性。
public class MyCache {
private static Map<String, String> cacheMap = new HashMap<String, String>();
static {
initCacheFromFile();
}
private static void initCacheFromFile() {
try {
long start = System.currentTimeMillis();
System.out.println("init start");
// 模拟读取文件耗时
Thread.sleep(10000L);
cacheMap.put("K1", "V1");
System.out.println("init end cost " + (System.currentTimeMillis() - start));
} catch (Exception ex) {
}
}
}
复制代码
第二种获取线程快照的方式在DUBBO线程池拒绝策略源码中,咱们分析源码知道每当出现线程池打满状况时DUBBO都会打印线程快照。
public class AbortPolicyWithReport extends ThreadPoolExecutor.AbortPolicy {
protected static final Logger logger = LoggerFactory.getLogger(AbortPolicyWithReport.class);
private final String threadName;
private final URL url;
private static volatile long lastPrintTime = 0;
private static Semaphore guard = new Semaphore(1);
public AbortPolicyWithReport(String threadName, URL url) {
this.threadName = threadName;
this.url = url;
}
@Override
public void rejectedExecution(Runnable r, ThreadPoolExecutor e) {
String msg = String.format("Thread pool is EXHAUSTED!" +
" Thread Name: %s, Pool Size: %d (active: %d, core: %d, max: %d, largest: %d), Task: %d (completed: %d)," +
" Executor status:(isShutdown:%s, isTerminated:%s, isTerminating:%s), in %s://%s:%d!",
threadName, e.getPoolSize(), e.getActiveCount(), e.getCorePoolSize(), e.getMaximumPoolSize(), e.getLargestPoolSize(),
e.getTaskCount(), e.getCompletedTaskCount(), e.isShutdown(), e.isTerminated(), e.isTerminating(),
url.getProtocol(), url.getIp(), url.getPort());
logger.warn(msg);
// 打印线程快照
dumpJStack();
throw new RejectedExecutionException(msg);
}
private void dumpJStack() {
long now = System.currentTimeMillis();
// 每10分钟输出线程快照
if (now - lastPrintTime < 10 * 60 * 1000) {
return;
}
if (!guard.tryAcquire()) {
return;
}
ExecutorService pool = Executors.newSingleThreadExecutor();
pool.execute(() -> {
String dumpPath = url.getParameter(Constants.DUMP_DIRECTORY, System.getProperty("user.home"));
System.out.println("AbortPolicyWithReport dumpJStack directory=" + dumpPath);
SimpleDateFormat sdf;
String os = System.getProperty("os.name").toLowerCase();
// linux文件位置/home/xxx/Dubbo_JStack.log.2021-01-01_20:50:15
// windows文件位置/user/xxx/Dubbo_JStack.log.2020-01-01_20-50-15
if (os.contains("win")) {
sdf = new SimpleDateFormat("yyyy-MM-dd_HH-mm-ss");
} else {
sdf = new SimpleDateFormat("yyyy-MM-dd_HH:mm:ss");
}
String dateStr = sdf.format(new Date());
try (FileOutputStream jStackStream = new FileOutputStream(new File(dumpPath, "Dubbo_JStack.log" + "." + dateStr))) {
JVMUtil.jstack(jStackStream);
} catch (Throwable t) {
logger.error("dump jStack error", t);
} finally {
guard.release();
}
lastPrintTime = System.currentTimeMillis();
});
pool.shutdown();
}
}
复制代码
从下面线程快照文件中咱们看到,200个DUBBO线程也都是执行在HelloServiceImpl第48行,从而也能够定位到问题代码位置。可是DUBBO打印线程快照不是jstack标准格式,因此没法使用IBM工具进行分析。
DubboServerHandler-1.1.1.1:9999-thread-200 Id=230 RUNNABLE
at com.java.front.dubbo.demo.provider.HelloServiceImpl.getValueFromCache(HelloServiceImpl.java:48)
at org.apache.dubbo.common.bytecode.Wrapper1.invokeMethod(Wrapper1.java)
at org.apache.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:56)
at org.apache.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:85)
at org.apache.dubbo.config.invoker.DelegateProviderMetaDataInvoker.invoke(DelegateProviderMetaDataInvoker.java:56)
复制代码
MyCache工具的修改方法也并不复杂,能够将其交给Spring管理,经过PostConstruct注解进行初始化,而且将获取缓存方法声明为对象方法。
其实咱们发现MyCache类语法并无错误,在静态代码块执行初始化操做也并不是不可。可是因为调用者流量很大,发生了MyCache没有初始化完成就被大量调用的状况,致使大量线程阻塞在初始化方法上,最终致使线程池打满。因此当流量逐渐增大时,量变引发了质变,原来不是问题的问题也暴露了出来,这须要引发咱们的注意,但愿本文对你们有所帮助。
欢迎你们关注公众号「JAVA前线」查看更多精彩分享文章,主要包括源码分析、实际应用、架构思惟、职场分享、产品思考等等,同时欢迎你们加我微信「java_front」一块儿交流学习