一行代碼引起的集羣服務宕掉的血案分析

時間 2019-11-29

原文原文鏈接

本文禁止轉載！原文地址： blog.csdn.net/lsgqjh/arti…java

緊急處理過程

11.05號晚上接近20點，有同事反應其它服務調用XXX服務出現少許超時，看了下Cat監控，發現些許機器當時處於fullgc，由於咱們的XXX服務自己在高峯期就有較爲頻繁的fullgc，而且當天我還灰度了一臺調過JVM參的XXX機器（本意是解決以前fullgc問題）。因此當時誤覺得是像往常同樣的fullgc引起的上游超時，同時從Cat gc指標來看，我灰度的一臺XXX機器都優於其它機器，同時查看超時報警消息都不涉及灰度的機器，從而也排除了本次灰度的因素。你們持續觀察後，報警愈來愈頻繁，fullgc也愈來愈頻繁，頻次已遠遠高於以前的高峯期，就在想有哪些因素的變更把以前的fullgc問題給放大了，詢問相關業務並無數據量級變更。編程

隨着fullgc愈來愈頻繁，觀察到今天的fullgc後old區內存回收較少，居高不下，馬上猜想是由於下午的XXX服務業務上線的代碼極可能有內存泄露的問題，立馬告知上線同窗回滾代碼，此時XXX集羣服務已不可用同時你們商討緊急預案，評估XXX服務哪些場景的請求可作最壞降級，畢竟XX服務只關注排序體驗，幸虧客戶端調用超時時間是1s，上游業務沒有被拖垮，沒有影響到商城召回。登錄高內存機器經過jmap查看實例狀況：緩存

查看灰度的一臺機器的gc日誌，能夠看到新生代每次gc，對象都會由於晉升擔保到老年代， new threshold 已被動態調整爲1，甚至：

427819   class space    used 9908K, capacity 10491K, committed 10624K, reserved 1048576K
427820 2019-11-05T20:12:56.043+0800: 17269.148: [GC (Allocation Failure) 17269.148: [ParNew
427821 Desired survivor size 100191432 bytes, new threshold 1 (max 15)
427822 - age   1:  142964632 bytes,  142964632 total
427823 : 1258304K->139776K(1258304K), 0.2134974 secs] 3853016K->2923653K(4054528K), 0.2140106 secs] [Times: user=1.32 sys=0.05, real=0.21 secs]
427824 Heap after GC invocations=12249 (full 57):
複製代碼

以後觀察到回滾後機器指標趨於正常了，因此肯定了case和這次上線有關，開始diff代碼查找內存泄露的地方bash

過後排查

首先跟上線同窗進行了代碼走讀，重點關注有沒有引入HashMap相關邏輯致使內存泄漏，然而並無定位出緣由。在Cat上查看當時的線程堆棧，發現JVM線程數打到1.5k+，而且觀察到大量業務線程block到某個同步代碼塊上。多線程

此時猜想死鎖？或者同步塊內有耗時任務？轉而詢問上線同窗均排除了這兩種可能。帶着爲何會大量block的疑問，趕忙觀察了Cat上cpu相關指標，load飆升和cpu buzy持續100%，意味着CPU某核心被打滿。

那麼問題來了，還有7個core來跑業務線程啊，也不至於block業務線程的。當時模模糊糊懷疑是業務失控建立了大量線程，內存資源大量消耗，並大量阻塞在syncrhonized 的wait_list，同時從Cat能看到整個服務端請求處理耗時飆升到幾十秒了，大量線程持有的內存因gc年齡大量晉升到老年代，進而致使了頻繁fullgc，（這裏的猜想後來證實並不正確，事實上有點「雞生蛋，蛋生雞」的味道）。接着上線的同窗果然排查到有行代碼存在bug：在進行特徵加載的時候，會致使每一個請求可能建立上千的子任務投遞到線程池，newCachedThreadPool！線程建立無上限。。。排查到這裏，彷佛以爲找到了內存打滿fullgc的緣由。但到這裏其實還解釋不了爲何CPU buzy 100%的現象。咱們在凌晨對上線的代碼進行了壓測，復現線上問題。在壓測時，能夠經過jstack命看到Java進程下一個很突兀的高消耗CPU的線程，CPU%指標逼近100%。打印該線程棧看它在作一些什麼事情。app

Streams$ConcatSpliterator.forEachRemaining(Streams.java:742)
 340     at java.util.stream.Streams$ConcatSpliterator.forEachRemaining(Streams.java:742)
 341     at java.util.stream.Streams$ConcatSpliterator.forEachRemaining(Streams.java:742)
 342     at java.util.stream.Streams$ConcatSpliterator.forEachRemaining(Streams.java:742)
 343     at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:512)
 344     at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:502)
 345     at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708)
 346     at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
 347     at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:499)
 348     at com.xxx.service.feature.logger.PrintUnit.countState(PrintUnit.java:69)
 349     at com.xxx.service.feature.logger.PrintJob.lambda$printFeatureCountNow$59(PrintJob.java:151)
