Spring Boot 는 Ready 뒤에도 첫 요청 비용이 남는다 - 시작 과정과 JVM 으로 따라가기

배포 직후 첫 요청만 느리다?!

애플리케이션을 띄우면 아래와 같이 Started 로그가 찍히고 readiness 도 200 을 응답한다.

Tomcat started on port 8080 (http) with context path '/'
Started StartupApplication in 1.877 seconds (process running for 2.195)

$ curl -s -o /dev/null -w "%{http_code}" localhost:8080/actuator/health/readiness
200

그런데 같은 시점에 MySQL 에서 한 건을 조회하는 /users/1 을 연달아 호출해보면, 한 번 띄운 결과에서 응답 시간이 아래와 같이 나온다.

애플리케이션은 시작을 마쳤고 readiness 도 통과했는데, 첫 요청만 100배 넘게 느리다.
Started 로그와 readiness 200 은 정확히 무엇이 끝났다는 뜻이고, 그 뒤에는 무엇이 남아 있을까?

한눈에 보기

Spring Boot 애플리케이션이 "준비됐다"고 말할 수 있는 시점은 하나가 아닌데, 시작부터 첫 요청까지를 그려보면 아래와 같다.

Liveness, Readiness 는 각 이벤트 바로 뒤에 바뀌는데, 그림의 2번(Started), 3번(Ready), 4번과 5번(첫 요청)을 기준으로 정리하면 아래와 같다.

테스트 환경

첫 요청에 어떤 비용이 더해지는지 나눠 보려고, 의존하는 대상이 다른 API 세 개를 두었다.

테스트는 아래와 같이 나눠서 진행했는데, 테스트마다 애플리케이션을 10번 새로 띄우고 중앙값을 냈다.

Spring MVC 기준으로 측정했고, WebFlux 는 요청을 처리하는 경로가 달라서 DispatcherServlet 초기화나 첫 요청에 로딩되는 클래스가 다르게 나타날 수 있다.
응답 시간은 가장 바깥 서블릿 필터에서 요청마다 잰 서버 안의 시간이고, 이 측정용 필터를 처음 실행하는 비용도 함께 들어 있다.
같은 설정이어도 Started 시간이 실행마다 1.6초에서 2.1초 사이로 달라져서 테스트끼리 수치가 조금씩 다른데, 수치는 이 환경에서 흐름을 보기 위한 예시로 읽으면 된다.

Spring Boot 시작 과정

1) SpringApplication.run() 의 순서

SpringApplication.run() 을 열어보면 시작 과정이 아래 순서로 이어진다. (Spring Boot 4.1.2, 일부 생략, 코드 바로가기)

public ConfigurableApplicationContext run(String... args) {
    ...
    listeners.starting(bootstrapContext, this.mainApplicationClass);           // ApplicationStartingEvent
    try {
        ConfigurableEnvironment environment = prepareEnvironment(...);        // ApplicationEnvironmentPreparedEvent
        context = createApplicationContext();
        prepareContext(...);                                                  // ApplicationContextInitializedEvent, ApplicationPreparedEvent
        refreshContext(context);                                              // 빈 생성, 웹 서버 시작
        afterRefresh(context, applicationArguments);
        Duration timeTakenToStarted = startup.started();
        new StartupInfoLogger(...).logStarted(getApplicationLog(), startup);  // "Started ... in N seconds"
        listeners.started(context, timeTakenToStarted);                       // ApplicationStartedEvent, LivenessState.CORRECT
        callRunners(context, applicationArguments);                           // ApplicationRunner, CommandLineRunner
    }
    ...
    if (context.isRunning()) {
        listeners.ready(context, startup.ready());                            // ApplicationReadyEvent, ReadinessState.ACCEPTING_TRAFFIC
    }
    return context;
}

IntelliJ 디버거로 refreshContext, listeners.started, callRunners, listeners.ready 줄에 중단점을 걸고 띄워보면 아래 순서로 멈춘다.

