关于java:运维你们-JAVA-服务怎么又又又又出问题了内存降不下来

5次阅读

共计 6312 个字符，预计需要花费 16 分钟才能阅读完成。

先点赞再看，养成好习惯

接上篇《运维：你们 JAVA 服务内存占用太高，还只增不减！告警了，快来接锅》

在上次在运维老哥敌对的和我沟通之后，还消停没几天，明天又来找（问候）我了……

运维：这个服务也是你们的吧，你看这个 JAVA 过程，内存占用都快 3 个 G 了，这机器才 4G，你们堆才配置 2G，都要告警了！这次是真的内存泄露了吧，不是我无知了吧！

又来搞事件……这大哥是对我有意见吗？有了上次的教训，这回更自信了。还是依照常规，先怼回去

我：“不可能，咱们服务十分稳固，不会有这种问题！”

运维：你这哪来的自信和勇气？梁静茹给的吗？你先回去查查再装

看来大哥这回是有备而来啊，难道真是出问题了？有点慌了……

不过还是不能怂，先搪塞下运维老哥，找个借口回去先偷摸查查监控看看

我：行，我待会看看，我先去跟人开个会啊……

这个服务的堆内存配置的是 2G，历史内存也的确达到过 2G，尽管当初 used 才几百兆……看起来也没啥问题

再加上一些 VM 本人的开销，一共占用 2 个多 G……如同也说的过来

而后我又找到了运维大哥，（敌对的）沟通一下……

我：和上次一样啊，没什么区别，上次都解释过那个内存治理的机制了，你咋还说咱们有问题？

运维：你看你们这个服务，配置的是 CMS+ParNew 垃圾回收器吧，上次是你说的这个回收器组合下会开释内存给操作系统吧？那怎么还占用 2G，开释到哪去了？

我：尽管上回测试后果是会开释，但还有一些其余的说法，说是闲暇时会增量开释，而且开释老本这么高，不开释又怎么样？

运维：你这话不是打本人脸么？上回说能开释，当初没开释你也说失常，你是不是感觉我傻？

运维大哥如同看出了我是在诡辩……

不开释也失常啊，开释老本这么高，开释后还得从新申请，从新组织内存构造 balabalabala……

这话说的我本人都没底气……毕竟上次才测试过 CMS+ParNew 的确会开释，只是工夫问题

运维：你持续诡辩，这服务的内存照这个趋势，预计要不要今天就得 OOM，而后零碎再给你来个 OOM Killer 的绝杀，你可就开心了！

我：没问题的，这个内存失常，本人的服务，我还能不理解嘛

此时我曾经有点不安了，大哥说的有情理啊，万一 OOM Killer 了，可不完蛋了！

我：我晚点有空再认真看看，应该没啥问题，你先忙你的，释怀！

打发走了运维老哥之后，我认真思考了一会。这内存的数据如同的确不太失常，这个服务属于那种后端利用，尽管业务简单，但只是给业务大佬们用。不过这个内存占用的确有点说不过去啊，到底内存跑哪去了……

还是数据谈话吧，上主机上找找看有没有什么线索

内存 – ok
CPU 利用率 – ok
CPU 负载 – ok

也没什么异样，CPU 利用率和负载啥的都很低……到底问题出在哪？

这么一点点的看指标太吃力了，还是拿 Arthas 看吧，JVM 相干的指标它根本都显示，比拟全：

[arthas@20727]$ dashboard

Memory                    used    total    max     usage    GC
heap                      498M     1963M    1963M   25.1%    gc.ps_scavenge.count          3
ps_eden_space             98M      512M     512M    19.5%    gc.ps_scavenge.time(ms)       44
ps_survivor_space         0K      87040K   87040K  0.00%    gc.ps_marksweep.count         1
ps_old_gen                39M     1365M    1365M   2.88%    gc.ps_marksweep.time(ms)      87
nonheap                   32M     180M      -1      17.7%
code_cache                10M      50M      240M    20%
metaspace                 20M     128M      -1      15.6%
compressed_class_space    2M      2M       1024M   0.25%

看起来 JVM 级别的内存也没啥问题，再看看线程呢：

[arthas@20727]$ thread

Threads Total: 9831, NEW: 0, RUNNABLE: 8, BLOCKED: 0, WAITING: 9789, TIMED_WAITING: 2, TERMINATED: 0, Internal threads
: 17

卧槽，这什么玩意！快 1w 个线程！还基本上都是 WAITING！

连忙看看这些 WAITING 的线程都是些啥：

[arthas@20727]$ thread --state WAITING

ID   NAME                          GROUP          PRIORITY  STATE     %CPU      DELTA_TIM TIME      INTERRUPT DAEMON
# 此处省略 9000+ 行……
9822 pool-9813-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9823 pool-9814-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9824 pool-9815-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9825 pool-9816-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9826 pool-9817-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9827 pool-9818-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9828 pool-9819-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9829 pool-9820-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9830 pool-9821-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9831 pool-9822-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9832 pool-9823-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9833 pool-9824-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9834 pool-9825-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9835 pool-9826-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9836 pool-9827-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9837 pool-9828-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9838 pool-9829-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9839 pool-9830-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false
9840 pool-9831-thread-1            main           5         WAITING   0.0       0.000     0:0.000   false     false

