Spring boot 에서 종료되지 않은 스레드 모니터링 하기

WEB개발/백엔드

Spring boot 에서 종료되지 않은 스레드 모니터링 하기

iks15174 2025. 5. 5. 21:49

목표

애플리케이션을 개발하던 중 spring boot가 종료될 때 기존에 진행 중이던 작업들이 어떻게 안전하게 종료되는지 궁금해졌다

그래서 아래 케이스에 대해 어떤 방식으로 종료되는지 확인하고, 안전하게 종료되지 않았을 경우 이를 어떻게 확인할 수 있는지도 알아보도록 하겠다. '안전하지 종료되지 않았다란' 해야 할 작업을 모두 끝내지 못하고 종료된 케이스를 의미한다

graceful shutdown이 활성화되고, shutdown timeout 이 5초이고, ThreadPoolTaskExecutor를 이용해서 비동기로 수행하던 작업이 5초 이상 걸릴 경우

코드를 통해 동작 살펴보기

먼저 graceful shutdown이 활성화되고, shutdown timeout 이 5초이고, ThreadPoolTaskExecutor를 이용해서 비동기로 수행하던 작업이 5초 이상 걸릴 경우에 대해 살펴보도록 하겠다

이 케이스에서는 어떻게 종료가 진행되는지 살펴보고, 안전하지 않게 종료됐을 경우 이를 어떻게 확인 가능할지도 알아보겠다

먼저 비동기로 5초 이상 작업을 수행하는데, 해당 작업이 단순히 스레드 sleep인 케이스를 살펴보겠다

//application.yml
spring:
  lifecycle:
    timeout-per-shutdown-phase: 5s
server:
  shutdown: graceful
  

fun execute() {
    repeat(5) {
        taskExecutor.execute {
            logger.info("${Thread.currentThread().name}: 비동기 작업 시작")
            Thread.sleep(50000)
            logger.info("${Thread.currentThread().name}: 비동기 작업 끝")
        }
    }
}
/*
result:
2025-05-04T16:35:17.422+09:00  INFO 49728 --- [         task-2] c.p.application.ShutdownExecutorService  : task-2: 비동기 작업 시작
2025-05-04T16:35:17.422+09:00  INFO 49728 --- [         task-1] c.p.application.ShutdownExecutorService  : task-1: 비동기 작업 시작
2025-05-04T16:35:17.423+09:00  INFO 49728 --- [         task-3] c.p.application.ShutdownExecutorService  : task-3: 비동기 작업 시작
2025-05-04T16:35:17.423+09:00  INFO 49728 --- [         task-4] c.p.application.ShutdownExecutorService  : task-4: 비동기 작업 시작
2025-05-04T16:35:17.424+09:00  INFO 49728 --- [         task-5] c.p.application.ShutdownExecutorService  : task-5: 비동기 작업 시작
2025-05-04T16:35:19.662+09:00  INFO 49728 --- [ionShutdownHook] o.s.b.w.e.tomcat.GracefulShutdown        : Commencing graceful shutdown. Waiting for active requests to complete
2025-05-04T16:35:19.670+09:00  INFO 49728 --- [tomcat-shutdown] o.s.b.w.e.tomcat.GracefulShutdown        : Graceful shutdown complete
2025-05-04T16:35:24.683+09:00  INFO 49728 --- [ionShutdownHook] o.s.c.support.DefaultLifecycleProcessor  : Shutdown phase 1073741823 ends with 1 bean still running after timeout of 5000ms: [applicationTaskExecutor]
2025-05-04T16:35:26.775+09:00  INFO 49728 --- [ionShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2025-05-04T16:35:26.777+09:00  INFO 49728 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2025-05-04T16:35:26.789+09:00  INFO 49728 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.
Exception in thread "task-5" Exception in thread "task-3" Exception in thread "task-4" Exception in thread "task-1" Exception in thread "task-2" java.lang.InterruptedException: sleep interrupted
	at java.base/java.lang.Thread.sleep0(Native Method)
	at java.base/java.lang.Thread.sleep(Thread.java:509)
	at com.pjh.application.ShutdownExecutorService.execute$lambda$1$lambda$0(ShutdownExecutorService.kt:18)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
	at java.base/java.lang.Thread.run(Thread.java:1583)
java.lang.InterruptedException: sleep interrupted
	at java.base/java.lang.Thread.sleep0(Native Method)
	at java.base/java.lang.Thread.sleep(Thread.java:509)
	at com.pjh.application.ShutdownExecutorService.execute$lambda$1$lambda$0(ShutdownExecutorService.kt:18)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
	at java.base/java.lang.Thread.run(Thread.java:1583)
java.lang.InterruptedException: sleep interrupted
	at java.base/java.lang.Thread.sleep0(Native Method)
	at java.base/java.lang.Thread.sleep(Thread.java:509)
	at com.pjh.application.ShutdownExecutorService.execute$lambda$1$lambda$0(ShutdownExecutorService.kt:18)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
	at java.base/java.lang.Thread.run(Thread.java:1583)
java.lang.InterruptedException: sleep interrupted
	at java.base/java.lang.Thread.sleep0(Native Method)
	at java.base/java.lang.Thread.sleep(Thread.java:509)
	at com.pjh.application.ShutdownExecutorService.execute$lambda$1$lambda$0(ShutdownExecutorService.kt:18)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
	at java.base/java.lang.Thread.run(Thread.java:1583)
java.lang.InterruptedException: sleep interrupted
	at java.base/java.lang.Thread.sleep0(Native Method)
	at java.base/java.lang.Thread.sleep(Thread.java:509)
	at com.pjh.application.ShutdownExecutorService.execute$lambda$1$lambda$0(ShutdownExecutorService.kt:18)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642)
	at java.base/java.lang.Thread.run(Thread.java:1583)
*/

