ThreadLocal remove는 가상 스레드를 켜도 남겨 둔다

로그 추적기를 싱글톤 빈 하나로 만들고 요청을 묶는 트랜잭션 ID를 그 필드에 두면, 첫 요청이 끝나기 전에 들어온 두 번째 요청이 같은 ID를 이어 쓴다. 필드를 ThreadLocal로 바꾸면 값이 스레드마다 갈리지만, 톰캣 스레드 풀에서 같은 스레드가 다음 요청을 받으면 remove()로 지우지 않은 값이 그 요청으로 넘어간다. Java 21부터 정식 기능인 가상 스레드를 켜면 차례로 보낸 요청이 매번 다른 가상 스레드에서 처리되어 이 값이 넘어가지 않았다. 그래도 remove() 호출은 가상 스레드를 켜도 코드에서 빼지 않는다. 설정 속성 하나만 되돌려도 요청 스레드가 다시 풀에서 나오기 때문이다

트랜잭션 ID를 싱글톤 필드에 두면 겹친 요청이 같은 ID를 쓴다

로그 추적기는 HTTP 요청 하나에서 일어난 컨트롤러·서비스·리포지토리 호출을 같은 ID로 묶고, 호출 깊이를 화살표 들여쓰기로 보여 준다. 강의는 이 ID를 트랜잭션 ID라고 부르는데, 요청 하나를 묶는 값일 뿐 DB 트랜잭션과는 관계가 없다. 계층마다 다음처럼 begin()으로 시작을 찍고 end()나 exception()으로 끝을 찍는다

@GetMapping("/v3/request")
public String request(String itemId) {
    TraceStatus status = null;
    try {
        status = trace.begin("OrderControllerV3.request()");
        orderService.orderItem(itemId);
        trace.end(status);
        return "ok";
    } catch (Exception e) {
        trace.exception(status, e);
        throw e; //예외를 꼭 다시 던져주어야 한다.
    }
}

ID와 깊이를 서비스와 리포지토리로 넘기는 가장 단순한 방법은 메서드 파라미터다. 그러면 로그를 남기는 모든 메서드의 시그니처에 TraceId가 붙고, 인터페이스가 있으면 인터페이스까지 바꿔야 한다. 그래서 추적기 객체가 지금 쓰는 ID를 필드에 들고 있게 바꾼다

public class FieldLogTrace implements LogTrace {

    private TraceId traceIdHolder; // 요청마다 바뀌는 값을 필드에 둔다

    // ...

    private void syncTraceId() {
        if (traceIdHolder == null) {
            traceIdHolder = new TraceId();                  // 바깥 호출: 새 ID, 깊이 0
        } else {
            traceIdHolder = traceIdHolder.createNextId();   // 안쪽 호출: 같은 ID, 깊이 +1
        }
    }
    // ...
}

이 객체는 @Bean으로 등록한 싱글톤이라 애플리케이션 컨텍스트에 하나뿐이고, 모든 요청 스레드가 같은 traceIdHolder를 읽고 쓴다. 요청을 한 번씩 보낼 때는 문제가 드러나지 않는다. 리포지토리의 저장은 일부러 1초가 걸리게 해 두었다. 첫 요청이 그 1초를 쓰는 동안 두 번째 요청이 들어오도록 0.1초 간격으로 요청을 보내면 로그는 다음과 같다. 각 줄은 시각, 요청을 받은 스레드, 로거 이름, 메시지 순이고, 메시지 앞 대괄호 안이 트랜잭션 ID다

