들어가며: 로깅 시스템을 구축하면서 마주친 문제
프로젝트 초기, AOP를 활용한 기본 로깅 시스템을 구축했다. "모든 메서드 호출을 기록하면 되겠지"라는 단순한 생각으로 시작했다.
2025-01-10 14:23:45 INFO Begin: UserService.findById, args=[123]
2025-01-10 14:23:45 INFO Begin: OrderService.createOrder, args=[{userId=456, ...}]
2025-01-10 14:23:45 INFO Begin: ProductService.checkStock, args=[789]
2025-01-10 14:23:45 INFO Begin: OrderRepository.save, args=[Order{...password=secret123...}]로컬에서 테스트할 때는 문제없어 보였다. 하지만 실제로 여러 기능을 구현하고, 로그 파일을 열어보는 순간 현실을 마주했다:
발견한 문제점들:
- 동시 요청 시 로그가 완전히 섞임
- 민감정보가 그대로 노출됨
- 불필요한 로그로 인한 노이즈
- 로그 레벨 구분이 없음
"이 정도면 충분하겠지"라고 생각했던 로깅이, 실제로는 오히려 문제 해결을 방해하고 있었다.
"이 에러가 어느 사용자 요청에서 발생한 건지 모르겠어요"라고 했을 때, 로그를 한참 뒤적여야 했다. 같은 스레드 이름(exec-3)에 완전히 다른 두 요청의 로그가 뒤섞여 있었기 때문이다.
제대로 된 로깅 시스템을 구축해야 한다는 필요성을 절실히 느낀 순간이었다.
첫 번째 시도: 스레드 이름으로 구분
시도한 이유: "같은 요청은 같은 스레드니까 스레드 이름으로 구분하자"
log.info("[{}] Controller - BEGIN", Thread.currentThread().getName());문제
[exec-1] UserController.login - BEGIN
[exec-1] UserController.login - END
// 스레드 반납
[exec-1] UserController.getUserById - BEGIN // 같은 스레드!각각 독립적인 요청 두 개가 같은 스레드로 찍혔다.
근본 원인: 톰캣 스레드 풀
톰캣은 스레드를 재사용한다.
- 100개 요청 -> 10개 스레드 사용
- 각 스레드가 평균 10번 재사용
같은 스레드 != 같은 요청
MDC 발견과 Aspect 구현
MDC(Mapped Diagnostic Context)란?
로그 추적 방법을 찾던 중 SLF4J의 MDC를 발견했다. MDC는 현재 스레드에 컨텍스트 정보를 저장할 수 있는 구조다.
내부 구조
본질적으로 MDC는 ThreadLocal을 기반으로 동작한다.SLF4J는 로깅 파사드(Logging Facade)이므로, 실제 MDC 구현은 로깅 프레임워크에 따라 다르다. 하지만 모든 구현체가 ThreadLocal을 사용한다는 공통점이 있다.
// 내부 동작 원리
private static final ThreadLocal<Map<String, String>> threadLocalMap = new ThreadLocal<>();Aspect 구현
모든 레이어(Controller, Service, Repository)에서 로깅이 필요했기 때문에, AOP로 관리하면 편할 것 같았다:
@Around("controllerPointcut()")
public Object controllerLog(ProceedingJoinPoint joinPoint) throws Throwable {
MDC.put("traceId", UUID.randomUUID().toString().substring(0, 8));
try {
log.info("Controller BEGIN");
return joinPoint.proceed();
} finally {
MDC.clear();
}
}기대 결과
[a1b2c3d4] Controller BEGIN
[a1b2c3d4] Service BEGIN
[a1b2c3d4] Service END
[a1b2c3d4] Controller ENDMDC.clear() 타이밍 문제
증상
[a1b2c3d4] Controller BEGIN
[a1b2c3d4] Service BEGIN
[a1b2c3d4] Service END
[] Controller END // traceId 사라짐!AOP 중첩 실행 순서
1. Controller AOP → MDC.put("a1b2c3d4")
2. Controller → Service 호출
3. Service AOP → 로그 정상 출력
4. Service AOP finally → MDC.clear()
5. Controller 복귀 → traceId = null핵심 문제
ThreadLocal 은 스레드당 하나의 저장소를 공유:
Thread-1
└─ {"traceId": "a1b2c3d4"} // Controller와 Service가 같은 Map 공유Service의 MDC.clear()가 Controller에도 영향을 준다.
검증 테스트
MDC.put("traceId", "abc123");
log.info("Controller BEGIN"); // [abc123]
try {
try {
log.info("Service BEGIN"); // [abc123]
} finally {
MDC.clear(); // !!!
}
log.info("Controller END"); // []
} finally {
MDC.clear();
}Filter
비교표
| 기준 | Filter | Interceptor | Aspect |
|---|---|---|---|
| 실행 시점 | DispatcherServlet 이전 | Handler 호출 전후 | 메서드 실행 시 |
| 요청당 실행 | 1회 | 1회 | N회 (중첩) |
| MDC 관리 | 최적 | 가능 | 위험 |
실행 순서
HTTP 요청
↓
Filter (MDC.put)
↓
DispatcherServlet
↓
Interceptor
↓
Controller (MDC 사용)
↓
Service (MDC 사용)
↓
Repository (MDC 사용)
↓
Filter 종료 (MDC.clear)
↓
HTTP 응답FIlter 구현
public class MdcLoggingFilter extends OncePerRequestFilter {
private static final String TRACE_ID = "traceId";
private static final String REQUEST_METHOD = "method";
private static final String REQUEST_URI = "uri";
@Override
protected void doFilterInternal(
HttpServletRequest request,
HttpServletResponse response,
FilterChain filterChain
) throws ServletException, IOException {
// 1. traceId 생성 (기존 헤더가 있으면 재사용)
String traceId = request.getHeader("X-Trace-Id");
if (traceId == null || traceId.isEmpty()) {
traceId = UUID.randomUUID().toString().substring(0, 8);
}
// 2. MDC에 컨텍스트 정보 저장
MDC.put(TRACE_ID, traceId);
MDC.put(REQUEST_METHOD, request.getMethod());
MDC.put(REQUEST_URI, request.getRequestURI());
// 3. 요청 시작 로그
log.info("Request started - {} {}", request.getMethod(), request.getRequestURI());
long startTime = System.currentTimeMillis();
try {
// 4. 다음 필터 체인 실행
// 이후 실행되는 모든 코드(Controller, Service, Repository)는
// 같은 스레드에서 실행되므로 동일한 MDC를 공유한다
filterChain.doFilter(request, response);
} finally {
// 5. 요청 종료 로그
long duration = System.currentTimeMillis() - startTime;
log.info("Request completed - status: {}, duration: {}ms",
response.getStatus(), duration);
// 6. MDC 정리 (요청당 딱 한 번)
// 스레드 풀에서 재사용되는 스레드이므로 반드시 정리해야 함
MDC.clear();
}
}
}실행 결과
[c551a4bf] 2025-12-16T11:26:56.283+09:00 INFO 48556 --- [ Test worker] i.g.zeromok.filter.MdcLoggingFilter : Request started - POST /mdc/api/users/login
[c551a4bf] 2025-12-16T11:26:56.345+09:00 INFO 48556 --- [ Test worker] i.g.zeromok.controller.UserController : 로그인 요청. for user: alice
[c551a4bf] 2025-12-16T11:26:56.345+09:00 INFO 48556 --- [ Test worker] io.github.zeromok.service.UserService : 사용자 인증: alice
[c551a4bf] 2025-12-16T11:26:56.346+09:00 DEBUG 48556 --- [ Test worker] i.g.zeromok.repository.UserRepository : 이름으로 사용자 찾기: alice
[c551a4bf] 2025-12-16T11:26:56.362+09:00 DEBUG 48556 --- [ Test worker] i.g.zeromok.repository.UserRepository : 사용자 찾음: 1
[c551a4bf] 2025-12-16T11:26:56.362+09:00 DEBUG 48556 --- [ Test worker] io.github.zeromok.service.UserService : 비밀번호가 맞지 않습니다.
[c551a4bf] 2025-12-16T11:26:56.362+09:00 DEBUG 48556 --- [ Test worker] io.github.zeromok.service.UserService : 비밀번호 일치
[c551a4bf] 2025-12-16T11:26:56.363+09:00 DEBUG 48556 --- [ Test worker] io.github.zeromok.service.UserService : 사용자를 위한 토큰 생성: 1
[c551a4bf] 2025-12-16T11:26:56.363+09:00 DEBUG 48556 --- [ Test worker] io.github.zeromok.service.UserService : 토큰 생성 완료
[c551a4bf] 2025-12-16T11:26:56.363+09:00 INFO 48556 --- [ Test worker] io.github.zeromok.service.UserService : 사용자 인증 완료. user: alice
[c551a4bf] 2025-12-16T11:26:56.363+09:00 INFO 48556 --- [ Test worker] i.g.zeromok.controller.UserController : 로그인 성공. for user: alice
[c551a4bf] 2025-12-16T11:26:56.384+09:00 INFO 48556 --- [ Test worker] i.g.zeromok.filter.MdcLoggingFilter : Request completed - status: 200, duration: 100ms모든 로그에 일관된 traceId를 유지한다.
성능
성능을 어떨까? 성능이 저하되지는 않을까? 라는 의문이 들어 실제로 측정해보기로 했다.
마이크로 벤치마크
JMH(Java Microbenchmark Harness)로 나노초 단위의 정밀한 측정을 진행했다.
결과
Benchmark Mode Cnt Score Error Units
MdcPerformanceBenchmark.loggingWithMdc avgt 5 16401.445 ± 2875.711 ns/op
MdcPerformanceBenchmark.loggingWithoutMdc avgt 5 19905.075 ± 14091.645 ns/op
MdcPerformanceBenchmark.mdcPutAndGet avgt 5 343.959 ± 81.284 ns/op
MdcPerformanceBenchmark.uuidGeneration avgt 5 321.306 ± 64.073 ns/op측정 결과, UUID 생성은 약 321ns, MDC 작업(put/get/clear)은 약 344ns로 나노초 단위의 매우 빠른 속도를 보였다.
로깅 성능의 경우 MDC 사용 여부에 따른 의미있는 차이가 없었다 (MDC 사용: 16.4μs, 미사용: 19.9μs, 오차 범위: ±14μs).
이는 나노초~마이크로초 단위의 오버헤드로, 실제 비즈니스 로직 (DB 조회 ~10,000,000ns, API 호출 ~100,000,000ns)에 비하면 0.0001% 수준으로 무시할 수 있다.
정리
톰캣 스레드 풀의 동작 원리를 이해하게 되었다. 스레드는 재사용되므로 스레드 이름만으로는 요청을 구분할 수 없다. 100개의 요청이 10개의 스레드로 처리되는 것을 직접 확인했다.
ThreadLocal의 생명주기가 얼마나 중요한지 깨달았다. 스레드 풀 환경에서 ThreadLocal을 정리하지 않으면 이전 요청의 데이터가 다음 요청에 남아있을 수 있다. 이는 보안 문제나 메모리 누수로 이어질 수 있다.
AOP의 중첩 실행 구조를 명확히 이해하게 되었다. 여러 Aspect가 중첩되어 실행될 때 공유 자원(MDC, ThreadLocal)을 관리하면 예측하기 어려운 버그가 발생한다. Service AOP의 finally 블록에서 MDC.clear() 를 호출하면 Controller AOP도 영향을 받는다는 것을 코드로 확인했다.
횡단 관심사의 적절한 레이어 선택이 핵심이라는 것을 배웠다. "모든 레이어에서 로깅이 필요하다"는 요구사항을 "모든 레이어에 AOP를 적용한다"로 해석하면 안 된다. MDC처럼 요청 전체에 걸친 컨텍스트는 Filter에서 관리하고, 하위 레이어는 단순히 사용만 하는 것이 올바른 설계다.
기술 선택의 본질을 이해하게 되었다. 처음에는 "모든 레이어에 적용 = AOP"라고 직관적으로 연결했다. 하지만 문제의 본질은 요청 생명주기 전체의 컨텍스트 관리였고, 이는 Filter의 영역이었다. 기술을 선택할 때는 "무엇을 할 수 있는가"보다 "무엇을 해야 하는가" 가 더 중요하다.
성능보다 가치가 중요하다는 것을 확인했다. 나노초 단위의 오버헤드는 실제 비즈니스 로직에 비해 미미하다. 1~2ms의 응답 시간 증가는 사용자 경험에 영향을 주지 않는다. 하지만 장애 대응 시간이 30분에서 5분으로 줄어든 것은 팀 전체의 생산성을 크게 향상시켰다.
실패를 통해 배운 것이 가장 깊이 남는다. 처음부터 정답을 알았다면 ThreadLocal의 동작 원리, AOP의 중첩 실행, Filter의 생명주기를 이렇게 깊이 이해하지 못했을 것이다. 이 경험이 비슷한 문제를 마주한 누군가에게 도움이 되길 바란다.
🔗GitHub 저장소
- 예제 프로젝트: mdc-logging-example
실행 방법
// 스레드 이름 방식
./gradlew bootRun --args='--spring.profiles.active=thread-name'
// AOP MDC 방식
./gradlew bootRun --args='--spring.profiles.active=mdc-aspect'
// Filter MDC 방식
./gradlew bootRun --args='--spring.profiles.active=mdc-filter'각 방식을 독립적으로 실행하여 실패와 성공을 직접 체험할 수 있다.