歡迎你們關注公衆號「JAVA前線」查看更多精彩分享文章,主要包括源碼分析、實際應用、架構思惟、職場分享、產品思考等等,同時歡迎你們加我我的微信「java_front」一塊兒交流學習java
1 一個公式
以前咱們在一個公式看懂:爲何DUBBO線程池會打滿 這篇文章中分析了爲何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 RT架構
若是系統爲每個請求分配一個處理線程,那麼併發量能夠近似等於線程數。基於上述公式不難看出併發量受QPS和RT影響,這兩個指標任意一個上升就會致使併發量上升。
可是這只是理想狀況,由於併發量受限於系統能力而不可能持續上升,例如DUBBO線程池就對線程數作了限制,超出最大線程數限制則會執行拒絕策略,而拒絕策略會提示線程池已滿,這就是DUBBO線程池打滿問題的根源。
2 一段代碼
如今咱們分析一段看似正確的代碼爲何致使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); } }
2.1 生產者
(1) 服務聲明
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) 服務發佈
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) 服務消費
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 運行結果
觀察日誌發現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 一個工具
根據第一章節介紹的公式和代碼片斷,咱們不難推測大機率是由於RT上升致使線程池打滿,但若是須要分析詳細緣由還不能就此止步,還須要結合線程快照進行分析。線程快照還有一個做用就是若是線上服務器忽然報線程池打滿錯誤,咱們不能馬上定位問題代碼位置,這就須要經過線程快照進行分析。
3.1 jstack
獲取線程快照第一種方式是jstack命令,這個命令能夠根據JAVA進程號打印線程快照,使用方法分爲三個步驟,第一肯定JAVA進程號,第二打印線程快照,第三分析線程快照。
(1) 肯定JAVA進程號
jps -l
(2) 打印線程快照
假設第一步獲得JAVA進程號爲5678
jstack 5678 > dump.log
(3) 分析線程快照
如今咱們就要分析快照文件dump.log,咱們固然能夠直接打開快照文件進行分析,也能夠藉助工具進行分析,我一般使用一款IBM開發的免費線程快照分析工具:
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文件,選擇工具欄餅狀圖標分析線程狀態:
咱們發現大量線程阻塞在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) { } } }
3.2 DUBBO線程快照
第二種獲取線程快照的方式在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)
4 一些思考
MyCache工具的修改方法也並不複雜,能夠將其交給Spring管理,經過PostConstruct註解進行初始化,而且將獲取緩存方法聲明爲對象方法。
其實咱們發現MyCache類語法並無錯誤,在靜態代碼塊執行初始化操做也並不是不可。可是因爲調用者流量很大,發生了MyCache沒有初始化完成就被大量調用的狀況,致使大量線程阻塞在初始化方法上,最終致使線程池打滿。因此當流量逐漸增大時,量變引發了質變,原來不是問題的問題也暴露了出來,這須要引發咱們的注意,但願本文對你們有所幫助。
歡迎你們關注公衆號「JAVA前線」查看更多精彩分享文章,主要包括源碼分析、實際應用、架構思惟、職場分享、產品思考等等,同時歡迎你們加我我的微信「java_front」一塊兒交流學習