high-thread-count.png

?? 目錄

• ?? 一個 Jenkins 實例啟動了近兩萬個線程监透？
• ?? 初步分析
• ??? 分析社區(qū)改動
• ?? 確認(rèn)線程泄露
• ?? 日志提供線索
• ??? 研讀代碼確認(rèn)問題
• ?? 問題確認(rèn)及修復(fù)
• ?? 收獲
• ?? 參考
• ?? 后續(xù)

?? 一個 Jenkins 實例啟動了兩萬多個線程？

工作時观挎，接到一個 Oncall 處理臭猜，用戶報告在生產(chǎn)環(huán)境遇到告警瓶珊，提示線程數(shù)目過多夹界，根據(jù)排查戈次，確認(rèn)是 Jenkins 相關(guān)的線程過多轩勘，達(dá)到了驚人的兩萬條

與用戶溝通后，得知用戶是通過類似如下命令獲得的線程信息怯邪，并且通過關(guān)鍵字分析是 Jenkins 產(chǎn)生的線程

ps -eLf|grep jenkins|wc -l

確認(rèn)是 Jenkins 線程問題后绊寻，通過如下方式獲取了相關(guān)的線程信息用于問題分析

jenkins/$ ps -ef
UID        PID  PPID  C STIME TTY          TIME CMD
jenkins      1     0  0 Oct23 ?        00:00:19 /usr/bin/tini -- /usr/local/bin/jenkins.sh
jenkins      7     1  0 Oct23 ?        00:00:00 /bin/bash -e /usr/local/bin/jenkins.sh
jenkins     20     7  1 Oct23 ?        01:27:36 java -Duser.home=/var/jenkins_home -xxxx
jenkins  26436     0  0 06:40 pts/0    00:00:00 bash
jenkins  26459 26436  0 06:42 pts/0    00:00:00 ps -ef

獲取到 Jenkins 相關(guān)進(jìn)程 PID 為 20，通過 jstack 獲取該進(jìn)程相關(guān)線程的信息擎颖，并且存儲到文件 stack.txt 中

jstack -l 20 > stack.txt

隨后使用可視化工具 fastthread 來進(jìn)行分析榛斯，可以看到現(xiàn)在的線程情況如下

crazy-threads.png

通過圖片可知，現(xiàn)在的線程數(shù)目異常的多搂捧，肯定是發(fā)生了線程泄露驮俗，而且泄露的線程都是處于 TIMED_WAITING 和 WAITTING 的狀態(tài)，由于我對 Java 其實并不熟悉允跑，查閱得知對應(yīng)的線程狀態(tài)如下

兩個線程數(shù)目都這么多，很難一網(wǎng)打盡垒拢，先從線程詳情分析下旬迹，哪里有線索，就先處理哪個

?? 初步分析

fastthread 有一個很不錯的功能求类，可以將堆棧一致的線程整理并且明晰的展示出來

由此看到處于 TIMED_WAITING 狀態(tài)的線程最多奔垦，而且 stackTrace 中提供的信息我也更加熟悉，因此決定先從這個入手處理

identical-stack-trace.png

通過 stacktrace 看到相關(guān)線程的堆棧如下:

stackTrace:
java.lang.Thread.State: TIMED_WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@11.0.18/Native Method)
- parking to wait for <0x00000005672c9328> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(java.base@11.0.18/LockSupport.java:234)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@11.0.18/AbstractQueuedSynchronizer.java:2123)
at java.util.concurrent.LinkedBlockingQueue.poll(java.base@11.0.18/LinkedBlockingQueue.java:458)
at io.kubernetes.client.extended.workqueue.DefaultDelayingQueue.waitingLoop(DefaultDelayingQueue.java:93)
at io.kubernetes.client.extended.workqueue.DefaultDelayingQueue$$Lambda$347/0x0000000800a1bc40.run(Unknown Source)
at java.util.concurrent.Executors$RunnableAdapter.call(java.base@11.0.18/Executors.java:515)
at java.util.concurrent.FutureTask.run(java.base@11.0.18/FutureTask.java:264)
at java.util.concurrent.ThreadPoolExecutor.runWorker(java.base@11.0.18/ThreadPoolExecutor.java:1128)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(java.base@11.0.18/ThreadPoolExecutor.java:628)
at java.lang.Thread.run(java.base@11.0.18/Thread.java:829)