1. refreshContext2. listeners.started3. callRunners4. listeners.ready

• 확인해야 하는 부분
  • 여기서 refresh 로 들어가 빈을 만들고, 웹 서버를 띄워 포트를 연다
  • 아직 Started 로그는 찍히지 않았다

중단점 없이 띄운 콘솔 로그에도 같은 순서로 찍힌다. (Runner 2초)

위의 로그를 해석하면 아래와 같다.

• 포트는 13.722 에 열리고, 6ms 뒤에 Started 로그와 Liveness CORRECT 가 이어서 찍힌다
• Runner 가 main 스레드에서 2초 동안 실행되고, 끝난 직후인 15.741 에 Readiness 가 ACCEPTING_TRAFFIC 으로 바뀐다
• Started 와 Ready 사이는 Runner 가 걸린 시간만큼 벌어지고, 포트는 그 전에 열려 있어서 이 2초 동안에도 요청이 들어올 수 있다

Liveness 와 Readiness 는 각 이벤트를 발행하는 EventPublishingRunListener 에서 이벤트 바로 뒤에 바뀐다. (코드 바로가기)

public void started(ConfigurableApplicationContext context, Duration timeTaken) {
    context.publishEvent(new ApplicationStartedEvent(this.application, this.args, context, timeTaken));
    AvailabilityChangeEvent.publish(context, LivenessState.CORRECT);
}

public void ready(ConfigurableApplicationContext context, Duration timeTaken) {
    context.publishEvent(new ApplicationReadyEvent(this.application, this.args, context, timeTaken));
    AvailabilityChangeEvent.publish(context, ReadinessState.ACCEPTING_TRAFFIC);
}

2) 웹 서버는 refresh 안에서 두 번에 나눠 뜬다

내장 웹 서버는 refresh 안에서 만드는 단계와 시작하는 단계가 나뉘어 있다.

포트를 여는 WebServerStartStopLifecycle.start() 는 아래와 같은데, 웹 서버를 시작한 뒤에 ServletWebServerInitializedEvent 를 발행한다. (코드 바로가기)

// WebServerStartStopLifecycle
public void start() {
    this.webServer.start();
    this.running = true;
    this.applicationContext.publishEvent(new ServletWebServerInitializedEvent(this.webServer, this.applicationContext));
}

this.webServer.start() 줄에 중단점을 걸고 호출 스택을 보면, run() 의 refreshContext 에서 refresh 로 들어가 시작할 때 만드는 빈을 모두 만든 뒤, finishRefresh 에서 웹 서버가 시작된다.

디버거로 본 호출 스택 펼쳐 보기

text

start:32, WebServerStartStopLifecycle              ← 포트를 연다
doStart:420, DefaultLifecycleProcessor
...
startBeans:379, DefaultLifecycleProcessor
onRefresh:306, DefaultLifecycleProcessor
finishRefresh:1013, AbstractApplicationContext     ← 시작할 때 만드는 빈을 모두 만든 뒤
refresh:624, AbstractApplicationContext
refresh:131, ServletWebServerApplicationContext
refresh:744, SpringApplication
refreshContext:433, SpringApplication
run:309, SpringApplication                         ← refreshContext(context)

시작할 때 만드는 빈을 모두 만든 뒤에 포트를 열기 때문에, 그 빈의 생성자나 @PostConstruct 에서 시간이 걸리면 그동안 포트가 닫혀 있어 연결 자체가 실패하고,
Runner 에서 시간이 걸리면 포트는 열려 있는 상태로 Ready 만 늦어진다.

3) 단계별 소요 시간

각 단계에 걸린 시간은 BufferingApplicationStartup 을 붙여서 Actuator 의 /actuator/startup 으로 확인할 수 있다.

SpringApplication application = new SpringApplication(StartupApplication.class);
application.setApplicationStartup(new BufferingApplicationStartup(20_000));
application.run(args);

테스트 애플리케이션에서 주요 단계의 시간을 뽑아보면 아래와 같다.