複製代碼

能夠看到佔用CPU%的線程在執行咱們業務裏特徵日誌打印的邏輯，迅速讓同事定位到某行代碼，看爲何會那麼消耗CPU，review一遍這塊代碼（本次新上線的一條日誌打印），看起來邏輯只是循環拼接了一些要打印的日誌，看起來並無複雜的業務邏輯，同時review到日誌打印線程是單線程，因此不存在用到的HashMap跑飛。那隻能是循環次數很大很大？同事說確實比較大，較大的能達到上萬次，那關鍵問題是上萬次規模的循環也不至於CPU100%啊！咱們加了關鍵邏輯的代碼耗時，看看到底每一個業務請求在特徵打印階段會致使多少次遍歷，耗時多少，從新壓測後，驚人的發現日誌打印耗時不少能達到上百ms！正常狀況下server端業務線程耗時才幾十ms。去掉本次上線的日誌打印邏輯，從新壓測，指標正常。至此基本鎖定到是這塊代碼問題，但看起來並無哪行代碼那麼耗時，但隱隱約約聽過String.format底層有坑？問題定位後，下半夜就回家了。 11.06號上午，在網上看了String.format和StringBuilder性能評測，並親測String.format耗時相比StringBuilder高20倍左右。 因此得出初步結論： 直接緣由是日誌打印單線程邏輯耗時較長（大循環+String.format），在高峯期致使消息積壓在線程池的任務隊列裏，而任務全都是計算型，並無任何IO阻塞或睡眠操做，很難釋放CPU資源，進而致使相似於在run()寫了個死循環！因爲消息堆積致使內存激增，fullgc頻次激增，多個GC線程CPU消耗激增，業務線程hang住，客戶端請求無響應超時，斷開鏈接，服務端close_wait飆升至幾k。 dom

驗證結論：ide

在本地模擬了業務代碼的線程模型，每1s提交到隊列50個任務，單線程處理隊列任務。run()方法裏模擬了日誌打印的循環規模和耗時的String.format代碼。運行後，發現打印的隊列大小是持續增長的。若是放開循環裏的字符串拼接註釋，消息隊列就沒有了堆積。其實本質緣由仍是線程池參數設置不合理，致使生產者消費者失衡。工具

public static void main(String[] args) throws InterruptedException {
        BlockingQueue<Runnable> blockingQueue = new LinkedBlockingQueue<>(99200);
        ThreadPoolExecutor threadPool = new ThreadPoolExecutor(1, 1,
                0L, TimeUnit.MILLISECONDS, blockingQueue
        ))

        new Thread(new Runnable() {
            @Override
            public void run() {
                while (true) {
                    System.out.println("queueSize:" + blockingQueue.size());
                    for (int i = 0; i < 100; i++) {
                        threadPool.execute(new Runnable() {
                            @Override
                            public void run() {
                                long start2 = System.currentTimeMillis();
                                for (int j = 0; j < 10000; j++) {

                                    //String s = "asdsdsdsaa" + new Random().nextLong() + "bbbbbfbfdsfb" +  new Random().nextLong() + "kkksdskkkkk";
                                    String.format("[%s] $ [%s] : [%s]", new Random().nextLong(), new Random().nextLong(), new Random().nextLong());
                                }

                                try {
                                    Thread.sleep(50);
                                } catch (InterruptedException e) {
                                    e.printStackTrace();
                                }
                                 System.out.println(Thread.currentThread().getName());
                                //System.out.println("time:" + (System.currentTimeMillis() - start2));
                            }
                        });
                    }
                    try {
                        Thread.sleep(1000);
                    } catch (InterruptedException e) {
                        e.printStackTrace();
                    }
                }
            }
        }).start();

複製代碼

問題解決

稍微改改就解決了性能

總結

線程池參數的修改應該很是很是謹慎！ 由於可能好多業務在用
敬畏每一行代碼的修改，由於每每就由於「多打了一行日誌」的相似問題整個服務掛掉
重視領域頂層設計，每每決定了後續服務的擴展性，靈活性，健壯性，可維護性。
要作「正確的事」，而不是作各類事，正確的事每每是具有長遠價值的事
禁止使用Executors提供的工具方法，手動建立ThreadPoolExecutor，設置好重要參數。 像案例中兩處使用線程池均致使bug，如newCachedThreadPool萬一線程hang住，線程數就會不可控。
注意「雪崩效應」。 系統若是但願別的系統問題儘可能減小對自身的影響，建議按期對自身系統的依賴作梳理，儘可能自治。對依賴系統進行：消除依賴、弱化依賴和控制依賴。