위 코드는 스레드 풀을 이용해서 5개의 작업을 비동기로 수행시킨다. 비동기로 시작된 작업 내부에서는 50초 동안 스레드를 sleep 시킨다. 이 상황에서 spring boot 애플리케이션을 종료시키면 shutdown timeout인 5초 동안 작업 종료를 기다리다가 강제로 sleep 됐던 스레드를 깨우고 작업을 끝낸다. 강제로 sleep 됐던 스레드를 깨우는 과정에서 InterruptedException이 발생한다. 때문에 graceful shutdown과정에서 작업이 제대로 처리되지 못하고 강제 종료됐음을 알 수 있다

이번에는 비동기 작업에서 스레드를 sleep 시키지 않고, 무한 루프를 돌며 어떤 연산을 처리하는 상황을 가정해 보겠다

fun execute() {
    repeat(5) {
        taskExecutor.execute {
            logger.info("${Thread.currentThread().name}: 비동기 작업 시작")
            while(true) {}
        }
    }
}
/*
result:
2025-05-04T16:40:46.581+09:00  INFO 14108 --- [         task-1] c.p.application.ShutdownExecutorService  : task-1: 비동기 작업 시작
2025-05-04T16:40:46.581+09:00  INFO 14108 --- [         task-2] c.p.application.ShutdownExecutorService  : task-2: 비동기 작업 시작
2025-05-04T16:40:46.582+09:00  INFO 14108 --- [         task-3] c.p.application.ShutdownExecutorService  : task-3: 비동기 작업 시작
2025-05-04T16:40:46.582+09:00  INFO 14108 --- [         task-4] c.p.application.ShutdownExecutorService  : task-4: 비동기 작업 시작
2025-05-04T16:40:46.582+09:00  INFO 14108 --- [         task-5] c.p.application.ShutdownExecutorService  : task-5: 비동기 작업 시작
2025-05-04T16:40:49.984+09:00  INFO 14108 --- [ionShutdownHook] o.s.b.w.e.tomcat.GracefulShutdown        : Commencing graceful shutdown. Waiting for active requests to complete
2025-05-04T16:40:49.991+09:00  INFO 14108 --- [tomcat-shutdown] o.s.b.w.e.tomcat.GracefulShutdown        : Graceful shutdown complete
2025-05-04T16:40:54.997+09:00  INFO 14108 --- [ionShutdownHook] o.s.c.support.DefaultLifecycleProcessor  : Shutdown phase 1073741823 ends with 1 bean still running after timeout of 5000ms: [applicationTaskExecutor]
2025-05-04T16:40:57.098+09:00  INFO 14108 --- [ionShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2025-05-04T16:40:57.101+09:00  INFO 14108 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2025-05-04T16:40:57.116+09:00  INFO 14108 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.
*/

위 코드는 스레드 풀을 이용해서 5개의 작업을 비동기로 수행시킨다. 비동기로 시작된 작업 무한루프를 돈다. 이 상황에서 spring boot 애플리케이션을 종료시키면 shutdown timeout인 5초 동안 작업 종료를 기다리다가 강제로 스레드를 종료시킨다. 근데 이번에는 스레드를 sleep 시켰던 케이스와 다르게 아무 예외 없이 작업이 조용히 종료됐다. 만약 현재 연산이 무한루프를 도는 연산이 아니라 어떤 핵심적인 작업을 하는 상황이었다면 우리는 핵심적인 연산이 비정상적으로 종료된 걸 몰랐을 것이다. 그러면 이 상황을 어떻게 알아챌 수 있을까?

