Tomcat需要很长时间才能识别spring-boot应用程序的启动

Posted 2023-02-26

【中文标题】Tomcat需要很长时间才能识别spring-boot应用程序的启动

【英文标题】：Tomcat requires long time to recognizes the start of spring-boot application

【发布时间】：2021-09-22 15:33:06

【问题描述】：

在将打包为war 的SpringBootApplication 部署到tomcat 服务器时遇到一个奇怪的问题。

虽然应用程序启动成功，但有时tomcat服务器无法识别应用程序启动（或者更准确地说，它需要很长时间）。 - 如果我说成功，我的意思是应用程序可以执行备份作业，例如cron 工作，访问其数据库并通过 SOAP 连接到第 3 方服务。

tomcat 服务器无法识别启动时的问题是应用程序的REST 端点无法访问，更糟糕的是，如果我在应用程序放在 webapps 文件夹时重新启动了 tomcat 服务器，整个 tomcat 服务器将被冻结。

说实话，我不知道可能是什么问题，甚至不知道从哪里开始寻找。

我怀疑，不知何故，自定义ThreadPoolTaskScheduler（见下文）会触发此问题。但即使我将池大小设置为 1，也会出现此问题。

从显示启动时间的日志文件中提取：

正常启动： 应用程序日志文件：Started CrewAlertApplication in 17.358 seconds (JVM running for 58.215) catalina.out: Deployment of web application archive [/srv/prod/cpappp/tomcat/webapps/crew-alert##1.2.1.war] has finished in [21.691] ms 启动缓慢： 应用程序日志文件：Started CrewAlertApplication in 25.161 seconds (JVM running for 75.633) catalina.out: Deployment of web application archive [/srv/prod/cpappp/tomcat/webapps/crew-alert##1.2.1.war] has finished in [1.056.389] ms

---

这里有一些关于环境的信息：

Tomcat（在VMWare 机器上运行，有 4 个内核）

Server Version:        Apache Tomcat/9.0.43
Server built:          Jan 28 2021 20:25:45 UTC
Server version number: 9.0.43.0
OS Name:               Linux
OS Version:            5.8.0-0.bpo.2-amd64
Architektur:           amd64
Java Home:             /srv/jdk-11.0.9+11
JVM Version:           11.0.9+11
JVM Hersteller:        Eclipse OpenJ9

应用程序本身基于：

SpringBoot：2.0.5 java: 11 如上所述，我们使用自定义ThreadPoolTaskScheduler

@Bean
public ThreadPoolTaskScheduler threadPoolTaskScheduler() 
    ThreadPoolTaskScheduler threadPoolTaskScheduler = new ThreadPoolTaskScheduler();
    threadPoolTaskScheduler.setPoolSize(5);
    threadPoolTaskScheduler.setThreadNamePrefix("CrewAlertThreadPool");
    threadPoolTaskScheduler.setRemoveOnCancelPolicy(true);
    return threadPoolTaskScheduler;

---

下图显示了 Tomcat 管理器。启动tomcat，然后部署应用程序（部署在tomcat上的其他应用程序都启动成功）。

一段时间后，tomcat 管理器显示应用程序已成功启动

---

更新 1：

正如@AndyWilkinson 指出的那样，问题出现在我的@EventListener 方法中，该方法调用了JpaRepository 方法

List<ScheduledNotification> findByScheduledTimeBetween(ZonedDateTime from, ZonedDateTime to)

被“翻译”成

Hibernate: select scheduledn0_.id as id1_6_, scheduledn0_.alert_id as alert_id3_6_, scheduledn0_.scheduled_time as scheduled_time2_6_ 
    from scheduled_notification scheduledn0_
    where scheduledn0_.scheduled_time between ? and ?

以下是实体的摘录：

@Entity(name = "SCHEDULED_NOTIFICATION")
@Table(indexes =  @Index(name = "IDX_SCHED_NOTIF_SCHEDTIME", columnList = "SCHEDULED_TIME") )
public class ScheduledNotification extends AbstractId implements Comparable<ScheduledNotification> 
    @ManyToOne(optional = false)
    @JoinColumn(name = "ALERT_ID", nullable = false)
    private Alert alert;

    @Column(name = "SCHEDULED_TIME", nullable = false, columnDefinition = "TIMESTAMP")
    @Convert(converter = ZonedDateTimeConverterUtc.class)
    private ZonedDateTime scheduledTime;

    @OneToMany(mappedBy = "scheduledNotification", cascade = ALL, orphanRemoval = true, fetch = EAGER)
    private Set<Leg> legs;
    ...

这个电话实际上需要将近 18 分钟。这有点令人惊讶，因为该表从未包含超过 100 个条目（在本例中返回 3 个结果）。

2021-07-14 12:53:34.506  INFO [] --- [Catalina-utility-3] c.lalacomp.alert.CrewAlertApplication    : Started CrewAlertApplication in 26.577 seconds (JVM running for 108237.294)
2021-07-14 12:53:34.509  INFO [] --- [Catalina-utility-3] c.l.a.scheduler.NotificationExecutor     : ApplicationReadyEvent received.
2021-07-14 12:53:34.528 DEBUG [] --- [Catalina-utility-3] c.l.a.s.ScheduledNotificationServiceImpl : findImmediate() - Looking up schedules between: 2021-07-14T10:38:34Z[UTC] and 2021-07-14T11:08:34Z[UTC]
2021-07-14 12:53:34.572  INFO [] --- [Catalina-utility-3] o.h.h.i.QueryTranslatorFactoryInitiator  : HHH000397: Using ASTQueryTranslatorFactory
...
2021-07-14 13:11:27.637 TRACE [] --- [Catalina-utility-3] c.l.a.s.ScheduledNotificationServiceImpl : We've found: ...
2021-07-14 13:11:27.639  INFO [] --- [Catalina-utility-3] c.l.a.scheduler.NotificationExecutor     : Adding 3 new ScheduledNotifications at startup.
...

等等，时间戳确实匹配，应用程序被识别为正在运行：

14-Jul-2021 13:11:27.662 INFORMATION [Catalina-utility-3] org.apache.catalina.startup.HostConfig.deployWAR Deployment of web application archive [/srv/prod/cpappp/tomcat/webapps/crew-alert##1.2.2.war] has finished in [1.103.405] ms

所以现在我必须弄清楚，为什么这需要这么长时间？因为对数据库（其他表）的其他查询正常执行。

更新 2：

如果我直接在控制台上运行类似的sql 语句，运行时绝对没问题。

select * from scheduled_notification sn
    join leg l on sn.id = l.SCHEDULED_NOTIFICATION_ID
    join alert a on sn.ALERT_ID = a.id
    where scheduled_time between SYSTIMESTAMP and SYSTIMESTAMP + 2 /24;

Fetched 30 rows in 0.015 secs

我还想知道为什么上面的 Hibernate 语句（更新 1）不包括“加入关系”。

【问题讨论】：

当应用程序似乎已启动但 Tomcat 没有注意到时，您能否进行线程转储？

谢谢@AndyWilkinson，你可以在这里找到转储：dropbox.com/s/qb8edzl976wehnd/…

是Catalina-utility-3 线程正在部署应用程序。线程转储显示您的应用程序有一个ApplicationReadyEvent 的侦听器。此侦听器调用了一些使用 Hibernate 与您的 Oracle DB 对话的代码，这就是它在执行线程转储时所做的事情。如果这需要很长时间，则不可能从单个转储中判断出来，但这就是我要开始调查的地方。也许您可以启用一些 Hibernate 或 Oracle JDBC 驱动程序日志记录，以了解与 DB 对话时所花费的时间。

正确，@EventListener 方法花费了这么多时间 - 或者更准确地说是调用 JpaRepository 方法 findByScheduledTimeBetween(ZonedDateTime from, ZonedDateTime to) - 这有点令人惊讶，因为这个表只包含最多最大限度。 100 个条目。该方法在将近 18 分钟后返回。我将使用日志文件中的摘要更新问题。

【参考方案1】：

正如@AndyWilkinson 指出的，问题出在ApplicationReadyEvent。在连接到此事件的方法中，我从数据库中获取数据，由于一些昂贵的关系，这花费了很长时间。

我更新了实体并简化了其中的一些关系。现在该方法按预期执行。

非常感谢 Andy！