天天看點

一次因線程池使用不當造成生産事故的排查記錄與思考

美好的一天從bug結束

某日當我點開熟悉的界面,一個又一個請求失敗的提示赫然出現在螢幕上,不會是昨晚上線的代碼有問題吧?

一次因線程池使用不當造成生産事故的排查記錄與思考

吓得我急忙按F12檢視了響應——"exception":"java.lang.OutOfMemoryError","message":"unable to create new native thread"

出現了記憶體溢出的情況,無法建立更多的本地線程。

監控中顯端倪

接着檢視了執行個體的監控大盤,發現每個執行個體的JVM線程數量都處于9000+的規模,且還有上漲的趨勢。

這是其中一個執行個體的線程數量監控圖:

一次因線程池使用不當造成生産事故的排查記錄與思考

10.17日出現下降,并不是由于GC,而是由于上線,是以會降到0。

目前服務一共有8個執行個體,臨時的方案是從負載均衡中摘除1個節點,用作排查使用,其他執行個體則按照順序進行原地重建。

dump線程日志

登入上這個容器,使用

ps -ef|grep java      

來查詢到java應用的程序号,得到了1127

接着使用

jstack 1127 > thread.log      

來導出程序内所有線程的狀态資料,其中一部分的日志如圖所示:

一次因線程池使用不當造成生産事故的排查記錄與思考

這兩個線程,名稱都是"pool-xxx-thread-xxx"的形式。

從Executors類中的靜态内部類DefaultThreadFactory源碼可知,預設線程工廠給線程池中的線程的取名規則就是這樣的格式。

一次因線程池使用不當造成生産事故的排查記錄與思考

 我們可以使用

grep -c "pool-" thread.log      

來統計被線程池管理的線程總數,得到8336個,而一共才9000多個。

看來這次事故和線程池脫不了關系了,對線程池不了解的同學,可以先移步我的另外一篇文章​​還好我接住了面試官對線程池的奪命連環問​​

接着使用

grep java.lang.Thread.State thread.log | awk '{print $2$3$4$5}' | sort | uniq -c      

按線程狀态分組統計,得到這樣的結果

40    RUNNABLE
5     TIMED_WAITING(onobjectmonitor)
63    TIMED_WAITING(parking)
12    TIMED_WAITING(sleeping)
73    WAITING(onobjectmonitor)
8100  WAITING(parking)      

RUNNABLE

代表線程已經執行了start方法,但還沒有獲得CPU時間片,得到時間片後,才會變成RUNNING的狀态。

TIMED_WAITING(onobjectmonitor)與WAITING(onobjectmonitor) 

當線程擷取螢幕鎖之後(一般是進入了synchronized方法),又調用了對象的wait或wait(time)方法,釋放了鎖,進入Wait Set中。

TIMED_WAITING(parking)與WAITING(parking)

當調用LockSupport.park就可以使得線程處于該狀态,之後線程會定時或非定時地等待unpark的到來。

TIMED_WAITING(sleeping)

調用sleep(time)方法就會處于該狀态,時間到了自動醒來。

是以,這邊我們可以得出結論,大量線程池中的線程處于WAITING(parking)的狀态。

我們随便(刻意)從日志中取到一個線程的運作堆棧資訊:

一次因線程池使用不當造成生産事故的排查記錄與思考

worker在運作的過程中,會使用getTask方法從阻塞隊列LinkedBlockQueue中擷取任務。因為此時沒有任務,是以被await方法阻塞,而await内部又會調用LockSupport的park方法,進而使得線程處于WAITING(parking)的狀态。

随便看了一些日志,基本上都是這樣,線程池中的大量線程因擷取不到任務處于阻塞的狀态。

排查到這裡,我不禁發出疑問,線程池到底在搞什麼鬼,都不幹活的嗎?

一次因線程池使用不當造成生産事故的排查記錄與思考

不經意的突破口

直到我在代碼裡搜尋使用到線程池的地方時,我瞥到了這樣一段代碼:

一次因線程池使用不當造成生産事故的排查記錄與思考

