Huge Performance Overhead From ContextPropagation With Micrometer Tracing

Huge Performance Overhead From ContextPropagation With Micrometer Tracing

Micrometer Tracing을 사용하는 Context Propagation에서 발생하는 심각한 성능 오버헤드

https://github.com/reactor/reactor-core/issues/3840

Huge Performance Overhead From ContextPropagation With Mircrometer Tracing · Issue #3840 · reactor/reactor-core

 

Expected

로깅 기능에 의한 오버헤드는 업계 표준으로 5%를 넘지 않아야 함

 

Actual

Spring WebFlux 애플리케이션에서 Micrometer + Brave 기반의 Tracing을 사용하면
ThreadLocal 복원 작업(Context Propagation)이 과도하게 발생하여 25~30% 이상의 성능 저하가 발생함

 

 

재현방법 ( Steps to reproduce)

동일 JVM 내에서 Spring WebFlux 요청을 처리하면서 trace-id를 MDC에 넣어 로그에 출력하려는 간단한 시나리오.
Micrometer Observation + Brave Tracing + SLF4J MDC 조합 사용.

 

https://private-user-images.githubusercontent.com/17241575/346383859-d7ab0d1e-cba7-4650-88e9-7f567cf61caf.png?jwt=eyJ0eXAiOiJKV1QiLCJhbGciOiJIUzI1NiJ9.eyJpc3MiOiJnaXRodWIuY29tIiwiYXVkIjoicmF3LmdpdGh1YnVzZXJjb250ZW50LmNvbSIsImtleSI6ImtleTUiLCJleHAiOjE3NTk3MzMwMDUsIm5iZiI6MTc1OTczMjcwNSwicGF0aCI6Ii8xNzI0MTU3NS8zNDYzODM4NTktZDdhYjBkMWUtY2JhNy00NjUwLTg4ZTktN2Y1NjdjZjYxY2FmLnBuZz9YLUFtei1BbGdvcml0aG09QVdTNC1ITUFDLVNIQTI1NiZYLUFtei1DcmVkZW50aWFsPUFLSUFWQ09EWUxTQTUzUFFLNFpBJTJGMjAyNTEwMDYlMkZ1cy1lYXN0LTElMkZzMyUyRmF3czRfcmVxdWVzdCZYLUFtei1EYXRlPTIwMjUxMDA2VDA2MzgyNVomWC1BbXotRXhwaXJlcz0zMDAmWC1BbXotU2lnbmF0dXJlPThkZTMyNGNjMDUwMzNlYTg5MjhjMTEyNDNhNzQzZjk1NDg4ZGU0NmM3YjkzNGMxYWE4NzNmN2FhMTU3NGEyNTUmWC1BbXotU2lnbmVkSGVhZGVycz1ob3N0In0.J_atwfAe-F65XMEOwSECg5ucbuS3YtMwMOKj86R2zGc

 

관련 stackoverflow : https://stackoverflow.com/questions/78677203/moving-from-reactor-3-5-to-3-6-in-spring-flux-shows-large-increase-in-cpu-due-to

 

Environment

Reactor version(s) used: reactor-core:3.6.7
Other relevant libraries versions (eg. netty, ...): spring-webflux:3.3.1
io.micrometer:1.13.1
JVM version (java -version): java17
OS and version (eg uname -a): windows 11

 

 

Root Cause

ThreadLocal은 Reactive 모델과 충돌합니다.

• Reactive 체인은 스레드를 자유롭게 넘나들기 때문에, TL 값이 유실되거나 다른 요청에 누출(leak)될 수 있음.

Reactor 3.5 이전: TL 복원이 일부 연산자(예: handle, tap)에서만 수행 → 로깅 위치 제한, 마이그레이션 어려움

Reactor 3.6: "자동 모드(automatic propagation)" 도입 → 모든 스레드 전환 지점에서 TL을 복원/정리

• ✅ 장점: 어디서나 trace-id 사용 가능, 누출 방지
• ❌ 단점: 매 연산자마다 TL 복원/정리 → 성능 오버헤드 급증

 

Solution

조치/해결: Reactor 팀이 일부 특수 연산자에서 자동 전파를 건너뛰도록(skip) 최적화 PR들을 머지했고(예: #3845, #3848), 이 변경이 포함된 3.6.9 릴리스로 성능 개선이 보고됨(케이스에 따라 크게 개선됨)

 

---

 

원인 분석 (단계적으로)

 maintainer(chemicL)가 설명한 핵심 논리

1. 문맥 보관 방식 차이(동기 vs 비동기):
   전통적인 로깅(MDC/SLF4J/Logback)은 ThreadLocal을 사용해 "현재 쓰레드에 바인딩된" 컨텍스트(예: trace id)를 읽습니다. 반면 리액티브(reactive) 환경은 쓰레드에 종속되지 않고, 작업이 여러 쓰레드/스케줄러로 옮겨가며 실행됩니다. 따라서 ThreadLocal 복원을 명시적으로 하지 않으면 로그에서 trace-id가 사라질 수 있음. GitHub
2. 3.5에서의 접근(초기 방식):
   Reactor 3.5대에서는 tap() 같은 연산자를 통해 특정 지점에서 ThreadLocal을 복원하는 패턴이 사용됐습니다. 이 방식은 모든 연산자에서 항상 복원해 주지는 않아서, 기존(비반응형) 코드가 기대하던 "어디서든 MDC가 항상 있다"는 동작을 보장하지 못함. 즉, 일부 연산자에서는 로그에 trace-id가 빠질 수 있었습니다. GitHub
3. 자동 모드(automatic mode)의 도입과 비용:
   사용자 경험(기대)을 맞추기 위해 3.6에서 자동 전파 모드가 강화되었고, 가능한 많은 “문맥 누락” 케이스를 잡기 위해 더 광범위하게 ThreadLocal을 복원/정리하도록 구현되었습니다. 그러나 이로 인해 비동기 연속(continuation) 마다 restore/clear를 많이 하게 되고(연산자/체인의 모양에 따라 빈도 증가), 그 자체가 비용(특히 Micrometer의 Slf4jThreadLocalAccessor가 MDC를 조작하는 비용)을 유발합니다. GitHub
4. 실제 프로파일러 결과:
   한 사례에서는 3.5 → 3.6으로 가며 FluxContextWriteRestoringThreadLocals$...Subscriber.onNext(...) 호출과 decorateScope 등 호출이 대폭 증가했고, MDC.put 호출 수가 크게 늘어 CPU 사용량과 총 실행 시간이 증가한 것을 확인함.