程序员楼下闲聊：某次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教程