SpringBoot 应用程序中的线程计数每天午夜都会出现异常峰值

Question

应用程序上下文：我们目前正在部署一个基于

spring-boot:3.2.0

的应用程序，其中涉及使用

spring-boot-starter-web

向客户端公开的基于 REST 的 API，通过

org.springframework.boot:spring-boot-starter-data-elasticsearch

与我们的数据存储集成，并由基于

 的内存缓存进行补充。 com.github.ben-manes.caffeine:caffeine

并使用

org.springframework.kafka:spring-kafka

。

问题：每天午夜 00:00，我们应用程序的线程数会达到峰值，之后很少有线程被终止，导致我们的应用程序每天的线程数不断增加，有时会导致 Pod 重新启动（怀疑这是由于随着内存使用量的增加而出现 OOM）。

观察：在此期间，基于 REST 的请求或消息消耗管道的吞吐量模式几乎没有偏差。

---

尝试：因此，我们尝试分析应用程序的线程转储，并比较不同两天的转储。可见的主要方面之一是我们的应用程序中有大量

timed_waiting

的线程。

这些的堆栈跟踪看起来像

"http-nio-8080-exec-61" #37660 [37664] daemon prio=5 os_prio=0 cpu=38462.67ms elapsed=46889.40s tid=0x00007f2e0c0557b0 nid=37664 waiting on condition [0x00007f2ddf2fe000]
java.lang.Thread.State: TIMED_WAITING (parking)
at jdk.internal.misc.Unsafe.park(java.base@21/Native Method)
- parking to wait for <0x0000000684f26058> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
at java.util.concurrent.locks.LockSupport.parkNanos(java.base@21/LockSupport.java:269)
at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(java.base@21/AbstractQueuedSynchronizer.java:1758)
at java.util.concurrent.LinkedBlockingQueue.poll(java.base@21/LinkedBlockingQueue.java:460)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:99)
at org.apache.tomcat.util.threads.TaskQueue.poll(TaskQueue.java:33)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1113)
at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1176)
at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.runWith(java.base@21/Thread.java:1596)
at java.lang.Thread.run(java.base@21/Thread.java:1583)

---

寻求帮助：但从这里开始，我们目前不知道该往哪个方向看。期待来自社区的一些提示：

1. 提到的库之一是否可以有一些默认配置来在 00:00 准确地执行 JVM 内部的某些任务？
2. 根据转储的堆栈跟踪，我们如何找出许多线程正在等待的对象是由哪个进程创建的？ （附加信息）

注意 - 如果有帮助，我可以共享线程转储，并在该应用程序需要时提供更多信息。正如我所说，我们的应用程序每天晚上都会发生这种情况。

---

更新：设置中应用程序覆盖的 Web 和 tomcat 属性包括：

spring.servlet.multipart.max-file-size=10MB
spring.servlet.multipart.max-request-size=10MB
server.servlet.context-path=/places/api

server.tomcat.accesslog.enabled=true
server.tomcat.accesslog.suffix=.log
server.tomcat.accesslog.prefix=access_log
server.tomcat.accesslog.file-date-format=.yyyy-MM-dd
server.tomcat.accesslog.pattern=%h %l %t "%r" %s %b "%{Referer}i" "%{User-Agent}i" %D
server.tomcat.accesslog.rotate=true
server.tomcat.basedir=/var/log
server.tomcat.accesslog.directory=places
server.tomcat.accesslog.max-days=7

Answer 1

第一阶段：

感谢用户的评论，这促使我调查应用程序的非默认配置。在我们的案例中，我们正在处理以下问题：

server.tomcat.accesslog.file-date-format=.yyyy-MM-dd
server.tomcat.accesslog.rotate=true

这意味着每天的00:00时间戳我们的日志文件都会被轮换为更新的文件名。这导致多个 Tomcat 线程处于

timed_waiting

状态。

将轮换持续时间从“一天”更改为“一个月”后，可以感受到影响 - 午夜期间线程数增加并不明显。但是，对于我们的应用程序来说，某些线程仍然以奇数间隔导致 timed_waiting 状态。

第二阶段

---

进一步检查应用程序的线程转储后，我们仍然怀疑日志记录。我们发现我们正在使用 GCP 上的 K8s 集群跨多个 Pod（在我们的例子中是三个）部署应用程序，每个日志记录到已安装磁盘上的

相同的访问日志文件。我怀疑这会对线程进入等待状态以引起我们的注意产生重大影响。 我使用添加到日志文件（包括应用程序日志、访问日志和 gc 日志）中的基于 pod 的

前缀

来验证这些内容。这帮助我们在几天内恢复了应用程序的正常执行。