high-thread-count.png

📜 目录

• 😮 一个 Jenkins 实例启动了近两万个线程？
• 🔍 初步分析
• 🏘️ 分析社区改动
• 🌟 确认线程泄露
• 🔑 日志提供线索
• 🕵️ 研读代码确认问题
• 🚀 问题确认及修复
• 🤔 收获
• 🥰 参考
• 💥 后续

😮 一个 Jenkins 实例启动了两万多个线程？

工作时，接到一个 Oncall 处理，用户报告在生产环境遇到告警，提示线程数目过多，根据排查，确认是 Jenkins 相关的线程过多，达到了惊人的两万条

与用户沟通后，得知用户是通过类似如下命令获得的线程信息，并且通过关键字分析是 Jenkins 产生的线程

ps -eLf|grep jenkins|wc -l

确认是 Jenkins 线程问题后，通过如下方式获取了相关的线程信息用于问题分析

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 相关进程 PID 为 20，通过 jstack 获取该进程相关线程的信息，并且存储到文件 stack.txt 中

jstack -l 20 > stack.txt

随后使用可视化工具 fastthread 来进行分析，可以看到现在的线程情况如下

crazy-threads.png

通过图片可知，现在的线程数目异常的多，肯定是发生了线程泄露，而且泄露的线程都是处于 TIMED_WAITING 和 WAITTING 的状态，由于我对 Java 其实并不熟悉，查阅得知对应的线程状态如下

两个线程数目都这么多，很难一网打尽，先从线程详情分析下，哪里有线索，就先处理哪个

🔍 初步分析

fastthread 有一个很不错的功能，可以将堆栈一致的线程整理并且明晰的展示出来

由此看到处于 TIMED_WAITING 状态的线程最多，而且 stackTrace 中提供的信息我也更加熟悉，因此决定先从这个入手处理

identical-stack-trace.png

通过 stacktrace 看到相关线程的堆栈如下:

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)

观察线程详情，可以看到问题出现在io.kubernetes.client.extended.workqueue.DefaultDelayingQueue.waitingLoop(DefaultDelayingQueue.java:93) ，具体代码在 DefaultDelayingQueue.java#L93，相关代码如下

  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 行，也就是提示出现问题的位置
        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 的实现，可以得知该函数功能如下

• 等待 queue 中插入数据，如果 queue 中插入了数据，则立即将该数据返回
• 如果在一段时间内没有返回，则超时返回

在该库 kubernetes-client/java 的 Issues 和 PullRequests 中也没有发现类似的线程泄露问题

另外通过阅读该项目代码，了解到了这个 Jenkins 插件项目与这个库的关系

• 该插件会通过该库的 controller-manager 启动五个 controller
• 每个 controller 会监听目标集群某种特定资源的变化事件，变化的事件会存储到这个 queue 中
• 当 controller 监听的资源发生改动事件(增删改)时，会通过 queue 得到消息并且触发 controller 的 reconcile 的逻辑

现在 TIMED_WAITING 的线程全部卡在 waitingLoop queue 的 poll 这里，根据当前已有的代码信息，很难确认问题是在哪里，不好确认下一步方向

但是在分析该库 kubernetes-client/java 时，注意到使用的版本已经比较老旧了，社区最新版本已经是 v21.0.1 了，但是我们使用的是 v11.0.0 的版本，因此先决定看下社区最新的版本是否已经解决了类似问题

🏘️ 分析社区改动

对比了最新 master 和 release-11 的相关代码，发现存在一个类似相关的改动 Fix the default delay queue to use a fixed time source

根据 commit message 与实际改动内容，判断改动修复如下场景的问题

• 在计算 queue nextReady 超时时间时
• 在不同时区设置的场景下可能计算结果不同

感觉跟当前遇到的问题并不是特别的相关，大致判断是在中国时区下，这个值会被计算的无限大，导致的在 queue 中始终无法结束？

为了验证这个问题，采取了如下两个验证方案

1. 直接升级库的版本到最新，但是有特别多的依赖问题，这个后面作为教训来讨论，不作为解决问题的主线讨论
2. 将 master 上的改动 fallback 到 release-11 中，增加补充日志，自编译产出依赖包来判断是否可以解决问题

通过一番的依赖解决折腾后，将编译出来的包部署到了私有 Nexus 中，并且将使用该依赖的插件重新编译，导入并重启 Jenkins 进行观察

增加日志包括判断是否超时时间计算存在错误，导致线程进入后就会卡在这里，一直无法出来