觀察線程詳情尸疆，可以看到問題出現(xiàn)在io.kubernetes.client.extended.workqueue.DefaultDelayingQueue.waitingLoop(DefaultDelayingQueue.java:93) 椿猎，具體代碼在 DefaultDelayingQueue.java#L93，相關(guān)代碼如下

  private void waitingLoop() {
    try {
      while (true) {
        // underlying work-queue is shutting down, quit the loop.
        if (super.isShuttingDown()) {
          return;
        }
        // peek the first item from the delay queue
        WaitForEntry<T> entry = delayQueue.peek();
        // default next ready-at time to "never"
        Duration nextReadyAt = heartBeatInterval;
        
        ....

        # 這里就是第 93 行寿弱，也就是提示出現(xiàn)問題的位置
        WaitForEntry<T> waitForEntry =
            waitingForAddQueue.poll(nextReadyAt.toMillis(), TimeUnit.MILLISECONDS);
        if (waitForEntry != null) {
          if (Duration.between(waitForEntry.readyAtMillis, Instant.now()).isNegative()) {
            // the item is not yet ready, insert it to the delay-queue
            insert(this.delayQueue, this.waitingEntryByData, waitForEntry);
          } else {
            // the item is ready as soon as received, fire it to the work-queue directly
            super.add(waitForEntry.data);
          }
        }
      }
    } catch (InterruptedException e) {
      // empty block
    }
  }

查看 waitingForAddQueue.poll 的實現(xiàn)犯眠，可以得知該函數(shù)功能如下

• 等待 queue 中插入數(shù)據(jù)，如果 queue 中插入了數(shù)據(jù)脖捻，則立即將該數(shù)據(jù)返回
• 如果在一段時間內(nèi)沒有返回阔逼，則超時返回

在該庫 kubernetes-client/java 的 Issues 和 PullRequests 中也沒有發(fā)現(xiàn)類似的線程泄露問題

另外通過閱讀該項目代碼，了解到了這個 Jenkins 插件項目與這個庫的關(guān)系

• 該插件會通過該庫的 controller-manager 啟動五個 controller
• 每個 controller 會監(jiān)聽目標(biāo)集群某種特定資源的變化事件地沮，變化的事件會存儲到這個 queue 中
• 當(dāng) controller 監(jiān)聽的資源發(fā)生改動事件(增刪改)時嗜浮，會通過 queue 得到消息并且觸發(fā) controller 的 reconcile 的邏輯

現(xiàn)在 TIMED_WAITING 的線程全部卡在 waitingLoop queue 的 poll 這里，根據(jù)當(dāng)前已有的代碼信息摩疑，很難確認(rèn)問題是在哪里危融，不好確認(rèn)下一步方向

但是在分析該庫 kubernetes-client/java 時，注意到使用的版本已經(jīng)比較老舊了雷袋，社區(qū)最新版本已經(jīng)是 v21.0.1 了吉殃，但是我們使用的是 v11.0.0 的版本，因此先決定看下社區(qū)最新的版本是否已經(jīng)解決了類似問題

??? 分析社區(qū)改動

對比了最新 master 和 release-11 的相關(guān)代碼楷怒，發(fā)現(xiàn)存在一個類似相關(guān)的改動 Fix the default delay queue to use a fixed time source

根據(jù) commit message 與實際改動內(nèi)容蛋勺，判斷改動修復(fù)如下場景的問題

• 在計算 queue nextReady 超時時間時
• 在不同時區(qū)設(shè)置的場景下可能計算結(jié)果不同

感覺跟當(dāng)前遇到的問題并不是特別的相關(guān)，大致判斷是在中國時區(qū)下鸠删，這個值會被計算的無限大抱完，導(dǎo)致的在 queue 中始終無法結(jié)束？

為了驗證這個問題刃泡，采取了如下兩個驗證方案

1. 直接升級庫的版本到最新巧娱，但是有特別多的依賴問題碉怔，這個后面作為教訓(xùn)來討論，不作為解決問題的主線討論
2. 將 master 上的改動 fallback 到 release-11 中禁添，增加補充日志撮胧，自編譯產(chǎn)出依賴包來判斷是否可以解決問題

通過一番的依賴解決折騰后，將編譯出來的包部署到了私有 Nexus 中老翘，并且將使用該依賴的插件重新編譯芹啥，導(dǎo)入并重啟 Jenkins 進(jìn)行觀察

增加日志包括判斷是否超時時間計算存在錯誤，導(dǎo)致線程進(jìn)入后就會卡在這里酪捡，一直無法出來

根據(jù)增加的日志判斷叁征，時間計算一直都是沒問題的纳账，無論是 master 還是 release-11 上逛薇，超時時間都是 10s，所以可以基本判斷這個修改不能 fix 問題