19:54:18.231 [http-nio-18081-exec-2] FieldLogTrace : [959b8ef1] OrderControllerV3.request()
19:54:18.232 [http-nio-18081-exec-2] FieldLogTrace : [959b8ef1] |-->OrderServiceV3.orderItem()
19:54:18.232 [http-nio-18081-exec-2] FieldLogTrace : [959b8ef1] |    |-->OrderRepositoryV3.save()
19:54:18.335 [http-nio-18081-exec-3] FieldLogTrace : [959b8ef1] |    |    |-->OrderControllerV3.request()
19:54:18.336 [http-nio-18081-exec-3] FieldLogTrace : [959b8ef1] |    |    |    |-->OrderServiceV3.orderItem()
19:54:18.336 [http-nio-18081-exec-3] FieldLogTrace : [959b8ef1] |    |    |    |    |-->OrderRepositoryV3.save()
19:54:19.232 [http-nio-18081-exec-2] FieldLogTrace : [959b8ef1] |    |<--OrderRepositoryV3.save(), time=1000ms
19:54:19.233 [http-nio-18081-exec-2] FieldLogTrace : [959b8ef1] |<--OrderServiceV3.orderItem(), time=1002ms
19:54:19.233 [http-nio-18081-exec-2] FieldLogTrace : [959b8ef1] OrderControllerV3.request(), time=1002ms
19:54:19.340 [http-nio-18081-exec-3] FieldLogTrace : [959b8ef1] |    |    |    |    |<--OrderRepositoryV3.save(), time=1004ms
19:54:19.341 [http-nio-18081-exec-3] FieldLogTrace : [959b8ef1] |    |    |    |<--OrderServiceV3.orderItem(), time=1005ms
19:54:19.341 [http-nio-18081-exec-3] FieldLogTrace : [959b8ef1] |    |    |<--OrderControllerV3.request(), time=1006ms

두 번째 요청은 다른 스레드가 받았는데도 새 ID가 만들어지지 않았다. 첫 요청이 필드에 남겨 둔 ID를 그대로 이어받아 깊이 3에서 시작했고, 두 요청의 로그가 한 요청의 깊은 호출처럼 계단을 이룬다. 필드를 읽기만 한다면 요청이 겹쳐도 문제가 없다. 문제는 요청마다 값을 바꿔 쓰는 필드이고, 요청이 몰릴수록 자주 겹치므로 개발 중에 한 번씩 호출해 보는 것으로는 드러나지 않는다

ThreadLocal은 값을 스레드마다 나누지만 비우는 일은 코드에 남는다

ThreadLocal은 같은 변수를 읽어도 스레드마다 다른 값을 돌려주는 JDK 클래스다. 싱글톤의 필드 한 칸을 스레드별 칸으로 나눈다고 보면 된다. 필드를 ThreadLocal<TraceId>로 바꾸고, 가장 바깥 호출이 끝날 때 remove()로 비운다

public class ThreadLocalLogTrace implements LogTrace {

    private ThreadLocal<TraceId> traceIdHolder = new ThreadLocal<>();

    // ...

    private void releaseTraceId() {
        TraceId traceId = traceIdHolder.get();
        if (traceId.isFirstLevel()) {
            traceIdHolder.remove(); // 가장 바깥 호출이 끝나면 이 스레드의 값을 지운다
        } else {
            traceIdHolder.set(traceId.createPreviousId());
        }
    }
}

releaseTraceId()는 end()와 exception()이 함께 거치는 마무리 단계라 예외로 끝난 요청도 값을 지운다. 같은 조건으로 두 요청을 겹쳐 보낸 로그다

19:54:27.174 [http-nio-18081-exec-3] ThreadLocalLogTrace : [fb3d032c] OrderControllerV3.request()
19:54:27.174 [http-nio-18081-exec-3] ThreadLocalLogTrace : [fb3d032c] |-->OrderServiceV3.orderItem()
19:54:27.174 [http-nio-18081-exec-3] ThreadLocalLogTrace : [fb3d032c] |    |-->OrderRepositoryV3.save()
19:54:27.286 [http-nio-18081-exec-4] ThreadLocalLogTrace : [60cbcc57] OrderControllerV3.request()
19:54:27.286 [http-nio-18081-exec-4] ThreadLocalLogTrace : [60cbcc57] |-->OrderServiceV3.orderItem()
19:54:27.286 [http-nio-18081-exec-4] ThreadLocalLogTrace : [60cbcc57] |    |-->OrderRepositoryV3.save()
19:54:28.179 [http-nio-18081-exec-3] ThreadLocalLogTrace : [fb3d032c] |    |<--OrderRepositoryV3.save(), time=1005ms
19:54:28.180 [http-nio-18081-exec-3] ThreadLocalLogTrace : [fb3d032c] |<--OrderServiceV3.orderItem(), time=1006ms
19:54:28.180 [http-nio-18081-exec-3] ThreadLocalLogTrace : [fb3d032c] OrderControllerV3.request(), time=1006ms
19:54:28.292 [http-nio-18081-exec-4] ThreadLocalLogTrace : [60cbcc57] |    |<--OrderRepositoryV3.save(), time=1006ms
19:54:28.293 [http-nio-18081-exec-4] ThreadLocalLogTrace : [60cbcc57] |<--OrderServiceV3.orderItem(), time=1007ms
19:54:28.293 [http-nio-18081-exec-4] ThreadLocalLogTrace : [60cbcc57] OrderControllerV3.request(), time=1007ms