설정 클래스 분석은 빈 후처리 안에서 일어나는 단계라서 두 값을 더하지 않고 읽어야 하는데,
전체 시간의 대부분은 refresh 에서 쓰이고, 그 안에서도 자동 설정 조건을 따지는 설정 클래스 분석과 빈 354개를 만드는 데 시간이 많이 든다.

4) 이벤트 순서

Runner 에 2초가 걸리는 작업을 두고, 각 이벤트가 JVM 시작부터 몇 ms 에 발행되는지 기록해보면 아래와 같다.

공식 문서도 Started 와 Ready 를 Runner 를 기준으로 아래와 같이 구분한다.

Q. Started 로그가 찍혔는데 왜 아직 Ready 가 아닐까?

A. run() 에서 Started 로그와 ApplicationStartedEvent 다음에 callRunners() 가 있고, Ready 는 그 뒤에 오기 때문이다.
Runner 가 없거나 금방 끝나면 두 시점이 거의 붙어 있어서 같은 것처럼 보이는데, 위처럼 Runner 가 2초 걸리면 그만큼 벌어진다.
Started 로그는 준비가 끝난 시점보다는 컨텍스트가 뜬 시점으로 읽는 편이 정확하다.

Q. readiness 가 503 인데 요청은 왜 처리될까?

A. Runner 를 5초로 늘리고, 애플리케이션을 띄운 직후부터 100ms 마다 /hello 와 liveness, readiness 를 호출해보면 응답 코드가 아래와 같이 바뀐다.

readiness 가 503 인 약 5초 동안에도 /hello 는 200 으로 정상 응답하는데,
readiness 는 애플리케이션이 요청을 거절하는 장치가 아니라 바깥에 보내는 신호이기 때문이다.

쿠버네티스라면 readiness 가 실패하는 동안 Service 가 이 Pod 로 트래픽을 보내지 않지만, Pod IP 로 직접 들어오는 요청은 그대로 처리된다.
트래픽을 받기 전에 끝내야 하는 작업은 Runner 에 두는 편이 좋은데, 그래야 포트는 열린 상태로 그 작업이 끝날 때까지 readiness 가 실패 상태로 남는다.
Probe 와 연결되는 자세한 동작은 Kubernetes Probe 이해하기 에서 다뤘다.

Ready 뒤에도 남는 Spring 초기화

Ready 가 되면 Spring Boot 는 트래픽을 받아도 된다고 알리지만, 일부 초기화는 처음 쓰이는 순간까지 미뤄진다.
그 순간이 첫 API 요청일 수도 있고, Ready 를 확인하는 Probe 요청일 수도 있다.

1) DispatcherServlet

DispatcherServlet 은 서블릿 컨테이너가 처음 요청을 넘길 때 초기화되는데,
Spring Boot 의 spring.mvc.servlet.load-on-startup 기본값이 -1 이라 시작할 때 미리 초기화하지 않는다.
그런데 기본값으로 띄운 로그를 보면, 첫 /hello 요청보다 먼저 초기화가 끝나 있다.

10:40:44.081 INFO [main]            StartupApplication : Started StartupApplication in 1.877 seconds
10:40:44.197 INFO [nio-8080-exec-1] DispatcherServlet  : Initializing Servlet 'dispatcherServlet'
10:40:44.198 INFO [nio-8080-exec-1] DispatcherServlet  : Completed initialization in 1 ms
[request] seq=1 path=/hello status=200 server=6489us

Actuator 엔드포인트도 같은 포트의 DispatcherServlet 을 거치기 때문에,
테스트 스크립트가 Ready 를 확인하려고 readiness 요청을 보냈을 때 그 요청이 첫 요청이 되어 대신 초기화했다.
10번 모두 readiness 가 200 을 돌려주기 약 150ms 전에 초기화가 끝나 있었고, 관리 포트를 따로 두지 않았다면 쿠버네티스의 Probe 요청도 같은 역할을 하게 된다.

Q. load-on-startup 을 켜면 첫 요청이 빨라질까?

