為什么一段看似正確的代碼會導(dǎo)致DUBBO線程池被打滿
JAVA前線
歡迎大家關(guān)注公眾號「JAVA前線」查看更多精彩分享，主要包括源碼分析、實際應(yīng)用、架構(gòu)思維、職場分享、產(chǎn)品思考等等，同時也非常歡迎大家加我微信「java_front」一起交流學(xué)習(xí)
1 一個公式
之前我們在《一個公式看懂：為什么DUBBO線程池會打滿》這篇文章中分析了為什么DUBBO線程池為什么會打滿，在本文開始時我們不妨先回顧這個公式：一個公司有7200名員工，每天上班打卡時間是早上8點到8點30分，每次打卡系統(tǒng)耗時5秒。請問RT、QPS、并發(fā)量分別是多少？
RT表示響應(yīng)時間，問題已經(jīng)告訴了我們答案：
RT = 5
QPS表示每秒查詢量，假設(shè)簽到行為平均分布：
QPS = 7200 / (30 * 60) = 4
并發(fā)量表示系統(tǒng)同時處理的請求數(shù)量：
并發(fā)量 = QPS x RT = 4 x 5 = 20
根據(jù)上述實例引出如下公式：
并發(fā)量 = QPS x RT
如果系統(tǒng)為每一個請求分配一個處理線程，那么并發(fā)量可以近似等于線程數(shù)。基于上述公式不難看出并發(fā)量受QPS和RT影響，這兩個指標(biāo)任意一個上升就會導(dǎo)致并發(fā)量上升。
但是這只是理想情況，因為并發(fā)量受限于系統(tǒng)能力而不可能持續(xù)上升，例如DUBBO線程池就對線程數(shù)做了限制，超出最大線程數(shù)限制則會執(zhí)行拒絕策略，而拒絕策略會提示線程池已滿，這就是DUBBO線程池打滿問題的根源。
2 一段代碼
現(xiàn)在我們分析一段看似正確的代碼為什么導(dǎo)致DUBBO線程池打滿：MyCache是一個緩存工具，初始化時從很多文件中讀取數(shù)據(jù)內(nèi)容至內(nèi)存，獲取時直接從內(nèi)存中讀取。
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);
}
}
2.1 生產(chǎn)者
(1) 服務(wù)聲明
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);
}
}
(2) 配置文件
<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>
(3) 服務(wù)發(fā)布
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();
}
}
2.2 消費者
(1) 配置文件
<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>
(2) 服務(wù)消費
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();
}
}
}
2.3 運行結(jié)果
觀察日志發(fā)現(xiàn)DUBBO線程池被打滿：
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
3 一個工具
根據(jù)第一章節(jié)介紹的公式和代碼片段，我們不難推測大概率是因為RT上升導(dǎo)致線程池打滿，但如果需要分析詳細(xì)原因還不能就此止步，還需要結(jié)合線程快照進行分析。線程快照還有一個作用就是如果線上服務(wù)器突然報線程池打滿錯誤，我們不能立刻定位問題代碼位置，這就需要通過線程快照進行分析。
3.1 jstack
獲取線程快照第一種方式是jstack命令，這個命令可以根據(jù)JAVA進程號打印線程快照，使用方法分為三個步驟，第一確定JAVA進程號，第二打印線程快照，第三分析線程快照。
(1) 確定JAVA進程號
jps -l
(2) 打印線程快照
假設(shè)第一步得到JAVA進程號為5678
jstack 5678 > dump.log
(3) 分析線程快照
現(xiàn)在我們就要分析快照文件dump.log，我們當(dāng)然可以直接打開快照文件進行分析，也可以借助工具進行分析，我通常使用一款I(lǐng)BM開發(fā)的免費線程快照分析工具：
IBM Thread and Monitor Dump Analyzer for Java
(a) 如何下載
https://public.dhe.ibm.com/software/websphere/appserv/support/tools/jca/jca469.jar
(b) 如何運行
java -jar jca469.jar
(c) 如何分析
我們用這個工具打開dump.log文件，選擇工具欄餅狀圖標(biāo)分析線程狀態(tài)：
我們發(fā)現(xiàn)大量線程阻塞在HelloServiceImpl第48行，找到相應(yīng)代碼位置：
public class HelloServiceImpl implements HelloService {
// 省略代碼......
@Override
public String getValueFromCache(String key) {
return MyCache.getValueFromCache(key); // 第48行
}
}
我們假設(shè)如果MyCache.getValueFromCache這個方法中存在耗時操作，那么線程應(yīng)該阻塞在這方法的某一行，但是最終竟然阻塞在HelloServiceImpl這個類，這說明是阻塞發(fā)生在MyCache這個類初始化上。我們再回顧MyCache代碼，發(fā)現(xiàn)確實是初始化方法消耗了大量時間，證明根據(jù)線程快照分析的正確性。
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) {
}
}
}
3.2 DUBBO線程快照
第二種獲取線程快照的方式在DUBBO線程池拒絕策略源碼中，我們分析源碼知道每當(dāng)出現(xiàn)線程池打滿情況時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線程也都是執(zhí)行在HelloServiceImpl第48行，從而也可以定位到問題代碼位置。但是DUBBO打印線程快照不是jstack標(biāo)準(zhǔn)格式，所以無法使用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)
4 一些思考
MyCache工具的修改方法也并不復(fù)雜，可以將其交給Spring管理，通過PostConstruct注解進行初始化，并且將獲取緩存方法聲明為對象方法。
其實我們發(fā)現(xiàn)MyCache類語法并沒有錯誤，在靜態(tài)代碼塊執(zhí)行初始化操作也并非不可。但是由于調(diào)用者流量很大，發(fā)生了MyCache沒有初始化完成就被大量調(diào)用的情況，導(dǎo)致大量線程阻塞在初始化方法上，最終導(dǎo)致線程池打滿。所以當(dāng)流量逐漸增大時，量變引起了質(zhì)變，原來不是問題的問題也暴露了出來，這需要引起我們的注意，希望本文對大家有所幫助。
JAVA前線
歡迎大家關(guān)注公眾號「JAVA前線」查看更多精彩分享，主要包括源碼分析、實際應(yīng)用、架構(gòu)思維、職場分享、產(chǎn)品思考等等，同時也非常歡迎大家加我微信「java_front」一起交流學(xué)習(xí)