根据增加的日志判断，时间计算一直都是没问题的，无论是 master 还是 release-11 上，超时时间都是 10s，所以可以基本判断这个修改不能 fix 问题

并且后续观察到的 Jenkins 线程数目变化也说明了这一点，相应的线程数目仍然毫不收敛，也说明了问题解决不会是这条路子

🌟 确认线程泄露

暂时没什么处理思路，只能先基于当前的情况再冷静的分析一下

目前处在 TIMED_WAITTING 状态并且在 waitingLoop 卡住的线程越来越多，分析一下大概可能有两种原因

• 某些原因导致的一些线程有概率的进入 waitingLoop 后一直卡住出不来，导致后续创建了新的线程来完成任务
• 总是有新的线程被创建，他们都在 waitingLoop 中循环，每次获取线程快照时，这些新建的线程正好都在执行 poll 的操作

这两种原因会决定后续排查方向，为了弄清楚这个问题，增加日志来做类似的判断，具体方式如下

在进入 waittingLoop 逻辑时，生成一个随机字符串 ID，在进入 poll 逻辑之前打印这个 ID，并且在 poll 逻辑之后也打印这个 ID，最终得到的结果如下

idin-idout.png

如图中解释，左侧是从 poll 逻辑中出来的 ID 序号，右侧是刚刚进入 poll 逻辑的 ID 序号

由此可以推断，进入 poll 逻辑的线程并不是第一种情况卡在 waittingLoop 中一直出不来，而是第二种情况，执行该逻辑的线程数目越来越多

（实际日志不是这么直接打印出来的，我通过使用 cursor AI 帮忙处理了一些数据，这个放在后面再聊 有时间可以聊一下这个工具，大概会介绍这么两条

1. 确实可以写一些简单的脚本，高效的完成一些任务
2. 但是在处理一些问题的时候，会有一些虚幻的回答，搞笑的完成一些任务

貌似是到了它现在的顶，后续有时间可以专门总结下这个工具的使用情况)

好了，现在就可以明确是有越来越多的线程在执行这个逻辑，而不是线程进入了这里之后出不来卡死，这两种方式对应的解决思路是不一样的

但是到了这里，也只是确认了大体问题方向，如何进行下一步仍然是有些迷茫，controller 代码处理看起来是正常的，正常的启动 controller，功能上也没有什么异常的地方，完全看不出问题出现在哪里

🔑 日志提供线索

没有线索，那就只能再从日志下手了，看看是否能找到什么线索(会考虑通过日志查找，这里也是经验所致，后面会提到这一点)

因为问题出现在 queue 身上，所以浏览了一遍相关代码，找出所有目前会打印的日志，通过日志中的关键字，搜索 Jenkins 的日志，果然在 Jenkins 的日志，发现了一些有用的日志信息

发现会有 Controller xxxx worker exiting because work-queue has shutdown.. 而且这些日志是规律输出的，基本上每隔一个小时，就会有这些日志的输出，这是一个很重要的线索，通过这个线索，得知了如下的信息

因此插件中有五个 controller 会监听 k8s 资源变化并且将资源改动对应同步到 Jenkins 中，但是某个机制会导致这些 controller 会定期每隔一个小时全部重启一次，此时就会关闭这个 work-queue 然后重启

虽然会定时关闭，但是不应该导致线程数目攀升，因为看到代码的具体逻辑，在 cotroller shutdwon 的时候，也会将对应的 queue 同时进行关闭

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

那就不应该存在线程泄露的问题

因此有理由搞清楚，在 queue 产生和回收的时候，是否还是存在差异，于是继续为 work-queue 的代码增加日志，在 work-queue 初始化和 work-queue 回收的地方，增加了相关的日志，果然发现了问题。

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，但是在关闭的时候，却只关闭 6 个 queue，其余的未被销毁的线程仍然会存在

问题基本确认了，那就在在代码中增加日志打印调用栈，看看哪里会调用创建 queue，为何与 controller 的数目不一样

🕵️ 研读代码确认问题

通过堆栈获知在下面这段用来构建每个 controller 代码中，有两个地方会创建 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);

其中涉及到创建 queue 的代码是下面这两部分

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

第一个是在 controller 启动时，初始化了一个 default queue，可以看到在 DefaultControllerBuilder() 初始化 ControllerBuilder 时，会默认先启动一个 queue 作为 defaultWorkQueue

第二个 queue 是在不想使用默认 queue 时，新建一个 queue 来并且使用 .withWorkQueue() 替换默认的 queue

以上就是这两个会创建 queue 的地方