看到这个线程名，我也大略明确了，肯定是哪个小蠢才在代码里下毒。

从线程名称来看，必定是线程池里的线程嘛，而且是默认的线程名生成规定。线程池里的线程都是通过 ThreadFactory 来创立的，而默认的 ThreadFactory 生成规定就是这样：

DefaultThreadFactory() {SecurityManager s = System.getSecurityManager();
    group = (s != null) ? s.getThreadGroup() :
    Thread.currentThread().getThreadGroup();

    // 前缀，每一个新的 ThreadFactory 都有一个新的前缀
    // 每一个线程池，都只有一个 ThreadFactory
    namePrefix = "pool-" +
        poolNumber.getAndIncrement() +
        "-thread-";
}

public Thread newThread(Runnable r) {
    
    // 每个线程都会应用 factory 的前缀，而后加上自增的线程数
    Thread t = new Thread(group, r,
                          namePrefix + threadNumber.getAndIncrement(),
                          0);
    if (t.isDaemon())
        t.setDaemon(false);
    if (t.getPriority() != Thread.NORM_PRIORITY)
        t.setPriority(Thread.NORM_PRIORITY);
    return t;
}

所以这个问题，必定是哪个小蠢才，在代码里每次都新建线程池，而后还不 shutdown 导致的！轻易找个线程，看看它的 stack：

"pool-1-thread-1" Id=10 WAITING on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@6ba7592
    at sun.misc.Unsafe.park(Native Method)
    -  waiting on java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@6ba7592
    at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
    at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
    at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
    at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1074)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1134)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
    at java.lang.Thread.run(Thread.java:748)

实锤了，就是每次 new 线程池不 shutdown……当初只须要找到创立线程池的中央，再翻翻提交记录，就能够晓得是哪个小蠢才了……

但代码这么多，想找到这个新建线程池的中央还是有点麻烦的，搜代码可不太不便。这里还是用 Arthas 来看看，stack 一看就晓得

不过如果这里间接 stack ThreadPoolExecutor#execute 办法的话，烦扰信息可能太多了，毕竟调用 execute 的中央太多，不好抓到重点

所以还是 stack 线程池初始化的办法比拟好：

[arthas@20727]$ stack java.util.concurrent.ThreadPoolExecutor <init>

Affect(class count: 0 , method count: 0) cost in 4 ms, listenerId: 5
No class or method is affected, try:
1. Execute `sm CLASS_NAME METHOD_NAME` to make sure the method you are tracing actually exists (it might be in your parent class).
2. Execute `options unsafe true`, if you want to enhance the classes under the `java.*` package.
3. Execute `reset CLASS_NAME` and try again, your method body might be too large.
4. Check arthas log: /home/jiangxin/logs/arthas/arthas.log
5. Visit https://github.com/alibaba/arthas/issues/47 for more details.

这……是不反对吗？

Arthas 的加强策略是比拟激进的，局部零碎级别的类它不做加强，java.* 包下的类默认是不加强的，须要手动开启才行：

[arthas@20727]$ options unsafe true

 NAME    BEFORE-VALUE  AFTER-VALUE
-----------------------------------
 unsafe  false         true

再次执行 stack 之后，能够用了。过了两分钟之后，终于有一次调用：

ts=2021-06-12 12:04:03;thread_name=main;id=1;is_daemon=false;priority=5;TCCL=sun.misc.Launcher$AppClassLoader@4e0e2f2a
    @java.util.concurrent.ThreadPoolExecutor.<init>()
        at java.util.concurrent.Executors.newFixedThreadPool(Executors.java:89)
        at XXXService.sendSms(XXXService.java:782)
        //...

终于找到了这个骚操作代码……它是这么写的：

ExecutorService executorService = Executors.newFixedThreadPool(8);
        
executorService.submit(smsTask);

//...

和我猜想的一样，果然是每次 new，而后还不 shutdown。

这也能和下面的状况对上了，多出的内存占用是因为这小一万个线程……而且这些线程池没有工作须要执行的话，线程必定是 WAITING 状态，也不会占用 CPU 的利用率，负载有不会有影响。不认真还真看不出问题
，还是得联合各种指标来看，综合剖析。

解决这个问题倒简略，让写这个屎代码的人去改了，而后拉出去祭天。

可是运维大哥那边……曾经装出去了，这下脸可是丢完了。上次好不容易挣回来的体面，这次啥都没了

我：服务的确有点问题，咱们发个紧急修复版本，早晨上线就能解决了

运维：你不是说没问题么？自信哪去了

我：这不是没吃早饭，饿的头发昏，脑子不够苏醒……没看进去问题，我的锅我的锅

运维：必定是你们的屎山代码导致的，没事也搞搞 code review，查查代码，当前少出这种低级问题，不然我一天到晚解决你们这些破事不得烦死了

没想到这运维还喘起来了，给点体面就要入地……不过谁让我理亏呢，只能应下