high-thread-count.png

?? 目錄

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

?? 一個 Jenkins 實(shí)例啟動了兩萬多個線程？

工作時，接到一個 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 其實(shí)并不熟悉，查閱得知對應(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 的實(shí)現(xiàn)，可以得知該函數(shù)功能如下

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

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

另外通過閱讀該項(xiàng)目代碼，了解到了這個 Jenkins 插件項(xiàng)目與這個庫的關(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 與實(shí)際改動內(nèi)容，判斷改動修復(fù)如下場景的問題

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

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

為了驗(yàn)證這個問題，采取了如下兩個驗(yàn)證方案

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

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

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

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

并且后續(xù)觀察到的 Jenkins 線程數(shù)目變化也說明了這一點(diǎn)，相應(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ù)目越來越多

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

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

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

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

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

?? 日志提供線索

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

因?yàn)閱栴}出現(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ù)目攀升，因?yàn)榭吹酱a的具體邏輯，在 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 的實(shí)現(xiàn)，查看代碼發(fā)現(xiàn) withWorkQueue 的實(shí)現(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，但是都不是長久之計(jì)，如果其他同學(xué)不了解，踩了這個坑的話，還是要費(fèi)大力氣來查找修復(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ī)會，有幾點(diǎn)經(jīng)驗(yàn)忍不住想要分享一下，給大家提供解決問題的一些看法

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

這種情況下，要尋求團(tuán)隊(duì)的幫助，大概有一下兩點(diǎn)

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

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

冷靜的思考

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

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

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

關(guān)于日志

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

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

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

?? 參考

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

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

?? 后續(xù)

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

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

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

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

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