종료에 120초가 걸리던 이유: ScheduledThreadPoolExecutor의 대기 큐

TL;DR

배포할 때마다 알림 채널에 LettuceConnectionFactory has been STOPPED 에러가 한두 건씩 찍혔다. 처음 질문은 단순했다. “이거 뮤트해도 되나?”

따라가 보니 에러 자체는 라이브러리가 종료 중에 내는 노이즈였지만, 그 밑에서 더 큰 문제가 나왔다. 배치 스케줄러를 스프링 빈으로 등록한 커밋 하나가, 도입된 뒤로 한 번도 실행된 적 없던 graceful shutdown 설정을 깨운 것이다. 그 뒤로 모든 컨테이너가 종료에 정확히 120초를 쓰고 있었다.

Spring의 cron 작업은 JDK 눈에는 “지연 1회성 작업”이고, shutdown()은 이런 작업을 큐에서 버리지 않는다. 실행 중인 배치가 없어도 풀은 다음 주에 실행될 작업을 기다리며 타임아웃을 전부 소진했다.

수정 한줄로, destroy()가 120,022ms에서 1ms가 됐고, 실배포에서 마이그레이션 태스크 종료가 120.8초에서 0.375초가 됐다.

---

1. 알림 하나에서 시작된 추적

에러 로그를 열어 보면 이상한 규칙이 하나 보인다. 발생 시각이 전부 xx:xx:00.00x, 그러니까 정확히 매분 0초다. 그리고 컨테이너가 종료될 때만, 컨테이너당 한두 건씩 찍힌다.

스레드를 집계해 보니 7일간 ERROR 133건이 전부 spring-session-1이라는 스레드 하나에서 나왔다. 세션을 Redis에 저장하는 구성에서 Spring Session이 만료된 세션을 정리하려고 직접 띄우는 스케줄러다.

// spring-session-data-redis 3.5.5 · RedisIndexedSessionRepository
public void afterPropertiesSet() {
    if (!Scheduled.CRON_DISABLED.equals(this.cleanupCron)) {
        this.taskScheduler = createTaskScheduler();
        this.taskScheduler.initialize();
        this.taskScheduler.schedule(this::cleanUpExpiredSessions,
                new CronTrigger(this.cleanupCron));   // 기본값 "0 * * * * *" — 매분 0초
    }
}

크론 기본값이 매분 0초다.

어느 날부터 갑자기

30일 타임시리즈를 그려 보니 앞의 4주가 사실상 0건이다. 그러다 특정 날짜부터 에러가 붙기 시작해 그 뒤로 쭉 이어진다. 원래 있던 문제가 아니라 그 주에 생긴 문제라는 뜻이다.

그럼 그 주에 뭔가 바뀌었을까. 제일 먼저 의심한 건 배포 횟수다. 종료할 때만 나는 에러니까 배포가 잦아졌으면 에러도 따라 늘었을 것이다. 그래서 같은 30일 동안 Commencing graceful shutdown 로그를 세어 봤는데, 종료 횟수는 내내 비슷한 페이스였다. 배포량은 그대로인데 에러만 늘었으니 남은 건 배포되는 코드 쪽이다.

@Bean 한 단어

에러가 시작된 날짜 전후로 스케줄러 관련 변경을 뒤지니 하나가 나왔다. 배치 스케줄러 설정을 정리한 techdebt 커밋이다.

public void configureTasks(ScheduledTaskRegistrar taskRegistrar) {
-       ThreadPoolTaskScheduler scheduler = new ThreadPoolTaskScheduler();
-       // ...설정...
-       scheduler.initialize();               // 그냥 new 해서 손으로 초기화
-       taskRegistrar.setTaskScheduler(scheduler);
+       taskRegistrar.setTaskScheduler(batchTaskScheduler());
    }

+   @Bean                                     // ← 이 한 단어가 방아쇠
+   public ThreadPoolTaskScheduler batchTaskScheduler() {
+       // ...같은 설정...
+   }

diff를 아무리 봐도 설정값은 하나도 안 바뀌었다. 풀 크기도, waitForTasksToCompleteOnShutdown=true도, awaitTerminationSeconds=120도 이전 그대로다. 달라진 건 스프링이 이 객체를 자기 빈으로 알게 됐다는 것뿐이다.

그런데 그게 전부였다. ThreadPoolTaskScheduler의 graceful shutdown 설정은 destroy() → shutdown() 경로에서만 동작하는데, 빈이 아니던 시절에는 종료 시 아무도 destroy()를 불러주지 않았다. 혹시 ScheduledTaskRegistrar가 대신 닫아주지 않았을까 싶어 소스를 열어 봤다.