并且后續(xù)觀察到的 Jenkins 線程數(shù)目變化也說明了這一點疏虫，相應(yīng)的線程數(shù)目仍然毫不收斂永罚，也說明了問題解決不會是這條路子

?? 確認(rèn)線程泄露

暫時沒什么處理思路，只能先基于當(dāng)前的情況再冷靜的分析一下

目前處在 TIMED_WAITTING 狀態(tài)并且在 waitingLoop 卡住的線程越來越多卧秘，分析一下大概可能有兩種原因

• 某些原因?qū)е碌囊恍┚€程有概率的進(jìn)入 waitingLoop 后一直卡住出不來呢袱，導(dǎo)致后續(xù)創(chuàng)建了新的線程來完成任務(wù)
• 總是有新的線程被創(chuàng)建，他們都在 waitingLoop 中循環(huán)翅敌，每次獲取線程快照時羞福，這些新建的線程正好都在執(zhí)行 poll 的操作

這兩種原因會決定后續(xù)排查方向，為了弄清楚這個問題蚯涮，增加日志來做類似的判斷治专，具體方式如下

在進(jìn)入 waittingLoop 邏輯時，生成一個隨機(jī)字符串 ID遭顶，在進(jìn)入 poll 邏輯之前打印這個 ID张峰，并且在 poll 邏輯之后也打印這個 ID，最終得到的結(jié)果如下

idin-idout.png

如圖中解釋棒旗，左側(cè)是從 poll 邏輯中出來的 ID 序號喘批，右側(cè)是剛剛進(jìn)入 poll 邏輯的 ID 序號

由此可以推斷，進(jìn)入 poll 邏輯的線程并不是第一種情況卡在 waittingLoop 中一直出不來铣揉，而是第二種情況饶深，執(zhí)行該邏輯的線程數(shù)目越來越多

（實際日志不是這么直接打印出來的，我通過使用 cursor AI 幫忙處理了一些數(shù)據(jù)逛拱，這個放在后面再聊 有時間可以聊一下這個工具敌厘，大概會介紹這么兩條

1. 確實可以寫一些簡單的腳本，高效的完成一些任務(wù)
2. 但是在處理一些問題的時候橘券，會有一些虛幻的回答额湘，搞笑的完成一些任務(wù)

貌似是到了它現(xiàn)在的頂卿吐，后續(xù)有時間可以專門總結(jié)下這個工具的使用情況)

好了，現(xiàn)在就可以明確是有越來越多的線程在執(zhí)行這個邏輯锋华，而不是線程進(jìn)入了這里之后出不來卡死嗡官，這兩種方式對應(yīng)的解決思路是不一樣的

但是到了這里，也只是確認(rèn)了大體問題方向毯焕，如何進(jìn)行下一步仍然是有些迷茫衍腥，controller 代碼處理看起來是正常的，正常的啟動 controller纳猫，功能上也沒有什么異常的地方婆咸，完全看不出問題出現(xiàn)在哪里

?? 日志提供線索

沒有線索，那就只能再從日志下手了芜辕，看看是否能找到什么線索(會考慮通過日志查找尚骄，這里也是經(jīng)驗所致，后面會提到這一點)

因為問題出現(xiàn)在 queue 身上侵续，所以瀏覽了一遍相關(guān)代碼倔丈，找出所有目前會打印的日志，通過日志中的關(guān)鍵字状蜗，搜索 Jenkins 的日志需五，果然在 Jenkins 的日志，發(fā)現(xiàn)了一些有用的日志信息

發(fā)現(xiàn)會有 Controller xxxx worker exiting because work-queue has shutdown.. 而且這些日志是規(guī)律輸出的轧坎，基本上每隔一個小時宏邮，就會有這些日志的輸出，這是一個很重要的線索缸血，通過這個線索蜜氨，得知了如下的信息

因此插件中有五個 controller 會監(jiān)聽 k8s 資源變化并且將資源改動對應(yīng)同步到 Jenkins 中，但是某個機(jī)制會導(dǎo)致這些 controller 會定期每隔一個小時全部重啟一次属百，此時就會關(guān)閉這個 work-queue 然后重啟

雖然會定時關(guān)閉记劝，但是不應(yīng)該導(dǎo)致線程數(shù)目攀升，因為看到代碼的具體邏輯族扰，在 cotroller shutdwon 的時候厌丑，也會將對應(yīng)的 queue 同時進(jìn)行關(guān)閉

  public void shutdown() {
    // shutdown work-queue before the thread-pool
    workQueue.shutDown();
    workerThreadPool.shutdown();
  }