A. spring.mvc.servlet.load-on-startup=1 로 시작 과정에서 초기화하도록 바꿔도, 이 테스트에서는 첫 /hello 시간이 거의 같았다.

초기화 자체가 1ms 정도로 짧은 데다, 기본값에서도 readiness 요청이 먼저 치러주기 때문이다.
HandlerMapping 이나 MessageConverter 같은 빈은 이미 시작할 때 만들어져 있어서, DispatcherServlet 초기화는 그 빈을 찾아 연결하는 정도로 끝나는 것으로 보인다.

2) lazy-initialization

spring.main.lazy-initialization 을 켜면 빈을 시작할 때 만들지 않고 처음 쓰일 때 만든다.

10:40:44.081 INFO [main]            Started StartupApplication in 1.877 seconds
10:40:44.197 INFO [nio-8080-exec-1] Initializing Servlet 'dispatcherServlet'
10:40:44.198 INFO [nio-8080-exec-1] Completed initialization in 1 ms
[request] seq=1 path=/hello status=200 server=6489us
[request] seq=2 path=/hello status=200 server=1403us

시작은 약 0.3초 빨라졌지만, 첫 /hello 는 약 스무 배 길어졌다.
공식 문서는 잘못 설정된 빈의 오류가 시작할 때 드러나지 않고 늦게 발견될 수 있다는 점도 함께 짚고 있어서,
시작 시간을 줄이려고 켠다면 첫 요청 시간과 오류가 드러나는 시점을 함께 확인해보는 편이 좋다.

3) 커넥션 풀

Spring Boot 는 DataSource 로 HikariCP 를 쓰는데, Spring Boot 가 만드는 HikariDataSource 는 처음 getConnection() 이 불릴 때 풀을 만든다. (HikariCP 7.0.2)

// HikariDataSource.getConnection() 일부
HikariPool result = pool;
if (result == null) {
    synchronized (this) {
        result = pool;
        if (result == null) {
            LOGGER.info("{} - Starting...", getPoolName());
            pool = result = new HikariPool(this);   // 이때 풀을 만들고 DB 에 연결한다
            LOGGER.info("{} - Start completed.", getPoolName());
        }
    }
}

그래서 풀이 언제 시작되는지는 시작하는 동안 누가 커넥션을 요청하느냐에 달려 있다.
Spring MVC 쪽 첫 요청 비용이 섞이지 않게 /hello 를 한 번 먼저 부르고,
JDBC 만 쓸 때, JPA 를 기본 설정으로 켰을 때, JPA 에서 설정 두 가지를 바꿔 시작 중 DB 연결을 막았을 때를 비교하면 아래와 같다.

10:51:08.956 INFO [main]            Started StartupApplication in 2.13 seconds
10:51:09.671 INFO [nio-8080-exec-4] HikariPool-1 - Starting...
10:51:09.831 INFO [nio-8080-exec-4] HikariPool-1 - Start completed.
[request] seq=2 path=/users/1 status=200 server=194109us

Q. JPA 를 켜면 왜 시작할 때 DB 에 연결할까?

A. 처음에는 Hibernate 가 시작할 때 JDBC 메타데이터를 읽기 때문이라고 보고 그 설정만 꺼봤는데, 풀은 여전히 시작 과정에서 만들어졌다.
Hikari 가 풀을 시작하는 순간의 호출 스택을 찍어보면, 연결을 연 곳은 Hibernate 가 아니라 Spring Boot 였다.

com.zaxxer.hikari.HikariDataSource.getConnection
org.springframework.boot.jdbc.EmbeddedDatabaseConnection.isEmbedded
org.springframework.boot.hibernate.autoconfigure.HibernateDefaultDdlAutoProvider.getDefaultDdlAuto
org.springframework.boot.hibernate.autoconfigure.HibernateProperties.determineDdlAuto