두 요청은 스레드마다 다른 ID로 각자 깊이 0에서 시작해 0으로 돌아왔다. 로거 이름이 FieldLogTrace에서 ThreadLocalLogTrace로 바뀐 것은 구현체가 바뀌었다는 표시다. 바꾼 곳은 설정 클래스에서 빈을 등록하는 한 줄이고, 컨트롤러·서비스·리포지토리 코드는 그대로다

remove()를 빠뜨렸을 때 무슨 일이 생기는지는 스레드 풀이 정한다. 강의는 톰캣이 요청을 마친 스레드를 버리지 않고 풀에 돌려놓았다가 다음 요청에 다시 쓰기 때문에, 사용자 A가 남긴 값을 사용자 B의 요청이 읽게 된다고 설명한다. 풀에서 어느 스레드가 다음 요청을 받을지는 정해져 있지 않으므로, 같은 스레드가 다음 요청을 받는 상황을 확실히 만들려면 톰캣 요청 스레드를 하나로 줄이면 된다

server.tomcat.threads.max=1

이 설정에 더해 remove() 줄을 주석으로 막고 요청 세 번을 차례로 보낸 로그다

19:54:41.032 [http-nio-18081-exec-1] ThreadLocalLogTrace : [89a6fac6] OrderControllerV3.request()
19:54:41.033 [http-nio-18081-exec-1] ThreadLocalLogTrace : [89a6fac6] |-->OrderServiceV3.orderItem()
19:54:41.033 [http-nio-18081-exec-1] ThreadLocalLogTrace : [89a6fac6] |    |-->OrderRepositoryV3.save()
19:54:42.035 [http-nio-18081-exec-1] ThreadLocalLogTrace : [89a6fac6] |    |<--OrderRepositoryV3.save(), time=1002ms
19:54:42.035 [http-nio-18081-exec-1] ThreadLocalLogTrace : [89a6fac6] |<--OrderServiceV3.orderItem(), time=1002ms
19:54:42.035 [http-nio-18081-exec-1] ThreadLocalLogTrace : [89a6fac6] OrderControllerV3.request(), time=1003ms
19:54:42.053 [http-nio-18081-exec-1] ThreadLocalLogTrace : [89a6fac6] |-->OrderControllerV3.request()
19:54:42.053 [http-nio-18081-exec-1] ThreadLocalLogTrace : [89a6fac6] |    |-->OrderServiceV3.orderItem()
19:54:42.054 [http-nio-18081-exec-1] ThreadLocalLogTrace : [89a6fac6] |    |    |-->OrderRepositoryV3.save()
19:54:43.057 [http-nio-18081-exec-1] ThreadLocalLogTrace : [89a6fac6] |    |    |<--OrderRepositoryV3.save(), time=1003ms
19:54:43.058 [http-nio-18081-exec-1] ThreadLocalLogTrace : [89a6fac6] |    |<--OrderServiceV3.orderItem(), time=1005ms
19:54:43.058 [http-nio-18081-exec-1] ThreadLocalLogTrace : [89a6fac6] |<--OrderControllerV3.request(), time=1005ms
19:54:43.083 [http-nio-18081-exec-1] ThreadLocalLogTrace : [89a6fac6] |-->OrderControllerV3.request()
19:54:43.083 [http-nio-18081-exec-1] ThreadLocalLogTrace : [89a6fac6] |    |-->OrderServiceV3.orderItem()
19:54:43.084 [http-nio-18081-exec-1] ThreadLocalLogTrace : [89a6fac6] |    |    |-->OrderRepositoryV3.save()
19:54:44.089 [http-nio-18081-exec-1] ThreadLocalLogTrace : [89a6fac6] |    |    |<--OrderRepositoryV3.save(), time=1005ms
19:54:44.089 [http-nio-18081-exec-1] ThreadLocalLogTrace : [89a6fac6] |    |<--OrderServiceV3.orderItem(), time=1006ms
19:54:44.089 [http-nio-18081-exec-1] ThreadLocalLogTrace : [89a6fac6] |<--OrderControllerV3.request(), time=1006ms