那就不應(yīng)該存在線程泄露的問題

因此有理由搞清楚，在 queue 產(chǎn)生和回收的時候渔呵，是否還是存在差異怒竿，于是繼續(xù)為 work-queue 的代碼增加日志，在 work-queue 初始化和 work-queue 回收的地方扩氢，增加了相關(guān)的日志耕驰，果然發(fā)現(xiàn)了問題。

388 19:09:10: I am new created
413 19:09:10: I am new created
414 19:09:10: I am new created
416 19:09:10: I am new created
417 19:09:10: I am new created
419 19:09:10: I am new created
420 19:09:10: I am new created
422 19:09:10: I am new created
423 19:09:10: I am new created
426 19:09:10: I am new created
425 19:09:10: I am new created
281 19:09:19: I am really shutdown
303 19:09:19: I am really shutdown
309 19:09:19: I am really shutdown
306 19:09:19: I am really shutdown
315 19:09:19: I am really shutdown
312 19:09:19: I am really shutdown

通過日志可以看到录豺，controller 啟動的時候都會啟動 11 個 queue朦肘，但是在關(guān)閉的時候饭弓，卻只關(guān)閉 6 個 queue，其余的未被銷毀的線程仍然會存在

問題基本確認(rèn)了媒抠，那就在在代碼中增加日志打印調(diào)用棧弟断，看看哪里會調(diào)用創(chuàng)建 queue，為何與 controller 的數(shù)目不一樣

??? 研讀代碼確認(rèn)問題

通過堆棧獲知在下面這段用來構(gòu)建每個 controller 代碼中趴生，有兩個地方會創(chuàng)建 queue

queue = new DefaultRateLimitingQueue<>(Executors.newSingleThreadExecutor());

Controller controller =
    ControllerBuilder.defaultBuilder(factory)
        .withWorkQueue(queue)
        .watch(
            (workQueue) ->
        xxx
        .withName(CONTROLLER_NAME)
        .withWorkerCount(4)
        .build();

managerBuilder.addController(controller);

其中涉及到創(chuàng)建 queue 的代碼是下面這兩部分

1. ControllerBuilder.defaultBuilder(factory)
2. queue = new DefaultRateLimitingQueue<>(Executors.newSingleThreadExecutor());

第一個是在 controller 啟動時阀趴，初始化了一個 default queue，可以看到在 DefaultControllerBuilder() 初始化 ControllerBuilder 時苍匆，會默認(rèn)先啟動一個 queue 作為 defaultWorkQueue

第二個 queue 是在不想使用默認(rèn) queue 時刘急，新建一個 queue 來并且使用 .withWorkQueue() 替換默認(rèn)的 queue

以上就是這兩個會創(chuàng)建 queue 的地方

前面提到在 controller shutdown 的時候，會將 controller 相關(guān)的 queue shutdown浸踩，那這兩個 queue 為什么沒有被正確關(guān)閉呢叔汁？原因就在于這個 withWorkQueue 的實現(xiàn)，查看代碼發(fā)現(xiàn) withWorkQueue 的實現(xiàn)邏輯如下

public DefaultControllerBuilder withWorkQueue(RateLimitingQueue<Request> workQueue) {
  this.workQueue = workQueue;
  return this;
}

這里相當(dāng)于在調(diào)用 withWorkQueue() 的時候民轴，直接將新的 queue 替換了默認(rèn)的 queue攻柠，當(dāng) controller shutdown 時，它只能關(guān)閉當(dāng)前已經(jīng)被替換了的 queue后裸，至于原始的默認(rèn)的 queue，這個 controller 已經(jīng)丟失了對應(yīng)的引用冒滩，無法再將其關(guān)閉了

這也就是為什么會創(chuàng)建 11 個 queue微驶，但是只關(guān)閉 6 個的原因（其中某個 controller 使用的默認(rèn)的 queue，沒有通過 withWorkQueue 覆蓋默認(rèn)的 queue开睡，所以會創(chuàng)建 5x2+1=11 個 queue）

?? 問題確認(rèn)及修復(fù)

問題已經(jīng)確認(rèn)因苹，剩下的問題要考慮如何解決該問題

雖然可以有一些手段暫時繞過這個問題，比如不調(diào)用 withWorkQueue 來覆蓋 default queue篇恒，但是都不是長久之計扶檐，如果其他同學(xué)不了解，踩了這個坑的話胁艰，還是要費大力氣來查找修復(fù)

索性直接在開源社區(qū)修復(fù)款筑，在覆蓋舊的 workqueue 的時候，先將之前的 workqueue 關(guān)閉腾么，也正好可以看看社區(qū)是否認(rèn)可這個 Bug 和解決方案

因此先提交了一個 Issue When building a controller with DefaultControllerBuilder and overriding the queue with withWorkQueue, there will be a thread leakage issue. 描述清楚嘞情況奈梳，并且附上了一個修復(fù)問題的 PR Shutdown original queue before override，社區(qū)在兩天內(nèi) approve 了這個改動合并到了 master解虱，看起來社區(qū)也是認(rèn)可這個 Bug 和解決方案的

雖然社區(qū)在兩天內(nèi)同意了該 PR攘须，但是對后續(xù)合并到老舊版本并無什么興趣

因此決定 fork 社區(qū)版本 release-11 的版本，將改動 cherry-pick 到 fork 的 release-11 的倉庫中殴泰，通過流水線 maven 構(gòu)建推送到私有 Nexus 中于宙，并且在 Jenkins 插件編譯的過程中使用私有編譯的版本

這之后再觀察線程泄露浮驳，果然好了很多，即使多次重啟 controller manager 線程的變化幅度也不大捞魁，終于可以松口氣了

?? 收獲

問題解決肯定不是一帆風(fēng)順的抹恳，過程是曲折的，折磨人的署驻，借這次總結(jié)這個問題的機(jī)會奋献，有幾點經(jīng)驗忍不住想要分享一下，給大家提供解決問題的一些看法

積極的尋求團(tuán)隊幫助

這種情況下旺上，要尋求團(tuán)隊的幫助瓶蚂，大概有一下兩點

1. 坦誠透明的告訴團(tuán)隊成員，自己遇到了問題宣吱，它真的有些難窃这，不是很好解決
2. 告訴團(tuán)隊自己卡在了哪里，交流一下想法征候，看看是否有更好的解決思路

第一點是同步自己的進(jìn)展?fàn)顟B(tài)杭攻，而不是自己在這里瞎扛自壓力，第二點是與同事多交流疤坝，也許他們會有好的解決辦法

