運維：大家 JAVA 服務怎麼又又又又出問題了！內存降不下來！

時間 2021-06-16

標籤 java git github segmentfault 後端 bash 服務器運維測試 spa 欄目 Java 简体版

原文原文鏈接

先點贊再看，養成好習慣

接上篇《運維：大家 JAVA 服務內存佔用過高，還只增不減！告警了，快來接鍋》
java

在上次在運維老哥友好的和我溝通以後，還消停沒幾天，今天又來找（問候）我了……
git

運維：這個服務也是大家的吧，你看這個 JAVA 進程，內存佔用都快 3 個 G 了，這機器才 4G，大家堆才配置 2G，都要告警了！此次是真的內存泄露了吧，不是我無知了吧！

又來搞事情……這大哥是對我有意見嗎？有了上次的經驗，這回更自信了。仍是按照慣例，先懟回去github

我：「不可能，咱們服務很是穩定，不會有這種問題！」segmentfault

運維：你這哪來的自信和勇氣？梁靜茹給的嗎？你先回去查查再裝後端

看來大哥這回是有備而來啊，難道真是出問題了？有點慌了……bash

不過仍是不能慫，先敷衍下運維老哥，找個藉口回去先偷摸查查監控看看服務器

我：行，我待會看看，我先去跟人開個會啊……

分析監控數據

這個服務的堆內存配置的是 2G，歷史內存也確實達到過 2G，雖然如今 used 才幾百兆……看起來也沒啥問題
運維

再加上一些 VM 本身的開銷，一共佔用 2 個多 G……好像也說的過去
測試

而後我又找到了運維大哥，（友好的）溝通一下……
spa

我：和上次同樣啊，沒什麼區別，上次都解釋過那個內存管理的機制了，你咋還說咱們有問題？

運維：你看大家這個服務，配置的是 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 ，查查代碼，之後少出這種低級問題，否則我一天到晚處理大家這些破事不得煩死了

沒想到這運維還喘起來了，給點面子就要上天……不過誰讓我理虧呢，只能應下