@Bean
fun taskExecutor1(): ThreadPoolTaskExecutor {
    return ThreadPoolTaskExecutor().apply {
        corePoolSize = 10
        setWaitForTasksToCompleteOnShutdown(true)
        setAwaitTerminationSeconds(30)
        setThreadNamePrefix("jiho-")
    }
}
/*
result:
2025-05-04T17:14:25.536+09:00  INFO 50988 --- [ionShutdownHook] o.s.b.w.e.tomcat.GracefulShutdown        : Commencing graceful shutdown. Waiting for active requests to complete
2025-05-04T17:14:25.543+09:00  INFO 50988 --- [tomcat-shutdown] o.s.b.w.e.tomcat.GracefulShutdown        : Graceful shutdown complete
2025-05-04T17:14:57.686+09:00  WARN 50988 --- [ionShutdownHook] o.s.s.concurrent.ThreadPoolTaskExecutor  : Timed out while waiting for executor 'taskExecutor1' to terminate
2025-05-04T17:14:57.686+09:00  INFO 50988 --- [ionShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2025-05-04T17:14:57.688+09:00  INFO 50988 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2025-05-04T17:14:57.700+09:00  INFO 50988 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.
*/

ThreadPool taskExecutor를 만들 때 setWaitForTasksToCompleteOnShutdown에 true를 넣고, setAwaitTerminationSeconds에 기다릴 시간을 넣어주면 된다. 이렇게 설정을 해주면 스레드 풀의 스레드에서 수행하던 작업이 30초 이내에 종료되지 않을 경우 WARN 레벨의 로그로 time out이 났음을 알려준다

timeout-per-shutdown-phase에 대해서

지금까지 graceful shutdown을 위한 옵션으로 timeout-per-shutdown-phase와 ThreadPoolTaskExecutor의 setAwaitTerminationSeconds 2가지를 살펴봤다. 지금부터는 각각에 대해 좀 더 자세히 살펴보도록 하겠다

timeout-per-shutdown-phase에 설정한 값은 DefaultLifecycleProcessor클래스의 timeoutPerShutdownPhase의 값으로 세팅된다. 이 값은 각 빈을 종료처리 할 때 최대 얼마만큼의 시간이 걸릴지를 의미한다. 근데 phase라는 단어는 어떤 의미일까? 종료에 단계(Phase)가 있는 것일까? 그렇다. 스프링을 빈의 종료처리를 단계별로 처리할 수 있도록 지원한다

스프링이 종료될 빈에서 특정 작업을 수행하고 싶다면 Lifecycle, SmartLifeCycle을 상속 후 stop메서드를 구현하면 된다. 그러면 스프링이 종료될 때 stop메서드도 호출될 것이다. SmartLifeCycle은 Lifecycle과 Phased를 상속하고 있는데 여기서 '단계'라는 개념이 등장한다. Phased는 getPhase메서드 하나만을 가진 인터페이스로 어떤 단계에서 종료(또는 시작)될지 결정하는 역할을 한다

// DefaultLifecycleProcessor 클래스의 일부
private void stopBeans() {
    Map<String, Lifecycle> lifecycleBeans = getLifecycleBeans();
    Map<Integer, LifecycleGroup> phases = new TreeMap<>(Comparator.reverseOrder());

    lifecycleBeans.forEach((beanName, bean) -> {
       int shutdownPhase = getPhase(bean);
       phases.computeIfAbsent(shutdownPhase,
             phase -> new LifecycleGroup(phase, determineTimeout(phase), lifecycleBeans, false)
       ).add(beanName, bean);
    });

    if (!phases.isEmpty()) {
       phases.values().forEach(LifecycleGroup::stop);
    }
}

내가 생각했을 때 phased의 개념을 가장 직관적으로 이해할 수 있는 부분이다.

LifeCycle, SmartLifeCycle을 상속한 빈들을 가져온다 (lifecycleBeans)
lifecycleBeans을 순회하며 phase를 구하고 같은 phase를 가진 빈끼리 LifecycleGroup이라는 객체 안에 그룹단위로 저장한다
1. phase 개념이 없는 LifeCycle을 상속한 빈의 경우 phase 0으로 계산되며 우선순위가 높은 종료대상이다
각 group(phase)을 돌면서 stop메서드를 호출한다. group의 stop메서드는 group에 속한 모든 빈을 종료시키는 걸 시도하며, 최대 타임아웃은 timeout-per-shutdown-phase에 설정한 시간이다. 즉 group(phase) 단위의 타임아웃이라는 말은 이러한 맥락에서 생겨난 것 같다

ThreadPoolTaskExecutor의 setAwaitTerminationSeconds에 대해서

ThreadPoolTaskExecutor를 만들 때 setWaitForTasksToCompleteOnShutdown에 true를 넣고, setAwaitTerminationSeconds에 30초를 넣으면 어떤 일이 발생할까?