첫 요청은 깊이 0으로 끝났지만 remove()가 없어 깊이 0의 TraceId가 스레드에 남았다. 같은 스레드가 받은 두 번째·세 번째 요청은 그 값을 이어받아 첫 요청과 같은 ID로 깊이 1에서 시작했다. 로그 추적기라면 다른 요청의 로그가 섞이는 정도로 끝나지만, ThreadLocal에 로그인 사용자 정보를 담았다면 다른 사용자의 정보로 요청을 처리할 수 있다. JDK의 기능 제안 문서인 JEP 506도 스레드 풀에서 제대로 지우지 않은 ThreadLocal 값이 상관없는 작업으로 새어 나가면 위험한 보안 취약점으로 이어질 수 있다고 경고한다(JEP 506: Scoped Values)

그래서 요청 문맥을 ThreadLocal에 넣는 코드는 비우는 일까지 맡는다. 앞의 releaseTraceId()처럼 추적기 안에서 비우거나, 요청이 드나드는 경계에서 비운다. 경계마다 비우는 자리가 다르다

  • 서블릿 필터: chain.doFilter()를 try/finally로 감싸 finally에서 비운다
  • 동기 요청을 처리하는 인터셉터: afterCompletion()에서 비운다. 이 메서드는 preHandle()이 true를 돌려준 경우에만 불리므로(HandlerInterceptor — afterCompletion), preHandle()에서 값을 넣고 false를 돌려주는 경로가 있다면 그 경로에서 직접 비운다
  • 비동기 요청: 원래 스레드에서는 afterCompletion()이 불리지 않으므로 AsyncHandlerInterceptor의 afterConcurrentHandlingStarted()에서 비운다. 문서도 이 메서드의 대표적인 쓰임으로 ThreadLocal 정리를 든다(AsyncHandlerInterceptor)

가상 스레드는 지난 요청의 값을 남기지 않지만 그 조건은 설정이 정한다

강의도 풀의 스레드를 다시 쓰는 경우를 문제로 들면서, 스레드 자체가 끝나면 상관없을 수 있다는 단서를 단다. 강의가 나온 2021년에는 없던 가상 스레드(virtual thread)가 그 경우다. 가상 스레드는 Java 21에서 정식 기능이 된 가벼운 스레드로, 운영체제 스레드에 1:1로 묶이지 않고 JDK가 스케줄링한다. JEP 444는 가상 스레드도 ThreadLocal을 그대로 지원한다고 밝히면서, 가상 스레드는 싸고 얼마든지 만들 수 있으니 풀에 담아 재사용하지 말고 작업마다 새로 만들라고 한다(JEP 444: Virtual Threads)

Spring Boot에서는 속성 하나로 켜고, 켜면 스레드 풀을 설정하는 속성은 더 이상 효과가 없다(Spring Boot — Virtual threads)

spring.threads.virtual.enabled=true

remove()를 막아 둔 같은 코드에, 톰캣 스레드를 하나로 제한한 설정은 그대로 둔 채 이 속성을 더하고 요청 세 번을 차례로 보냈다