spring.jpa.hibernate.ddl-auto 를 지정하지 않으면, Spring Boot 의 HibernateDefaultDdlAutoProvider 가 기본값을 정하려고
EmbeddedDatabaseConnection.isEmbedded() 로 DB 에 연결해서 내장 DB 인지 확인한다. (HibernateDefaultDdlAutoProvider 코드, EmbeddedDatabaseConnection 코드)
내장 DB 가 아니면 none 을 쓰고, 내장 DB 라면 Flyway 같은 스키마 관리 도구가 없을 때만 create-drop 을 쓴다.
Hibernate 도 시작할 때 DB 의 기능을 파악하려고 JDBC 메타데이터를 읽는데, 이 동작은 hibernate.boot.allow_jdbc_metadata_access 로 끌 수 있고 기본값은 켜져 있다. (Hibernate JdbcSettings)
그래서 이 테스트에서는 ddl-auto 를 지정하고, Hibernate 의 메타데이터 조회까지 꺼야 시작할 때 연결이 열리지 않았다.

풀이 시작되는 시점은 JPA 를 쓰는지와 상관없이, 시작하는 동안 DB 에 연결하는 코드가 있는지로 정해진다.
Hibernate 의 메타데이터 조회를 끄면 Dialect 를 직접 지정해야 하는데, DB 버전에 따라 달라지는 기능을 자동으로 맞추지 못할 수 있어서,
시작 시간을 줄이려는 목적이라면 첫 요청이 그 비용을 대신 치른다는 점과 함께 따져보는 편이 좋다.

Q. JPA 를 쓰면 첫 요청 문제가 없는 걸까?

A. 기본 설정의 JPA 는 풀이 이미 만들어져 있어서 첫 /users/1 이 16.8ms 로 짧지만, 반복 요청(1.7ms)과 비교하면 여전히 열 배 정도 길다.
커넥션 풀 말고도 이 경로를 처음 실행하는 비용이 남아 있다는 뜻인데, JVM 쪽에서 무엇이 일어나는지 이어서 살펴보자.

JVM 관점: 첫 요청 경로의 클래스 로딩과 JIT

Spring 의 초기화가 모두 끝나 있어도, JVM 은 첫 요청 경로의 코드를 아직 한 번도 실행하지 않은 상태다.

1) 클래스 로딩

JVM 은 클래스를 처음 쓰는 시점에 로딩하는데, 요청을 처리하는 경로처럼 시작할 때 쓰이지 않은 클래스는 요청이 들어온 뒤에 로딩된다.
-Xlog:class+load 로 로딩된 클래스를 기록하고, Ready 와 요청을 기준으로 구간을 나눠 세보면 아래와 같다.

java -Xlog:class+load:file=class-load.txt:uptimemillis \
     -Xlog:jit+compilation=debug:file=compile.txt:uptimemillis \
     -jar app.jar

Ready 를 readiness 요청으로 확인한 경우와, 요청 없이 로그로만 확인한 경우를 나눠서 비교했다.

요청 없이 Ready 뒤 1.5초를 기다려보면 새로 로딩되는 클래스는 0개였는데, 그 뒤에 readiness 요청을 한 번 보내자 약 550개가 로딩됐다.
readiness 확인 없이 띄운 경우의 "1번째 /hello 전" 약 160개도 Ready 직후가 아니라, /hello 의 연결이 들어온 뒤 측정 필터에 닿기 전에 Tomcat 이 연결과 요청을 읽으면서 로딩한 클래스다.
같은 웹 요청 경로를 거치는 첫 HTTP 요청이 공통 경로의 클래스를 로딩한다는 뜻인데, 이 테스트에서는 readiness 요청이 그 첫 요청이었다.
readiness 확인 없이 /hello 가 첫 요청이 된 경우에는, 처리하는 동안 로딩된 클래스를 묶어보면 아래와 같다.

112  tools.jackson                      ← JSON 직렬화 (Jackson 3)
 50  람다, 프록시 등 런타임 생성 클래스
 31  io.micrometer                      ← HTTP 요청 관측 필터
 25  com.fasterxml                      ← Jackson 어노테이션
 14  org.springframework.web.context
 11  org.springframework.web.servlet