在該段代碼中,每次請求都會建立一個固定大小為10的線程池。但在處理完業務邏輯後,并沒有調用shutdown或者shutdownNow方法。

難道是這裡發生了線程洩露嗎?pool作為局部變量,在方法執行完成後,應該會在GC中被回收掉啊!

假設pool及内部的線程會一直保留在記憶體中,不會被GC回收,确實有可能造成開頭的現象。每個線程都會占用堆記憶體,最終造成OOM。

那麼,線程池作為局部變量,在方法執行後,線程池及内部的線程會在什麼時候進行回收呢?

實驗開始

那我們就做一個實驗吧,實地去驗證下:

@RequestMapping("/execute")
    public String execute() {

        ExecutorService pool = Executors.newFixedThreadPool(10, new MyThreadFactory());
        for (int i = 0; i < 20; i++) {
            pool.execute(() -> {
                try {
                    //模拟業務耗時
                    Thread.sleep(2000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            });
        }

        return "success";
    }

    static class MyThreadFactory implements ThreadFactory {
        private final AtomicInteger threadNumber = new AtomicInteger(1);

        @Override
        public Thread newThread(Runnable r) {
            String name = "MyThreadFactory-" + threadNumber.getAndIncrement();
            return new Thread(r, name);
        }
    }      

MyThreadFactory是自定義的一個線程工廠,應用到該線程工廠的線程池,内部産生的線程的名稱都有“MyThreadFactory”字首。

啟動這個SpringBoot項目,調用execute接口。這個時候産生的線程日志中,确實多出了10個線程。

一次因線程池使用不當造成生産事故的排查記錄與思考

借助JVisualVM工具

當然我們可以通過JVisualVM工具來檢視記憶體與線程總數,這個工具就在jdk安裝路徑的bin目錄中

一次因線程池使用不當造成生産事故的排查記錄與思考

jvm自動觸發GC,以及在我們手動觸發GC後,線程數基本沒有任何變化。

一次因線程池使用不當造成生産事故的排查記錄與思考

MyThreadFactory産生的10個線程依然駐留在記憶體中,并沒有被回收掉。

大膽的猜測

到這裡,我們已經确定,方法執行結束後,相關線程确實不會被回收。

如果對線程池有一個簡單的認識的話,一定會知道線程池會将Thread保證成一個Worker,展現在Worker類中有一個thread變量。

一次因線程池使用不當造成生産事故的排查記錄與思考

是以當Thread正在running或處于任何阻塞階段,就不會被銷毀,其Worker對象也不會被銷毀。

而Woker類又是ThreadPoolExecutor裡的一個非靜态的内部類,對于一個非靜态的内部類,在執行個體化時,會隐式地持有外部類的一個強引用,展現在編譯器會自動往内部類的構造函數中追加一個外部類參數。

是以目前woker對象又持有着線程池對象的強引用,是以線程池對象也不會被銷毀。不過我們再也通路不到該線程池對象,無法往該線程池中送出任何任務,進而造成了記憶體洩露。

源碼探究

那麼當我們退出方法後,線程池内部的線程究竟是處于什麼狀态呢?從上面的線程日志,其實可以得到一些線索——線程在阻塞擷取任務。

為什麼退出方法了,線程還處于阻塞狀态呢?又怎麼去釋放這些線程呢?

我們從pool.execute入手

當目前線程數小于核心線程數時,會調用addWorker,将使用者送出的任務封裝成worker。

一次因線程池使用不當造成生産事故的排查記錄與思考

 進入到addWorker方法中,省略一些代碼

一次因線程池使用不當造成生産事故的排查記錄與思考

 第一步會調用Woker的構造方法,會用到使用者傳入的Runnable任務。

看一下Woker的構造方法:

一次因線程池使用不當造成生産事故的排查記錄與思考

構造函數隻做了兩件事:

(1)将使用者的Runnable任務指派給了成員變量firstTask

(2)getThreadFactory.newThread(this)會調用我們自定義的線程工廠的newThread方法,參數是目前實作了Runnable接口的worker對象,并把生成的Thread對象指派給了成員變量thread。

addWorker第二步則是将生成的worker對象存入線程池的woker集合中

addWorker第三步則是調用worker成員變量thread的start方法,用于啟動worker線程

到這裡,我們可以知道,線程池并不是将使用者傳入的Runnable任務作為一個線程執行,而是将任務包裝成worker,轉而去執行woker線程。

調用worker的start方法,則虛拟機會在合适時間回調run方法,那我們直接進入Worker類的run方法中。

在上圖中,可以看到,run方法又調用了runWorker方法:

一次因線程池使用不當造成生産事故的排查記錄與思考

當初次進入while循環中,firstTask也就是使用者的Runnable任務,肯定不會為null,是以會直接調用firstTask的run方法,執行使用者任務,接着将firstTask置null。

當再次進入while循環中,firstTask為null,此時會調用getTask從阻塞隊列中擷取任務,如果getTask傳回null,則會退出while循環,目前worker線程也就結束了。

進入到getTask中:

一次因線程池使用不當造成生産事故的排查記錄與思考

如果allowCoreThreadTimeOut被指定為true,則代表允許回收達到指定空閑時間的核心線程。另外當線程總數大于核心線程數時,都會使得timed為true。

如果timed為true,則調用阻塞隊列中poll方法。當擷取任務逾時後,poll會傳回null,并會在下一次for循環中,getTask傳回null。

如果timed為false,則調用take方法,底層會使用到aqs,直到有任務後,該方法才會傳回。

也就是說,如果我們沒有設定allowCoreThreadTimeOut,那麼allowCoreThreadTimeOut就預設為false,核心線程就會一直被阻塞在getTask上。

其實線上程日志中,早已經暴露了調用鍊路。

一次因線程池使用不當造成生産事故的排查記錄與思考

 直到這裡,我們才恍然大悟,原來核心線程處于阻塞階段,自然不能被GC回收。

一次因線程池使用不當造成生産事故的排查記錄與思考

解決方案

局部線程池不太優雅,大可以使用一個全局線程池來做。如果你的業務就是需要用到局部線程池,去做一些隔離的事情。

那麼需要及時地去釋放核心線程與線程池,為了防止線程洩露,有以下的方式:

(1)從源碼探究一節中,我們了解到可以設定allowCoreThreadTimeOut,來讓線程池回收空閑達到指定時間的核心線程。

修改一下代碼

@RequestMapping("/execute")
    public String execute() {

        ThreadPoolExecutor pool = new ThreadPoolExecutor(
                10,
                10,
                3,
                TimeUnit.SECONDS,
                new LinkedBlockingQueue<>(),
                new MyThreadFactory());

        pool.allowCoreThreadTimeOut(true);

        for (int i = 0; i < 20; i++) {
            pool.execute(() -> {
                try {
                    //模拟業務耗時
                    Thread.sleep(2000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            });
        }
        
        return "success";
    }      

10個核心線程,20個任務,每個任務耗時2秒,空閑時間為3秒,那麼一個線程應該會存活2+2+3=7秒左右,接着觀察一下JVisualVM

一次因線程池使用不當造成生産事故的排查記錄與思考

 每個線程一共存活了大概7秒,和期望相符,最後會被GC回收。

 (2)在方法結束前調用shutdown,當然如果配合CountDownLatch,也可以直接調用shutdownNow。

執行shutdown後,中斷空閑任務,正在執行的線程會繼續執行下去,但不能往隊列中添加任務。線程池中所有任務被執行完成後,線程池才會退出。

執行shutdownNow後,中斷所有線程,線程池立即退出,并傳回未執行的任務清單。

是以不管是shutdown還是shutdownNow,都可以回收所有的線程,最終線程池也會被回收。

總結與思考

我們從看到unable to create new native thread開始,檢視了監控,發現線程數量飙升。

接着分析了線程堆棧日志,了解到線程池中的核心線程全部處于WAITING(parking)的狀态。

然後我們做了一個簡單的小實驗,通過JVisualVM工具觀測到局部變量的線程池中的核心線程并沒有被回收。

于是推斷出發生了線程洩露的情況,最後通過源碼探究的方式,尋找到了解決方案,設定allowCoreThreadTimeOut或執行shutdown。

繼續閱讀