19:54:53.131 [tomcat-handler-1] ThreadLocalLogTrace : [aa1571c5] OrderControllerV3.request()
19:54:53.132 [tomcat-handler-1] ThreadLocalLogTrace : [aa1571c5] |-->OrderServiceV3.orderItem()
19:54:53.132 [tomcat-handler-1] ThreadLocalLogTrace : [aa1571c5] |    |-->OrderRepositoryV3.save()
19:54:54.137 [tomcat-handler-1] ThreadLocalLogTrace : [aa1571c5] |    |<--OrderRepositoryV3.save(), time=1005ms
19:54:54.137 [tomcat-handler-1] ThreadLocalLogTrace : [aa1571c5] |<--OrderServiceV3.orderItem(), time=1005ms
19:54:54.137 [tomcat-handler-1] ThreadLocalLogTrace : [aa1571c5] OrderControllerV3.request(), time=1006ms
19:54:54.159 [tomcat-handler-3] ThreadLocalLogTrace : [95c769b5] OrderControllerV3.request()
19:54:54.159 [tomcat-handler-3] ThreadLocalLogTrace : [95c769b5] |-->OrderServiceV3.orderItem()
19:54:54.159 [tomcat-handler-3] ThreadLocalLogTrace : [95c769b5] |    |-->OrderRepositoryV3.save()
19:54:55.163 [tomcat-handler-3] ThreadLocalLogTrace : [95c769b5] |    |<--OrderRepositoryV3.save(), time=1004ms
19:54:55.163 [tomcat-handler-3] ThreadLocalLogTrace : [95c769b5] |<--OrderServiceV3.orderItem(), time=1004ms
19:54:55.163 [tomcat-handler-3] ThreadLocalLogTrace : [95c769b5] OrderControllerV3.request(), time=1004ms
19:54:55.190 [tomcat-handler-4] ThreadLocalLogTrace : [1b3f1070] OrderControllerV3.request()
19:54:55.190 [tomcat-handler-4] ThreadLocalLogTrace : [1b3f1070] |-->OrderServiceV3.orderItem()
19:54:55.190 [tomcat-handler-4] ThreadLocalLogTrace : [1b3f1070] |    |-->OrderRepositoryV3.save()
19:54:56.191 [tomcat-handler-4] ThreadLocalLogTrace : [1b3f1070] |    |<--OrderRepositoryV3.save(), time=1001ms
19:54:56.191 [tomcat-handler-4] ThreadLocalLogTrace : [1b3f1070] |<--OrderServiceV3.orderItem(), time=1001ms
19:54:56.191 [tomcat-handler-4] ThreadLocalLogTrace : [1b3f1070] OrderControllerV3.request(), time=1001ms

세 요청은 모두 다른 스레드에서 처리됐고 트랜잭션 ID도 매번 새로 만들어져 깊이 0에서 시작했다. 스레드 이름이 http-nio-로 시작하던 것이 tomcat-handler-로 시작하게 바뀐 것은, Spring Boot가 요청 처리를 톰캣의 가상 스레드 실행기(작업을 받아 스레드에 맡기는 Executor)에 넘겼다는 표시다(TomcatVirtualThreadsWebServerFactoryCustomizer — Spring Boot 4.1.1)

스레드를 하나로 제한한 풀 설정은 문서에 적힌 대로 적용되지 않았다. 이 실행기는 작업마다 새 가상 스레드를 만든다고 문서화되어 있으니(VirtualThreadExecutor — Tomcat 11), 앞 요청이 ThreadLocal에 남긴 값은 다음 요청에 닿지 않는다. 가상 스레드에서는 요청 세 번을 차례로 보낸 한 번의 실행만 확인했고, 동시에 겹친 요청과 @Async 같은 다른 실행 경로는 확인하지 않았다

그래도 remove() 호출은 빼지 않는다. 값이 남지 않은 이유는 요청 스레드를 만드는 방식에 있고, 그 방식은 코드 바깥의 속성 하나가 정한다. 속성을 되돌리면 톰캣은 다시 풀의 스레드로 요청을 처리하고, 그 결과가 앞 절의 로그다

요청 스레드 밖도 같은 구조다. Spring Boot가 자동 구성하는 비동기 실행기는 가상 스레드를 켜면 SimpleAsyncTaskExecutor, 끄면 ThreadPoolTaskExecutor이고, 직접 등록한 Executor 빈이 있으면 @EnableAsync로 켠 @Async 메서드는 그 빈에서 돈다(Task Execution and Scheduling). 그 빈이 스레드 풀이면 가상 스레드를 켜 두어도 앞 작업이 ThreadLocal에 남긴 값이 다음 작업으로 넘어갈 수 있다. 스레드 1개짜리 고정 풀과 작업마다 가상 스레드를 만드는 실행기를 같은 절차의 테스트 두 개로 비교하면 차이가 보인다