...

readiness 요청이 먼저 들어온 경우에는 이 클래스가 이미 로딩되어 있어서, 첫 /hello 에는 그 API 에만 필요한 11개만 남았고 서버 시간도 58.0ms 에서 6.3ms 로 줄었다.
이 테스트에서는 readiness 응답과 /hello 응답이 Tomcat, Spring MVC, Jackson 경로를 함께 쓰기 때문에, 쿠버네티스에서도 Probe 요청이 공통 경로의 첫 비용 일부를 먼저 치를 수 있다.

Ready 전에 로딩된 클래스 중 약 1,460개는 jar 가 아니라 JDK 에 들어 있는 CDS 아카이브에서 왔다.
CDS 는 클래스를 미리 분석해 둔 파일을 메모리에 매핑해서 로딩을 줄이는 기능인데, JDK 12 부터 JDK 클래스용 기본 아카이브가 켜져 있다.

2) JIT 컴파일

HotSpot JVM 은 처음에는 바이트코드를 인터프리터로 한 줄씩 해석해 실행하다가, 자주 실행되는 메서드를 기계어로 컴파일한다.

OpenJDK 25 소스에 정리된 단계는 아래와 같다.

보통은 0단계에서 3단계로, 프로파일이 충분히 모이면 4단계로 넘어간다.
이 JDK 에서 -XX:+PrintFlagsFinal 로 확인한 기준값은 3단계로 넘어가는 호출 횟수(Tier3InvocationThreshold)가 200, 4단계로 넘어가는 호출 횟수(Tier4InvocationThreshold)가 5000 이다.
실제로는 반복 횟수와 컴파일 대기열 길이도 함께 따지기 때문에, 이 값을 정확한 경계로 보기보다는 수백 번은 불려야 C1, 수천 번은 불려야 C2 로 간다는 감으로 보면 된다.

/hello 를 200번 부르는 동안 컴파일된 메서드 수를 같은 구간으로 나눠보면 아래와 같다. (readiness 확인 후)

클래스 로딩은 첫 요청 무렵에 거의 끝나지만, 컴파일은 요청이 반복되는 동안 계속 일어난다.
Ready 뒤에 컴파일된 메서드를 패키지별로 나눠보면 아래와 같다. (첫 실행 기준)

Spring 메서드가 단계를 옮겨 가는 모습을 컴파일 로그에서 찾아보면 아래와 같다.

org.springframework.util.StringUtils::hasText                3단계 @982ms  (시작 중)  → 4단계 @2956ms (요청 반복 중)
org.springframework.util.Assert::state                       3단계 @633ms  (시작 중)  → 4단계 @2932ms (요청 반복 중)
org.springframework.web.cors.CorsUtils::isPreFlightRequest   3단계 @2792ms (Ready 뒤) → 200번 안에 4단계까지 가지 않음

Spring 의 공통 유틸 메서드는 시작하면서 이미 많이 불려서 C1 으로 컴파일되어 있었고, 요청이 반복되면서 C2 로 넘어갔다.
요청 경로를 처리하는 Spring MVC 메서드는 Ready 뒤에 C1 으로 컴파일됐지만, 요청 한 번에 몇 번만 불려서 200번 안에는 C2 까지 가지 않았다.
C2 로 먼저 넘어간 것은 요청 한 번에 여러 번 불리는 Tomcat 의 바이트 처리 메서드와 JDK 메서드였다.
처음 실행하는 코드는 인터프리터로 돌고, 같은 경로가 반복될수록 C1, C2 로 컴파일된 코드로 바뀐다.
이 테스트는 컴파일 수만 센 것이라, 응답 시간 중 몇 ms 가 인터프리터 실행 때문인지는 따로 나누지 않았다.

첫 요청과 반복 요청

API 마다 애플리케이션을 새로 띄우고 Ready 를 확인한 뒤 같은 API 를 200번 연달아 부르면 응답 시간이 아래와 같이 나온다.