// spring-context 6.2.17 · ScheduledTaskRegistrar.destroy()
public void destroy() {
    for (ScheduledTask task : this.scheduledTasks) {
        task.cancel(false);
    }
    if (this.localExecutor != null) {      // 레지스트라가 '직접 만든' 스케줄러일 때만
        this.localExecutor.shutdownNow();  // 외부에서 꽂아준 스케줄러는 안 닫는다
    }
}

안 닫아준다. 그러니까 “120초 graceful shutdown 대기”는 설정된 이래 줄곧 죽어 있던 코드였고, 이 커밋이 처음으로 실제로 켠 셈이다. 진행 중인 배치를 끊지 않겠다는 의도 자체는 옳았다. 다만 켜고 보니 종료 창이 수 초에서 2분으로 늘었고, 그 2분 사이에 매분 도는 세션 정리가 이미 꺼진 Redis를 찌르기 시작한 것이다.

빈으로 등록됐다는 증거는 로그에도 남아 있다. 타임아웃 경고가 Timed out while waiting for executor 'batchTaskScheduler' to terminate라고 찍히는데, 여기 들어가는 이름이 BeanNameAware로 채워지는 값이다.

---

2. 왜 하필 120초를 “꽉” 채우나

켜진 것까지는 알았다. 그런데 왜 매번 타임아웃 한계까지 가는지는 설명이 안 된다. 실행 중인 배치가 그렇게 오래 걸릴 리는 없다.

등장인물부터 정리하면, 같은 JVM에 스케줄러가 두 개 있다.

	① batchTaskScheduler	② spring-session 스케줄러
하는 일	@Scheduled 배치 55개 실행	만료 세션 정리 (매분 0초)
만든 곳	우리 설정 코드	Spring Session 라이브러리 내부
이번 사건에서의 역할	종료를 120초 붙잡는 원인	그 사이 에러를 찍는 실행자

에러 로그에 찍히는 건 ②지만, ②가 계속 살아서 돌 수 있는 시간을 만들어주는 건 ①이다.

Spring cron은 지연 1회성 작업의 무한 연쇄다

@Scheduled(cron=...)은 이름만 보면 주기(periodic) 작업 같지만, Spring은 이걸 scheduleAtFixedRate()로 등록하지 않는다.

// spring-context 6.2.17 · ReschedulingRunnable
public ScheduledFuture<?> schedule() {
    this.scheduledExecutionTime = this.trigger.nextExecution(...);  // "다음 실행 언제야?"
    Duration delay = Duration.between(now, this.scheduledExecutionTime);
    this.currentFuture = this.executor.schedule(this, delay.toNanos(), NANOSECONDS);
    // ↑ '그 시각까지의 지연 1회성 작업'으로 등록 ★
}

public void run() {
    super.run();                          // 배치 실행
    if (!obtainCurrentFuture().isCancelled()) {
        schedule();                       // 끝나면 스스로 다음 1회를 또 예약
    }
}

cron의 실체는 “1회성 지연 작업을 실행하고, 끝나면 스스로 다음 1회를 예약하는” 무한 연쇄다. 그래서 JDK 풀 입장에서 큐에 들어 있는 건 언제나 isPeriodic() == false인 지연 1회성(delayed) 작업이다. 우리 코드의 @Scheduled 55개 중 52개가 cron이었으니, 큐는 사실상 delayed 작업으로만 차 있는 셈이다.

JDK는 delayed를 버리지 않는다

이제 shutdown()이 호출되면 무슨 일이 벌어지는지 보자. ScheduledThreadPoolExecutor에는 종료 시 큐를 어떻게 처리할지 정하는 플래그가 둘 있는데, 기본값이 서로 반대다.

// JDK 21 · ScheduledThreadPoolExecutor
private volatile boolean continueExistingPeriodicTasksAfterShutdown;        // false → periodic은 취소
private volatile boolean executeExistingDelayedTasksAfterShutdown = true;   // true  → delayed는 유지 ★

// onShutdown() — shutdown() 시 큐 청소 로직
for (Object e : q.toArray()) {
    RunnableScheduledFuture<?> t = (RunnableScheduledFuture<?>) e;
    if ((t.isPeriodic() ? !keepPeriodic                             // periodic → 취소 대상
                        : (!keepDelayed && t.getDelay(...) > 0))    // delayed → keepDelayed=true라 항상 false
        || t.isCancelled()) {
        if (q.remove(t)) t.cancel(false);
    }
}

periodic 작업이라면 여기서 취소됐을 것이다. 하지만 cron 작업들은 delayed라서 취소 조건에 아예 걸리지 않고 큐에 그대로 남는다. 그리고 ThreadPoolExecutor의 종료 판정이 이렇게 생겼다.

// tryTerminate() — 풀을 TERMINATED로 전이시켜도 되는지
if (isRunning(c) || runStateAtLeast(c, TIDYING) ||
    (runStateLessThan(c, STOP) && !workQueue.isEmpty()))
    return;                               // ← 큐가 안 비었으면 종료 불가