@Slf4j
class ScopedValueTraceTest {

    static final ThreadLocal<String> TRACE_ID_LOCAL = new ThreadLocal<>();

    @Test
    void threadLocalLeaksInFixedPool() throws Exception {
        try (ExecutorService pool = Executors.newFixedThreadPool(1)) {
            pool.submit(() -> TRACE_ID_LOCAL.set("a1b2c3d4")).get();
            String seen = pool.submit(TRACE_ID_LOCAL::get).get();
            log.info("fixed pool, second task sees={}", seen);
            assertThat(seen).isEqualTo("a1b2c3d4");
        }
    }

    @Test
    void threadLocalDoesNotLeakAcrossVirtualThreads() throws Exception {
        try (ExecutorService vt = Executors.newVirtualThreadPerTaskExecutor()) {
            vt.submit(() -> TRACE_ID_LOCAL.set("a1b2c3d4")).get();
            String seen = vt.submit(TRACE_ID_LOCAL::get).get();
            log.info("virtual per task, second task sees={}", seen);
            assertThat(seen).isNull();
        }
    }
    // ...
}

두 테스트의 로그다

19:55:04.565 [Test worker] INFO hello.advanced.trace.scoped.ScopedValueTraceTest -- virtual per task, second task sees=null
19:55:04.569 [Test worker] INFO hello.advanced.trace.scoped.ScopedValueTraceTest -- fixed pool, second task sees=a1b2c3d4

고정 풀에서는 두 번째 작업이 첫 작업이 남긴 값을 읽었고, 가상 스레드 실행기에서는 null을 읽었다. 같은 코드가 어느 실행기 위에서 도느냐에 따라 결과가 갈리므로, 비우는 코드는 가상 스레드 설정과 상관없이 그대로 둔다

ScopedValue는 범위가 끝나면 값을 지우지만 begin과 end를 나눈 API와는 맞지 않는다

JDK 25에는 ThreadLocal을 대신할 수 있는 ScopedValue가 정식 기능으로 들어왔다(JEP 506: Scoped Values). 정식 기능이라 미리 보기 기능을 켜는 --enable-preview 옵션 없이 컴파일된다. JEP 506은 ThreadLocal의 약점으로 어느 코드든 값을 바꿀 수 있다는 점, 값이 스레드가 살아 있는 동안 남는다는 점, 자식 스레드에 물려줄 때 비용이 크다는 점을 든다. ScopedValue는 값을 한 번 묶고, 묶은 범위가 실행되는 동안에만 보여 준다. 같은 테스트 클래스의 다음 테스트로 확인할 수 있다

class ScopedValueTraceTest {
    // ...
    static final ScopedValue<String> TRACE_ID = ScopedValue.newInstance();

    @Test
    void scopedValueIsBoundOnlyInsideRun() {
        ScopedValue.where(TRACE_ID, "a1b2c3d4").run(() -> {
            log.info("controller sees={}", TRACE_ID.get());
            service();
        });
        log.info("after run, isBound={}", TRACE_ID.isBound());
        assertThat(TRACE_ID.isBound()).isFalse();
    }

    private void service() {
        log.info("service sees={}", TRACE_ID.get());
    }
}

실행하면 다음 로그가 남는다

19:55:04.492 [Test worker] INFO hello.advanced.trace.scoped.ScopedValueTraceTest -- controller sees=a1b2c3d4
19:55:04.497 [Test worker] INFO hello.advanced.trace.scoped.ScopedValueTraceTest -- service sees=a1b2c3d4
19:55:04.497 [Test worker] INFO hello.advanced.trace.scoped.ScopedValueTraceTest -- after run, isBound=false

run() 안에서 부른 service()도 파라미터 없이 같은 값을 읽고, run()이 끝나면 묶어 둔 값이 사라져 isBound()가 false를 돌려준다. 비우는 코드를 쓸 일이 없으니 앞에서 본 누수는 구조상 생기지 않는다

대신 값은 바꿀 수 없다. 로그 추적기의 깊이처럼 안쪽 호출에서 달라지는 값은 안쪽 범위에서 다시 묶어야 한다