세 API 모두 첫 요청이 11~200번째 요청보다 열 배 넘게 길었고, /users/1 은 백 배 넘게 길었다.
이 테스트에서는 의존하는 대상이 늘어날수록 첫 요청에 더해지는 비용도 커졌다.
2~10번째에서 대부분 줄어드는 것은 연결과 초기화 비용이 첫 요청에서 끝나기 때문으로 볼 수 있고, 그 뒤로 조금씩 더 줄어드는 것은 JIT 컴파일이 이어지는 것과 같은 흐름이다.

Ready 직후 요청이 몰릴 때의 CPU 와 JIT 컴파일

앞의 테스트는 요청을 하나씩 차례로 보낸 결과인데, 실제로는 Ready 가 되자마자 여러 요청이 한꺼번에 들어오는 경우가 많다.
컴파일은 JVM 안의 컴파일러 스레드가 따로 하는데, 요청을 처리하는 스레드와 같은 CPU 를 나눠 쓴다.
새로 뜬 서버로 다른 서버가 요청을 보내기 시작하는 상황을 흉내 내서, Ready 뒤 3초 쉬었다가 k6 로 VU 4개가 /users/1 을 10초 동안 쉬지 않고 호출하게 했다.

CPU 와 컴파일은 JFR(Java Flight Recorder) 로 100ms 마다 기록했다.

java "-XX:StartFlightRecording:filename=app.jfr,dumponexit=true,\
jdk.CPULoad#period=100ms,jdk.ThreadCPULoad#period=100ms,jdk.Compilation#threshold=0ms" \
     -jar app.jar

JFR 의 CPU 값은 장비 전체 코어 대비 비율이라, 읽기 쉽게 코어 수(10)를 곱해서 코어 몇 개를 쓴 셈인지로 바꿨다.

같은 시간 동안 k6 에서 잰 처리량과 응답 시간은 아래와 같다.

요청이 들어온 첫 1초에는 애플리케이션 CPU 의 40% 정도를 컴파일러 스레드가 쓰고, 그동안 C1 컴파일이 3천 번 넘게 일어난다.
같은 시간 처리량은 컴파일이 잦아든 3초 이후의 4분의 1 정도이고, 평균 응답 시간도 4배 가까이 길다.
이 구간에는 요청 코드가 아직 인터프리터나 C1 코드로 도는 비용, 컴파일러 스레드와 CPU 를 나눠 쓰는 비용, 커넥션 풀을 만드는 비용이 함께 들어 있고,
각각이 처리량을 얼마나 떨어뜨렸는지는 나눠서 재지 않았다.
첫 1초의 최대 230.64ms 는 첫 /users/1 요청이 커넥션 풀을 만들면서 걸린 시간이다. (이 테스트는 JDBC 만 쓰는 설정이다)

CPU 제한이 없는 10코어 장비에서 잰 값이라, 쿠버네티스에서 CPU limit 을 작게 잡으면 같은 일을 더 적은 CPU 로 나눠 하게 되어 이 구간이 더 길어질 수 있다.

Tips) 내 애플리케이션에서 확인하는 방법

1) 시작 단계별 시간

BufferingApplicationStartup 을 붙이고 startup 엔드포인트를 노출하면 단계마다 걸린 시간을 JSON 으로 볼 수 있다.

management:
  endpoints:
    web:
      exposure:
        include: health,startup

curl -s localhost:8080/actuator/startup | jq -r '.timeline.events[] | "\(.duration)\t\(.startupStep.name)"' | sort -r | head

2) Liveness, Readiness 가 바뀐 시점

상태가 바뀔 때 남기는 로그는 DEBUG 라서 따로 켜야 한다.

logging:
  level:
    org.springframework.boot.availability: DEBUG

3) 커넥션 풀이 시작된 시점

Hikari 는 풀을 시작할 때 HikariPool-1 - Starting... 을 INFO 로 남기는데, 이 로그가 Started 로그보다 뒤에 있고 요청 스레드(nio-8080-exec-*)에서 찍혔다면 첫 DB 요청이 그 비용을 치렀다고 볼 수 있다.