冷靜的思考

冷靜的思考兆解，制定下一步的解決方向，與之相反的是一個勁兒的瞎試

猜猜可能是這的原因跑揉，改一下編譯一下復(fù)現(xiàn)一下锅睛，猜一下改一下編譯一下復(fù)現(xiàn)一下，毫無根據(jù)的猜測和嘗試历谍，會消磨掉你的耐心和精力现拒，這樣浪費的時間，還不如你用來放空一會望侈，歇歇你的腦子

在做每一步之前印蔬，都要考慮清楚我要做什么來幫助我判斷，我做的這個事情能否幫助我判斷脱衙，是否有更好的辦法來幫助我做判斷

關(guān)于日志

日志這部分是跟這次不大相關(guān)侥猬，是之前排查問題得到的經(jīng)驗

日志應(yīng)該類似于小說，包含時間地點人物事件岂丘，也就是他應(yīng)該能充分說明我是誰陵究，在什么時間點什么地方做了什么事情

與之相反的是，隨便打印一個不知道什么的日志奥帘，沒有格式也不知道是哪一部分打印出來的铜邮，滿屏的日志打印出來，把自己也打印懵了

?? 參考

豆包大模型工具(國產(chǎn)的大模型確實不錯，某些回答甚至比 Gemini 和 ChatGPT 要強(qiáng))

fastthread 可視化分析線程工具松蒜，我使用這個工具多次解決了 Jenkins/Java 線程問題

?? 后續(xù)

你以為問題結(jié)束了嗎扔茅，其實并沒有

記得上面提到的我們遇到的是兩種線程狀態(tài)的問題嗎，一種是 TIMED_WAITTING秸苗，還有一種是 WAITTING

目前我們解決的只是 TIMED_WAITTING 狀態(tài)的線程問題召娜，之前以為這兩者可能是關(guān)聯(lián)的，解決完一個惊楼，或許另一個也就消失了玖瘸，但是實時并非如此

在觀察了幾天之后，發(fā)現(xiàn)線程數(shù)目雖然看起來正常了檀咙，但是還是會有輕微的上漲 (之前是每小時泄露 100 個雅倒，現(xiàn)在是每天 50 個線程)，所以問題還是沒有徹底解決弧可，這艘船上的大洞雖然補好了蔑匣，但是還有一些小窟窿要補，所以還是需要繼續(xù)分析...

這部分我放到下個文章中再介紹啦! See you later!