@Bean
fun taskExecutor1(): ThreadPoolTaskExecutor {
    return ThreadPoolTaskExecutor().apply {
        corePoolSize = 10
        setWaitForTasksToCompleteOnShutdown(true)
        setAwaitTerminationSeconds(30)
        setThreadNamePrefix("jiho-")
    }
}
/*
result:
2025-05-05T21:23:33.926+09:00  INFO 81016 --- [         jiho-2] c.p.application.ShutdownExecutorService  : jiho-2: 비동기 작업 시작
2025-05-05T21:23:33.926+09:00  INFO 81016 --- [         jiho-1] c.p.application.ShutdownExecutorService  : jiho-1: 비동기 작업 시작
2025-05-05T21:23:33.926+09:00  INFO 81016 --- [         jiho-3] c.p.application.ShutdownExecutorService  : jiho-3: 비동기 작업 시작
2025-05-05T21:23:33.927+09:00  INFO 81016 --- [         jiho-4] c.p.application.ShutdownExecutorService  : jiho-4: 비동기 작업 시작
2025-05-05T21:23:33.927+09:00  INFO 81016 --- [         jiho-5] c.p.application.ShutdownExecutorService  : jiho-5: 비동기 작업 시작
2025-05-05T21:23:37.047+09:00  INFO 81016 --- [ionShutdownHook] o.s.b.w.e.tomcat.GracefulShutdown        : Commencing graceful shutdown. Waiting for active requests to complete
2025-05-05T21:23:37.054+09:00  INFO 81016 --- [tomcat-shutdown] o.s.b.w.e.tomcat.GracefulShutdown        : Graceful shutdown complete
2025-05-05T21:24:09.157+09:00  WARN 81016 --- [ionShutdownHook] o.s.s.concurrent.ThreadPoolTaskExecutor  : Timed out while waiting for executor 'taskExecutor1' to terminate
2025-05-05T21:24:09.158+09:00  INFO 81016 --- [ionShutdownHook] j.LocalContainerEntityManagerFactoryBean : Closing JPA EntityManagerFactory for persistence unit 'default'
2025-05-05T21:24:09.160+09:00  INFO 81016 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown initiated...
2025-05-05T21:24:09.169+09:00  INFO 81016 --- [ionShutdownHook] com.zaxxer.hikari.HikariDataSource       : HikariPool-1 - Shutdown completed.
*/

위 코드의 결과를 보면 알 수 있듯이 timeout-per-shutdown-phase를 5초로 설정해 둬도 30초 뒤에 WARN로그와 함께 종료되는 걸 확인할 수 있다. 내부에서 어떻게 처리되길래 timeout-per-shutdown-phase를 무시한 것일까? 그것은 ThreadPoolTaskExecutor가 상속하고 있는 ExecutorConfigurationSupport클래스를 통해 확인할 수 있다

setWaitForTasksToCompleteOnShutdown에 true를 넣으면 이 스레드 풀은 lateShutdown이 true로 된다
lateShutdown이 true인 스레드 풀은 SmartLifecycle 상속을 통한 stop메서드가 호출될 때 stop 시키지 않는다. 다만 스레드 풀의 stop메서드를 호출한 caller에겐 stop이 완료된 것처럼 알려준다. 그러므로 timeout-per-shutdown-phase를 5초를 기다리지 않는다
spring의 stop과정이 끝나고 destroy가 시작될 때 ThreadPoolTaskExecutor는 setAwaitTerminationSeconds에 넣은 초만큼 기다렸다가 종료한다

@Override
public void stop(Runnable callback) {
    if (this.lifecycleDelegate != null && !this.lateShutdown) {
       this.lifecycleDelegate.stop(callback);
    }
    else {
    	// lateShutdown이 true 이므로 이 부분이 실행되고, 바로 callback을 수행해서 caller 에게 stop이 완료된 것 처럼 알려준다
       callback.run();
    }
}

결론

graceful shutdown 및 timeout-per-shutdown-phase를 사용할 때 timeout-per-shutdown-phase에 5s를 지정했다고 해서 5초 내에 작업이 끝나는 것이 아니다. timeout-per-shutdown-phase는 phase 당 timeout이기 때문에 최대 phase 수 X 5초가 걸릴 수 있음을 알아야 한다
ThreadPoolTaskExecutor를 graceful shutdown 할 때는 setWaitForTasksToCompleteOnShutdown / setAwaitTerminationSeconds을 사용하는 게 좋아 보인다. 왜냐하면 작업이 비정상적으로 끝났을 때 WARN로그를 통해 확인할 수 있기 때문이다
setWaitForTasksToCompleteOnShutdown에 true를 설정하면 timeout-per-shutdown-phase와 무관하게 setAwaitTerminationSeconds만큼 기다린다. 때문에 애플리케이션 종료시간을 예측할 때 이를 고려해야 한다. setAwaitTerminationSeconds 이전에 강제로 프로세스를 종료시킨다면 어떤 WARN로그도 없이 프로세스가 죽을 수도 있다