// getTask() — 워커가 다음 작업을 기다리는 곳
if (runStateAtLeast(c, SHUTDOWN)
    && (runStateAtLeast(c, STOP) || workQueue.isEmpty())) {
    return null;                          // 큐가 비어야만 워커가 종료
}
// 큐가 안 비었으면 → workQueue.take()에서 다음 실행 시각까지 무기한 대기

여기 나오는 take()가 이 사건의 목격자다. 큐에서 하나 꺼내되, 꺼낼 게 없으면 스레드를 재우는 메서드다. 그런데 DelayedWorkQueue는 여기에 조건이 하나 더 붙는다.

우리 큐에는 주 단위 cron이 앉아 있었다. 다음 실행이 최대 6.5일 뒤인 작업이 큐에 남아 있는 것이다. 그런 게 하나라도 있으면 큐는 120초 안에 절대 비지 않는다. tryTerminate()는 계속 거부하고, 워커들은 DelayedWorkQueue.take()에서 잠들어 있고, awaitTermination(120s)은 시간을 다 쓰고 타임아웃한다.

작업이 오래 걸려서 120초를 쓰는 게 아니다. “다음 주에 실행될 예정”인 작업들을 기다리느라 120초를 버리는 것이다.

왜 Redis가 스케줄러보다 먼저 꺼지나

에러가 나려면 Redis는 죽었는데 스케줄러는 살아 있는 순서여야 한다. Spring 종료는 stop 단계(SmartLifecycle 빈 정지)를 먼저 돌고 destroy 단계(빈 destroy() 호출)를 나중에 도는데, 스케줄러의 부모 클래스에 이런 분기가 있다.

// spring-context 6.2.17 · ExecutorConfigurationSupport
public void onApplicationEvent(ContextClosedEvent event) {
    if (this.acceptTasksAfterContextClose || this.waitForTasksToCompleteOnShutdown) {
        this.lateShutdown = true;   // ← stop 단계를 건너뛰고 destroy 때 정리
    } else { ... initiateEarlyShutdown(); }
}

waitForTasksToCompleteOnShutdown=true인 우리 스케줄러는 stop 단계를 그냥 통과한다. 반면 Redis 커넥션은 stop 단계에서 먼저 STOPPED가 된다. 그 결과 destroy 단계의 120초 동안, 매분 0초마다 세션 정리가 이미 죽은 Redis를 찌른다. 120초에 매분 주기니까 컨테이너당 에러 2건이고, 관측과 맞아떨어진다.

이론을 실험으로

여기까지는 소스 코드로 재구성한 이론이다. 이론은 실험으로 증명해야 한다. 프로덕션과 동일한 버전(JDK 21 + spring-context 6.2.17)에 동일한 스케줄러 설정, 실제 cron 스케줄 19종을 그대로 넣고, 작업 내용만 전부 no-op으로 비운 최소 재현을 만들었다.

모드=BROKEN(현재 설정) | awaitTerminationSeconds=120
[준비] 등록된 cron=19개, 큐 크기=19, 실행중 작업=0
[실행] destroy() 호출

### 스레드 덤프 (destroy() 시작 3초 후) ###
### 큐 크기=19, 활성=0, isShutdown=true, isTerminated=false

"scheduled-batch-pool-1" #21  state=WAITING
    at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(...)
    … 워커 19개 전부 동일 스택 …

### 큐에 남아있는 작업 ###
    - 다음 실행까지 600초        isPeriodic=false
    - 다음 실행까지 3,600초      isPeriodic=false
    ... 가장 먼 작업은 555,000초 (6.4일) 뒤 실행 예정

WARNING: Timed out while waiting for executor 'batchTaskScheduler' to terminate
────────────────────────────────────────────
결과: destroy() 소요 = 120,022 ms
      살아남은 non-daemon 워커 = 19개 → JVM이 스스로 종료 못 함

실행 중인 작업이 0개인데도 종료가 안 된다. “배치가 오래 걸려서”라는 가설은 이걸로 완전히 배제된다. 워커 19개는 전부 소스에서 추론한 바로 그 지점, DelayedWorkQueue.take()에서 잠들어 있다. 그리고 큐에 남은 작업들은 예외 없이 isPeriodic=false, 가장 먼 것은 6.4일 뒤 실행 예정이다.

프로덕션 실측이 120,142ms, 재현이 120,022ms다.

---

3. 조치와 검증

수정은 한 줄

// SchedulerConfig · batchTaskScheduler()
scheduler.setExecuteExistingDelayedTasksAfterShutdownPolicy(false);
// shutdown() 시 '대기 중인' cron은 큐에서 제거하고, '실행 중인' 작업만 마저 기다린다
// → 원래 의도(진행 중 배치 안 끊기)는 유지하면서 120초 낭비만 제거