前面提到在 controller shutdown 的时候，会将 controller 相关的 queue shutdown，那这两个 queue 为什么没有被正确关闭呢？原因就在于这个 withWorkQueue 的实现，查看代码发现 withWorkQueue 的实现逻辑如下

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

这里相当于在调用 withWorkQueue() 的时候，直接将新的 queue 替换了默认的 queue，当 controller shutdown 时，它只能关闭当前已经被替换了的 queue，至于原始的默认的 queue，这个 controller 已经丢失了对应的引用，无法再将其关闭了

这也就是为什么会创建 11 个 queue，但是只关闭 6 个的原因（其中某个 controller 使用的默认的 queue，没有通过 withWorkQueue 覆盖默认的 queue，所以会创建 5x2+1=11 个 queue）

🚀 问题确认及修复

问题已经确认，剩下的问题要考虑如何解决该问题

虽然可以有一些手段暂时绕过这个问题，比如不调用 withWorkQueue 来覆盖 default queue，但是都不是长久之计，如果其他同学不了解，踩了这个坑的话，还是要费大力气来查找修复

索性直接在开源社区修复，在覆盖旧的 workqueue 的时候，先将之前的 workqueue 关闭，也正好可以看看社区是否认可这个 Bug 和解决方案

因此先提交了一个 Issue When building a controller with DefaultControllerBuilder and overriding the queue with withWorkQueue, there will be a thread leakage issue. 描述清楚嘞情况，并且附上了一个修复问题的 PR Shutdown original queue before override，社区在两天内 approve 了这个改动合并到了 master，看起来社区也是认可这个 Bug 和解决方案的

虽然社区在两天内同意了该 PR，但是对后续合并到老旧版本并无什么兴趣

因此决定 fork 社区版本 release-11 的版本，将改动 cherry-pick 到 fork 的 release-11 的仓库中，通过流水线 maven 构建推送到私有 Nexus 中，并且在 Jenkins 插件编译的过程中使用私有编译的版本

这之后再观察线程泄露，果然好了很多，即使多次重启 controller manager 线程的变化幅度也不大，终于可以松口气了

🧐 收获

问题解决肯定不是一帆风顺的，过程是曲折的，折磨人的，借这次总结这个问题的机会，有几点经验忍不住想要分享一下，给大家提供解决问题的一些看法

积极的寻求团队帮助

这种情况下，要寻求团队的帮助，大概有一下两点

1. 坦诚透明的告诉团队成员，自己遇到了问题，它真的有些难，不是很好解决
2. 告诉团队自己卡在了哪里，交流一下想法，看看是否有更好的解决思路

第一点是同步自己的进展状态，而不是自己在这里瞎扛自压力，第二点是与同事多交流，也许他们会有好的解决办法

冷静的思考

冷静的思考，制定下一步的解决方向，与之相反的是一个劲儿的瞎试

猜猜可能是这的原因，改一下编译一下复现一下，猜一下改一下编译一下复现一下，毫无根据的猜测和尝试，会消磨掉你的耐心和精力，这样浪费的时间，还不如你用来放空一会，歇歇你的脑子

在做每一步之前，都要考虑清楚我要做什么来帮助我判断，我做的这个事情能否帮助我判断，是否有更好的办法来帮助我做判断

关于日志

日志这部分是跟这次不大相关，是之前排查问题得到的经验

日志应该类似于小说，包含时间地点人物事件，也就是他应该能充分说明我是谁，在什么时间点什么地方做了什么事情

与之相反的是，随便打印一个不知道什么的日志，没有格式也不知道是哪一部分打印出来的，满屏的日志打印出来，把自己也打印懵了

🥰 参考

豆包大模型工具(国产的大模型确实不错，某些回答甚至比 Gemini 和 ChatGPT 要强)

fastthread 可视化分析线程工具，我使用这个工具多次解决了 Jenkins/Java 线程问题

💥 后续

你以为问题结束了吗，其实并没有

记得上面提到的我们遇到的是两种线程状态的问题吗，一种是 TIMED_WAITTING，还有一种是 WAITTING

目前我们解决的只是 TIMED_WAITTING 状态的线程问题，之前以为这两者可能是关联的，解决完一个，或许另一个也就消失了，但是实时并非如此

在观察了几天之后，发现线程数目虽然看起来正常了，但是还是会有轻微的上涨 (之前是每小时泄露 100 个，现在是每天 50 个线程)，所以问题还是没有彻底解决，这艘船上的大洞虽然补好了，但是还有一些小窟窿要补，所以还是需要继续分析...

这部分我放到下个文章中再介绍啦! See you later!