程序員樓下閒聊：某次jvm崩潰排查

時間  2019-11-06
標籤 程序員 樓下 閒聊 jvm 崩潰 排查 欄目 快樂工作 简体版
原文   原文鏈接 
大望路某寫字樓下。

猿A：上家公司的時候，咱們組那個項目，天天半夜會跑個大批量數據處理的定時任務，而後程序常常崩潰。
我：哦？那怎麼處理的
猿A：當時的架構有點水，說讓調整「伊甸園」和「from-to」的比例……崩潰和這個就不要緊
我：少年，你成功引發了個人注意。來來來，請你喝飲料，好好聊聊當時的狀況。

業務場景

「猿A」是個人同事兼死黨，和他詳聊後大概明白了當時的場景。java

據我理解，那個定時任務，會從hive裏拿出超多的數據（聽說2億左右），按具體業務作數據整合和處理，最終推送到es（elasticsearch）中。（hive什麼的我沒搞過，但不妨礙要討論的東西）架構

業務處理部分，使用了線程池FixedThreadPool。jvm

模擬解決過程

問題定位

猿A：那時候懷疑是內存OOM致使的jvm崩潰，進而懷疑大量對象GC回收不了，因而打了GC日誌。
我：嗯，沒用hs_err_pid_xxx.log分析嗎？
猿A：當時小，還不會這個技能……

死黨「猿A」當時的解決過程比較粗暴，有了懷疑就直接在啓動參數增長了-XX:+PrintGC。此命令會打印GC日誌，姑且認爲生產環境使用GC是CMS，寫個demo模擬當時的場景。elasticsearch

public class CMSGCLogs {
    //啓動參數：-Xmx10m -Xms10m -Xmn4M -XX:+PrintGC -XX:+UseConcMarkSweepGC
    public static void main(String[] args) throws InterruptedException {
        // 線程數設置爲1，起名`T-1`
        ExecutorService es = Executors.newFixedThreadPool(1, new ThreadFactory() {
            @Override
            public Thread newThread(Runnable r) {
                return new Thread(r,"T-1");
            }
        });

        boolean flag = true;
        while (flag){
            es.execute(()->{
                try {
                    byte[] bytes = new byte[1024*1000*1];    //模擬從hive中讀取了大量數據（1M）
                    TimeUnit.MILLISECONDS.sleep(50L);   //模擬寫入es過程
                } catch (Exception e) {
                    e.printStackTrace();
                }
            });
        }
        es.shutdown();
    }
}

先背一段線程池的處理過程。ide

線程池接收請求，小於核心線程數時，會建立線程，直到等於核心線程數。
以後，核心線程數消化不了的請求放入阻塞隊列中。
再後，阻塞隊列也放滿了，再繼續建立線程，直到最大線程數。
最大線程也扛不住依然洶涌的請求，執行拒絕策略。

fixed線程池，做爲線程池家族中的一員，也知足上述規則。
差異在於它的 核心線程數=最大線程數，而後阻塞隊列（LinkedBlockingQueue）是無界的。函數

# 源碼中fixed線程池建立
public static ExecutorService newFixedThreadPool(int nThreads, ThreadFactory threadFactory) {
    return new ThreadPoolExecutor(nThreads, nThreads,
                                  0L, TimeUnit.MILLISECONDS,
                                  new LinkedBlockingQueue<Runnable>(),
                                  threadFactory);
}

運行一下，demo執行結果大概長這樣：ui