이 플래그를 끄면 onShutdown()이 대기 중인 delayed 작업을 큐에서 걷어낸다. 실행 중인 작업은 여전히 완료를 기다리니, graceful shutdown의 본래 의도는 그대로 살아 있다.

로컬 A/B 결과는 이렇다.

	BROKEN (수정 전)	FIXED (한 줄 추가)
destroy() 소요	120,022 ms	1 ms
종료 후 큐	18개 잔류	0개
isTerminated	false	true
남은 non-daemon 워커	19개 (JVM 자력 종료 불가)	0개
Timed out WARN	발생	없음

정책이 되돌아가면 실패하는 회귀 테스트도 같이 넣었다. 주 단위 cron을 걸어두고 destroy()가 즉시 반환되는지 검증하는 테스트다.

환경마다 증상이 달랐던 이유

그런데 조사 중에 이상한 점이 하나 있었다. 같은 코드인데 컨테이너마다 증상이 달랐다. 마이그레이션에서는 타임아웃 경고까지 찍히고, 배치에서는 에러만 찍히고, 웹에서는 가끔 한 건 나오는 정도였다. 이 차이는 인프라에서 나온다. 앱은 120초를 기다리고 싶어 하지만, 컨테이너 오케스트레이터가 실제로 주는 시간이 태스크마다 다르기 때문이다.

컨테이너	종료 트리거	실제 종료 창	관측
마이그레이션	일회성 태스크라 오케스트레이터 개입 없음, 스스로 종료	120초 완주	ERROR 2건 + Timed out WARN 1건
배치	SIGTERM → stopTimeout(대기시간과 동일, 여유 0초) → SIGKILL	≈120초	ERROR 2건 + WARN 0건 (찍기 직전 사망)
웹	SIGTERM → 짧은 stopTimeout → SIGKILL	≈10~20초	ERROR 가끔 1건

마이그레이션은 모든 배포 파이프라인에서 실행되는 태스크다. 즉 매 배포마다, 할 일을 이미 끝낸 컨테이너 하나가 아무 이유 없이 2분을 더 살아 있었다. Success:0, Failed:0으로 끝나 실제로는 아무 일도 하지 않은 마이그레이션도 예외 없이 그랬다.

웹과 배치는 더 나빴다. 매 배포마다 SIGKILL(exit 137)로 강제 종료되고 있었다. 원인 커밋이 의도했던 “진행 중 배치 안 끊기”는 실제로는 전혀 달성되지 않았고, 얻은 것은 로그 노이즈와 배포 지연뿐이었던 셈이다. 30일간 종료 시도 143건 중 104건(73%)이 완료 로그를 못 남긴 이유가 여기 있다.

실배포 검증

수정을 머지하고 실제 배포에서 전후를 쟀다.

지표	Before	After
destroy() (로컬 A/B)	120,022ms	1ms
마이그레이션 태스크 종료 (실배포 실측)	120.8초	0.375초
컨테이너 종료 코드 (배치 1 + 웹 2)	137 (SIGKILL)	143 (SIGTERM 정상 처리)
배치 컨테이너 종료 소요	133.4초	32.1초
Timed out WARN	2일간 31건	0건
세션 정리 ERROR	7일간 133건	0건 (종료 창 축소로 자연 소멸)

모니터는 뮤트하지 않았다

원래 질문이었던 “뮤트해도 되나?”의 답은 “안 된다”였다. 이 알림은 개발 환경 에러 전체를 잡는 캐치올 모니터라서, 문제의 에러를 걷어내도 7일간 79건의 진짜 에러가 남아 있었다. 뮤트하면 그걸 전부 잃는다.

제외 조건을 걸 때도 배운 게 하나 있다. 문구가 아니라 스레드 이름으로 걸어야 한다는 것. 같은 에러 문구가 전혀 다른 원인(별도 배치 스레드)으로도 대량으로 찍히고 있었는데, 문구 기반으로 제외하면 아직 조사도 안 한 그 별건까지 통째로 가려진다. 이번 에러는 ERROR 레벨 전부가 spring-session-1 스레드 하나였으니, 스레드 기준 제외면 이 노이즈만 걷어낼 수 있다.

---

정리

ScheduledThreadPoolExecutor.shutdown()은 delayed 작업을 버리지 않고, Spring cron은 전부 delayed다. graceful shutdown을 켤 때 이 조합을 모르면 풀은 “다음 주에 실행될 작업”을 기다리며 타임아웃을 전부 소진한다. 수정은 setExecuteExistingDelayedTasksAfterShutdownPolicy(false) 한 줄이었고, 로컬 A/B와 실배포 실측으로 검증했다.