4) 시작 중 DB 에 연결한 곳

Logback 의 %caller 를 넣으면 로그를 남긴 순간의 호출 스택이 함께 찍혀서 풀을 시작하게 만든 코드를 찾을 수 있다. 모든 로그에 스택이 붙으니 확인할 때만 쓴다.

java -jar app.jar '--logging.pattern.console=%logger{0} : %m%n%caller{40}' | grep -A 12 'HikariPool-1 - Starting'

5) 요청 뒤에 로딩된 클래스와 컴파일

-XX:+PrintCompilation 은 표준 출력에 애플리케이션 로그와 섞여 찍히므로, 같은 내용을 통합 로깅으로 파일에 따로 받는 편이 보기 편하다.

java -Xlog:class+load:file=class-load.txt:uptimemillis \
     -Xlog:jit+compilation=debug:file=compile.txt:uptimemillis \
     -jar app.jar

6) 컴파일러 스레드가 쓰는 CPU

JFR 로 기록한 파일은 JDK 에 들어 있는 jfr 명령으로 꺼내 볼 수 있는데, 스레드별 CPU 에서 컴파일러 스레드만 골라보면 요청이 들어온 직후 얼마나 CPU 를 쓰는지 알 수 있다.

jfr print --events jdk.ThreadCPULoad app.jfr | grep -A 3 'CompilerThread'

정리

첫 요청 비용마다 설정으로 바꿀 수 있는지 정리하면 아래와 같다.

이 테스트에서 설정만으로 큰 차이가 난 것은 lazy-initialization 이었는데,
클래스 로딩과 연결 비용은 Ready 전에 같은 경로를 한 번 실행해 두는 Warm-up 으로 앞당길 수 있고,
JIT 컴파일은 같은 경로가 충분히 반복되어야 진행되기 때문에, Warm-up 을 한다면 몇 번 반복할지도 함께 정하는 편이 좋다.

배포 직후 첫 요청이 중요한 서비스라면 이것만은 확인해보자.

• 무거운 시작 작업이 @PostConstruct 에 있어 포트가 닫힌 채 기다리는지, Runner 에 있어 포트는 열고 readiness 만 늦추는지
• 커넥션 풀이 시작 과정에서 만들어지는지, 첫 DB 요청에서 만들어지는지
• lazy-initialization 을 켰다면 첫 요청에서 얼마나 많은 빈이 만들어지는지
• 외부 API 를 호출한다면 첫 연결(DNS, TCP, TLS)이 첫 요청에 몰리지 않는지
• 첫 요청과 반복 요청의 응답 시간이 얼마나 차이 나는지

📚 Reference

Spring Boot

• Spring Boot - SpringApplication
• Spring Boot - Startup Endpoint
• Spring Boot 4.1.2 - SpringApplication.java
• Spring Boot 4.1.2 - EventPublishingRunListener.java
• Spring Boot 4.1.2 - WebServerStartStopLifecycle.java
• Spring Boot 4.1.2 - WebMvcProperties.java
• Spring Boot 4.1.2 - ServletWebServerApplicationContext.java
• Spring Boot 4.1.2 - HibernateDefaultDdlAutoProvider.java
• Spring Framework 7.0.10 - AbstractApplicationContext.java

DB 커넥션

• HikariCP 7.0.2 - HikariDataSource.java
• Hibernate - JdbcSettings

JVM

• OpenJDK 25 - compilationPolicy.hpp
• Java SE 25 - Java HotSpot Virtual Machine Performance Enhancements
• Java SE 25 - Class Data Sharing
• JEP 341 - Default CDS Archives

관련 글

• Kubernetes Probe 이해하기 - Liveness, Readiness, Startup
• Pod 리소스를 줄였더니 GC가 바뀌었다 - JDK 21 ergonomics를 OTel과 Prometheus로 확인하기