@Test
void scopedValueRebindsForNestedLevel() {
    ScopedValue.where(TRACE_ID, "a1b2c3d4|0").run(() -> {
        log.info("level0 sees={}", TRACE_ID.get());
        ScopedValue.where(TRACE_ID, "a1b2c3d4|1").run(() -> log.info("level1 sees={}", TRACE_ID.get()));
        log.info("back to level0 sees={}", TRACE_ID.get());
        assertThat(TRACE_ID.get()).isEqualTo("a1b2c3d4|0");
    });
}

중첩 테스트의 로그다

19:55:04.555 [Test worker] INFO hello.advanced.trace.scoped.ScopedValueTraceTest -- level0 sees=a1b2c3d4|0
19:55:04.556 [Test worker] INFO hello.advanced.trace.scoped.ScopedValueTraceTest -- level1 sees=a1b2c3d4|1
19:55:04.556 [Test worker] INFO hello.advanced.trace.scoped.ScopedValueTraceTest -- back to level0 sees=a1b2c3d4|0

안쪽 범위가 끝나면 바깥 값으로 저절로 돌아오므로 createPreviousId() 같은 되돌리기 코드도 필요 없다. 걸리는 것은 범위를 람다로 넘겨야 한다는 점이다. 앞의 컨트롤러에서 보듯 지금의 LogTrace는 begin()이 돌려준 상태를 들고 있다가 try 블록의 다른 줄에서 end()를, catch에서 exception()을 부르는 API라서, 시작과 끝 사이를 람다 하나로 넘길 자리가 없다. ScopedValue로 옮기려면 추적기 API부터 “메시지와 실행할 코드를 받아 그 범위 안에서 실행한다”는 모양으로 바꿔야 한다. 계층마다 반복되는 try/catch와 begin/end를 걷어 내는 템플릿 콜백 패턴이 그 모양이고, 다음 편에서 다룬다

JEP 506은 ThreadLocal을 그대로 두는 편이 나은 경우도 든다. 호출 깊은 곳에서 ThreadLocal.set으로 멀리 있는 호출자에게 값을 돌려보내는 식으로 값을 양방향으로 주고받거나 아무 구조 없이 쓰는 코드는 옮길 수 없다. 만들기 비싼 객체를 스레드마다 캐시해 두는 것은 ThreadLocal이 유리한 대표적인 예다. 다만 JEP 444는 스레드 풀에서 작업마다 가상 스레드를 만드는 방식으로 옮길 때 이 관용구를 조심하라고 한다. 가상 스레드는 작업마다 새로 만들어지므로, 스레드마다 캐시하면 작업마다 비싼 객체를 새로 만드는 셈이 되어 성능이 크게 떨어질 수 있다. 요청 하나 동안 위에서 아래로만 내려가는 트랜잭션 ID는 호출자에게 값을 돌려보내지도, 스레드마다 캐시하지도 않으니 ScopedValue로 옮길 수 있는 값이다

요청 문맥을 싱글톤 필드에 두면 겹친 요청이 같은 ID를 이어 쓰고, ThreadLocal로 옮기면 스레드마다 갈리지만 풀의 스레드에는 값이 남는다. 가상 스레드에서는 남은 값이 다음 요청에 닿지 않았지만, 그 조건은 속성 하나가 바꾸고 요청 밖의 실행기는 따로 정해진다. 지금의 begin/end 구조에서는 remove()를 지키고, 비우는 일 자체를 없애려면 ScopedValue가 요구하는 대로 추적 범위를 콜백으로 감싸는 구조를 먼저 만든다

출처와 범위

인프런 김영한님의 「스프링 핵심 원리 – 고급편」 강의를 듣고, 강의를 따라 만든 예제를 Spring Boot 4.1.1(Tomcat 11.0.24)과 Java 25로 옮겨 실행하며 썼다. 실험은 조건마다 한 번씩 실행했다. 로그 패턴은 시각·스레드·로거·메시지만 남겼고, 측정 전에 추적 로그가 없는 요청을 한 번 보내 서버 초기화를 마쳤다. 2026년 11월 4일 기준 공식 문서 대조와 비교 실험 코드 작성, 원고 정리에 AI(Claude)를 썼다

참고 자료