[GC (Allocation Failure)  3302K->1174K(9856K), 0.0037023 secs]
[GC (Allocation Failure)  3664K->1541K(9856K), 0.0014799 secs]
[Full GC (Allocation Failure)  1541K->1446K(9856K), 0.0039197 secs]
[Full GC (Allocation Failure)  1446K->1387K(9856K), 0.0037783 secs]
## 線程T-1 OOM
Exception in thread "T-1" java.lang.OutOfMemoryError: Java heap space
    at com.evolution.gc.CMSGCLogs.lambda$main$0(CMSGCLogs.java:44)
    at com.evolution.gc.CMSGCLogs$$Lambda$1/233530418.run(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

...

[Full GC (Allocation Failure)  9676K->9676K(9856K), 0.0253352 secs]
[Full GC (Allocation Failure)  9676K->9676K(9856K), 0.0190795 secs]
## 線程T-1 OOM
Exception in thread "T-1" java.lang.OutOfMemoryError: Java heap space
Exception in thread "T-1" java.lang.OutOfMemoryError: Java heap space

...

[GC (CMS Initial Mark)  9855K(9856K), 0.0051677 secs]
## 線程main OOM
Exception in thread "main" [Full GC (Allocation Failure)  9855K->9855K(9856K), 0.0211383 secs]
[Full GC (Allocation Failure)  9855K->9855K(9856K), 0.0203374 secs]
[Full GC (Allocation Failure)  9855K->9855K(9856K), 0.0433360 secs]
[GC (CMS Initial Mark)  9855K(9856K), 0.0029999 secs]
[Full GC (Allocation Failure) java.lang.OutOfMemoryError: Java heap space
 9855K->9855K(9856K), 0.0249560 secs]
[Full GC (Allocation Failure)  9855K->9854K(9856K), 0.0244291 secs]
[GC (CMS Initial Mark)  9854K(9856K), 0.0063567 secs]
[Full GC (Allocation Failure)  9854K->9854K(9856K), 0.0208301 secs]
[Full GC (Allocation Failure)  9854K->9854K(9856K), 0.0346616 secs]
[Full GC (Allocation Failure)  9855K->1147K(9856K), 0.0067034 secs]
*** java.lang.instrument ASSERTION FAILED ***: "!errorOutstanding" with message can't create byte arrau at JPLISAgent.c line: 813

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "T-1"

Exception: java.lang.OutOfMemoryError thrown from the UncaughtExceptionHandler in thread "main"

其實對fixed線程池熟悉的朋友，在看到使用的是這位爺的時候，就能猜出問題是什麼了——Fixed線程池的無界隊列，會使試圖無限存儲任務，直到內存溢出。
從GC日誌來看也確實是這個路數，還很貼心的指出了哪一個線程，哪一個對象，甚至是哪行異常了（at com.evolution.gc.CMSGCLogs$$Lambda$1/233530418.run(Unknown Source)，固然我這裏用了內部類和函數式，因此看着稍微費勁些）。spa

支線任務1：子線程OOM問題

但有一點和我想象的不同，日誌中線程T-1崩潰了屢次，程序依然堅挺了一陣，才迎來了線程main的崩潰。線程

這就奇怪了，堆內存不是公用的嗎？子線程T-1都崩潰了，爲何沒帶動整個JVM崩潰？3d

所以，我用VisualVM觀察了內存狀況：
clipboard.png
圖中的斷崖處就是線程T-1 OOM的時候，再求證了相關資料後，得出結論：當某一線程（T-1）OOM的時候，會把該線程佔用的內存釋放，而不影響其它線程（main）！

詳細過程是這樣的：

  1. 線程T-1業務處理較慢（TimeUnit.MILLISECONDS.sleep(50L);），任務又大量的涌過來，導致fixed線程池的阻塞隊列瘋狂儲備待執行任務，內存逐漸吃緊；
  2. 線程T-1每次執行又會佔用1M內存（byte[] bytes = new byte[102410001];），因爲內存不足（內存被阻塞隊列佔據了，已不足1M），線程T-1無奈宣告崩潰；
  3. 隨着線程T-1的崩潰，會把資源釋放出來，從新進入循環（下一輪循環，線程T-1繼續崩潰……），直到某個契機把線程main也搞崩潰了，整個JVM才崩潰退出

支線任務2：CMS的STP

我在demo調試時，無心間改大過模擬寫入es的時間，表示耗時更長（以下）：

while (flag){
    es.execute(()->{
        try {
            byte[] bytes = new byte[1024*1000*1];
            TimeUnit.HOURS.sleep(50L);    ## 直接把單位從`MILLISECONDS`改爲`HOURS`了
        } catch (Exception e) {
            e.printStackTrace();
        }
    });
}

本來覺得這樣會使jvm崩潰的更快——線程T-1 50個小時才能執行完，任務又無盡積壓，jvm理應更快的走向滅亡。
結果卻事與願違！

程序執行的效果變成了這樣：

31.949: [GC (CMS Initial Mark)  9855K(9856K), 0.0033049 secs]
31.966: [GC (CMS Final Remark)  9855K(9856K), 0.0046193 secs]
32.401: [Full GC (Allocation Failure)  9855K->9855K(9856K), 0.0243874 secs]
32.425: [Full GC (Allocation Failure)  9855K->9855K(9856K), 0.0240275 secs]
32.450: [GC (CMS Initial Mark)  9855K(9856K), 0.0033793 secs]
32.466: [GC (CMS Final Remark)  9855K(9856K), 0.0048207 secs]
34.473: [GC (CMS Initial Mark)  9855K(9856K), 0.0033645 secs]
34.485: [GC (CMS Final Remark)  9855K(9856K), 0.0046805 secs]
36.491: [GC (CMS Initial Mark)  9855K(9856K), 0.0032574 secs]
...
109.890: [GC (CMS Initial Mark)  9855K(9856K), 0.0038242 secs]
109.902: [GC (CMS Final Remark)  9855K(9856K), 0.0053191 secs]
111.909: [GC (CMS Initial Mark)  9855K(9856K), 0.0106591 secs]
111.945: [GC (CMS Final Remark)  9855K(9856K), 0.0059029 secs]

我獲得了無盡的CMS Initial Mark和CMS Final Remark。

VisualVM的分析圖長這樣：
clipboard.png

內存將將滿，就是等不到「壓倒駱駝的最後一根稻草」。
仔細思考了一番，想起CMS執行過程當中有兩個stop the world（STP）的環節，彷佛就是初始標記（CMS Initial Mark）和最終標記（CMS Final Remark）兩兄弟？

那這個現象就能解釋通了：
隨着堆內存的佔滿，CMS收集器開始執行，但兩個標記環節怎麼執行都發現沒有能回收的資源。（1M的bytes不能回收，由於50小時的休眠後還能用到；阻塞隊列中的任務也不能回收，jvm以爲總會執行這些任務的）
所以，內存吃緊jvm崩潰前夕，CMS就不斷執行初始標記和最終標記，而兩個命令會致使用戶線程（線程T-1）中止，沒機會再給jvm添堵。
因而就這樣微妙的保持了詭異的平衡……

解決方案

以上兩個支線任務是我demo模擬中遇到的魑魅魍魎，猿A同志並無搞出這麼多彎彎繞（固然他可能有其它際遇）。
既然已經定位到了問題產生於FixedThreadPool，那麼換掉它就好，本身new ThreadPoolExecutor。

  • 參數指定有界隊列
  • 修改拒絕策略爲ThreadPoolExecutor.CallerRunsPolicy

拒絕策略默認是ThreadPoolExecutor.AbortPolicy，表現爲丟棄任務並拋出異常；而ThreadPoolExecutor.CallerRunsPolicy則不勞煩線程池，直接交由原線程執行任務（demo中就是不麻煩線程T-1了，線程main頂上）

Tip：這裏給出所有策略，作個參考 ↓↓↓

ThreadPoolExecutor.AbortPolicy:丟棄任務並拋出RejectedExecutionException異常。
ThreadPoolExecutor.DiscardPolicy：也是丟棄任務，可是不拋出異常。
ThreadPoolExecutor.DiscardOldestPolicy：丟棄隊列最前面的任務，而後從新嘗試執行任務（重複此過程）
ThreadPoolExecutor.CallerRunsPolicy：由調用線程處理該任務

修改以後的demo代碼：

public class CMSGCLogs {
    //-Xmx10m -Xms10m -Xmn4M -XX:+PrintGC -XX:+UseConcMarkSweepGC
    public static void main(String[] args) throws InterruptedException {
        BlockingQueue list = new ArrayBlockingQueue(20);    //修改1：有界隊列
        ExecutorService es = new ThreadPoolExecutor(1, 1,
                0, TimeUnit.MILLISECONDS, list, new ThreadFactory() {
                    @Override
                    public Thread newThread(Runnable r) {
                        return new Thread(r,"T-1");
                    }
                },
                new ThreadPoolExecutor.CallerRunsPolicy());   //修改2：更換拒絕策略
        boolean flag = true;
        while (flag){
            es.execute(()->{
                try {
                    byte[] bytes = new byte[1024*1000*1];
                    TimeUnit.MILLISECONDS.sleep(50L);
                    System.out.println(String.format("curThread=%s,run task!",Thread.currentThread())); //打印執行線程
                } catch (Exception e) {
                    e.printStackTrace();
                }
            });
        }
        es.shutdown();
    }
}

看下執行效果：

53.422: [GC (Allocation Failure)  6615K->3550K(9856K), 0.0006514 secs]
curThread=Thread[main,5,main],run task!
curThread=Thread[main,5,main],run task!
curThread=Thread[T-1,5,main],run task!
53.473: [GC (Allocation Failure)  6615K->3550K(9856K), 0.0003791 secs]
curThread=Thread[main,5,main],run task!
curThread=Thread[T-1,5,main],run task!
curThread=Thread[main,5,main],run task!
curThread=Thread[T-1,5,main],run task!
53.573: [GC (Allocation Failure)  6615K->3550K(9856K), 0.0003733 secs]
curThread=Thread[main,5,main],run task!
curThread=Thread[T-1,5,main],run task!
53.623: [GC (Allocation Failure)  6615K->3550K(9856K), 0.0009536 secs]
curThread=Thread[main,5,main],run task!
curThread=Thread[T-1,5,main],run task!
curThread=Thread[main,5,main],run task!
curThread=Thread[T-1,5,main],run task!
53.724: [GC (Allocation Failure)  6615K->3550K(9856K), 0.0004394 secs]

咱們發現程序已經可以平穩的運行了，再觀察此時的jvm堆內存，一切正常：
clipboard.png

新生代各區比例的做用

問題解決了，回顧下架構師當時的提議：

猿A：當時的架構有點水，說讓調整「伊甸園」和「from-to」的比例……崩潰和這個就不要緊

「架構」說的是設定-XX:NewRadio參數來調整新生代各模塊比例。
clipboard.png

這個比例默認爲8:1:1，咱們來看下調整這個參數產生的影響。

  • 極端一些，把Edian調的很大

clipboard.png

新生代GC時，對象是否進入老年代主要取決於兩個因素——對象年齡和對象大小。
若是對象大小超出了某界限，對象就直接進入老年代。如此，會給老年代的GC會增長更多壓力，有可能產生更多的STP。

  • 反向極端，把Edian調的很小

clipboard.png

由於s1和s2兩個區域總有1個是空的，這樣調整會浪費更多的內存，並更頻繁的觸發的新生代GC。

咱們感性的理解了這個比例的做用，那麼架構師的提議和猿A遇到的問題有關嗎？答案是沒有，因此那個架構是真的水……
相關文章
相關標籤/搜索
每日一句
    每一个你不满意的现在，都有一个你没有努力的曾经。
本站公眾號
   歡迎關注本站公眾號,獲取更多信息
聯繫我們 最近搜索 最新文章 沪ICP备13005482号-10 MyBatis教程 SQL 教程 MySQL教程 Java 教程 Thymeleaf 教程 Hibernate教程 Spring教程 Redis教程