❗이 게시물은 김영한님의 인프런 강좌 스프링 핵심 원리 - 고급편의 내용을 개인 정리를 위한 목적으로 작성하였습니다.
지난 게시물 [Spring] 로그 추적기 생성을 통해 로그 추적기를 개발해보았다. 그런데 다음 로그를 출력할 때 트랜잭션ID와 level을 동기화하는 문제를 해결하기 위해 매번 TraceId를 파라미터를 넘겨야 했다. 우선 TraceId를 파라미터로 넘기지 않고 이 문제를 해결할 수 있는 방법을 간략히 알아보자. 그리고 중점적으로는 ThreadLocal이 왜 필요하고, 어떻게 사용하는지 대해서 살펴볼 것이다.
필드 동기화
새로운 로그 추적기를 개발해볼텐데, 이번에는 프로토타입 버전이 아닌 정식 버전으로 개발해볼 것이다. 향후 다양한 구현체로 변경할 수 있도록 인터페이스를 먼저 만들고, 구현할 것이다.
LogTrace.java
package hello.advanced.trace.logtrace;
import hello.advanced.trace.TraceStatus;
public interface LogTrace {
TraceStatus begin(String message);
void end(TraceStatus status);
void exception(TraceStatus status, Exception e);
}LogTrace 인터페이스는 로그 추적기를 위한 최소한의 기능인 begin(), end(), exception()을 정의했다. 이제 파라미터를 넘기지 않고 TraceId를 동기화할 수 있는 FieldLogTrace 구현체를 만들어보자.
FieldLogTrace.java
package hello.advanced.trace.logtrace;
import hello.advanced.trace.TraceId;
import hello.advanced.trace.TraceStatus;
import lombok.extern.slf4j.Slf4j;
@Slf4j
public class FieldLogTrace implements LogTrace {
private static final String START_PREFIX = "-->";
private static final String COMPLETE_PREFIX = "<--";
private static final String EX_PREFIX = "<X-";
private TraceId traceIdHolder; //traceId 동기화, 동시성 이슈 발생
@Override
public TraceStatus begin(String message) {
syncTraceId();
TraceId traceId = traceIdHolder;
Long startTimeMs = System.currentTimeMillis();
log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);
return new TraceStatus(traceId, startTimeMs, message);
}
private void syncTraceId() {
if (traceIdHolder == null) {
traceIdHolder = new TraceId();
} else {
traceIdHolder = traceIdHolder.createNextId();
}
}
@Override
public void end(TraceStatus status) {
complete(status, null);
}
@Override
public void exception(TraceStatus status, Exception e) {
complete(status, e);
}
private void complete(TraceStatus status, Exception e) {
Long stopTimeMs = System.currentTimeMillis();
long resultTimeMs = stopTimeMs - status.getStartTimeMs();
TraceId traceId = status.getTraceId();
if (e == null) {
log.info("[{}] {}{} time={}ms", traceId.getId(), addSpace(COMPLETE_PREFIX, traceId.getLevel()), status.getMessage(), resultTimeMs);
} else {
log.info("[{}] {}{} time={}ms ex={}", traceId.getId(), addSpace(EX_PREFIX, traceId.getLevel()), status.getMessage(), resultTimeMs, e.toString());
}
releaseTraceId();
}
private void releaseTraceId() {
if (traceIdHolder.isFirstLevel()) {
traceIdHolder = null; //destroy
} else {
traceIdHolder = traceIdHolder.createPreviousId();
}
}
private static String addSpace(String prefix, int level) {
StringBuilder sb = new StringBuilder();
for (int i = 0; i < level; i++) {
sb.append( (i == level - 1) ? "|" + prefix : "| ");
}
return sb.toString();
}
}FieldLogTrace는 기존에 만들었던 HelloTraceV2와 대체적으로 같은데, TraceId를 동기화하는 부분만 파라미터를 사용하는 방식에서 TraceId traceIdHolder 필드를 사용하도록 변경되었다. 여기서 중요한 부분은 로그를 시작할 때 호출하는 syncTraceId()와 로그를 종료할 때 호출하는 releaseTraceId()이다. 각 메서드를 호출할 때마다 level을 증가 또는 감소시키고, syncTraceId()는 직전 로그가 있는지 여부에 따라 TraceId를 동기화하거나 새로 생성하고, releaseTraceId()는 level==0일 때 호출이면 traceId를 제거한다.
그럼 지금까지 만든 FieldLogTrace를 애플리케이션에 적용해보자. FieldLogTrace를 수동으로 스프링 빈으로 등록하면 향후 구현체를 편리하게 변경할 수 있다.
LogTraceConfig.java
package hello.advanced;
import hello.advanced.trace.logtrace.LogTrace;
import hello.advanced.trace.logtrace.FieldLogTrace;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
@Configuration
public class LogTraceConfig {
@Bean
public LogTrace logTrace() {
return new FieldLogTrace();
}
}그리고 로그 추적기 V2를 V3로 복사하여 새로 만들자. 이때 HelloTraceV2 대신 LogTrace 인터페이스를 사용하여야 하며, TraceId traceId 파라미터를 모두 제거하도록 한다. 또한 beginSync() 대신 전부 begin()을 사용한다.
OrderRepositoryV3.java
package hello.advanced.app.v3;
import hello.advanced.trace.TraceStatus;
import hello.advanced.trace.logtrace.LogTrace;
import lombok.RequiredArgsConstructor;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.bind.annotation.RestController;
@RestController
@RequiredArgsConstructor
public class OrderControllerV3 {
private final OrderServiceV3 orderService;
private final LogTrace trace;
@GetMapping("/v3/request")
public String request(@RequestParam("itemId") String itemId) {
TraceStatus status = null;
try {
status = trace.begin("OrderController.request()");
orderService.orderItem(itemId);
trace.end(status);
return "ok";
} catch (Exception e) {
trace.exception(status, e);
throw e;
}
}
}OrderServiceV3.java
package hello.advanced.app.v3;
import hello.advanced.trace.TraceStatus;
import hello.advanced.trace.logtrace.LogTrace;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Service;
@Service
@RequiredArgsConstructor
public class OrderServiceV3 {
private final OrderRepositoryV3 orderRepository;
private final LogTrace trace;
public void orderItem(String itemId) {
TraceStatus status = null;
try {
status = trace.begin("OrderService.orderItem()");
orderRepository.save(itemId);
trace.end(status);
} catch (Exception e) {
trace.exception(status, e);
throw e;
}
}
}OrderRepositoryV3.java
package hello.advanced.app.v3;
import hello.advanced.trace.TraceStatus;
import hello.advanced.trace.logtrace.LogTrace;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Repository;
@Repository
@RequiredArgsConstructor
public class OrderRepositoryV3 {
private final LogTrace trace;
public void save(String itemId) {
TraceStatus status = null;
try {
status = trace.begin("OrderRepository.save()");
//저장 로직
if (itemId.equals("ex")) {
throw new IllegalStateException("예외 발생!");
}
sleep(1000);
trace.end(status);
} catch (Exception e) {
trace.exception(status, e);
throw e;
}
}
private void sleep(int millis) {
try {
Thread.sleep(millis);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}동시성 문제
위와 같이 필드 동기화를 적용하였을 때 문제가 없어보일 수 있지만, 사실 FieldLogTrace는 심각한 동시성 문제를 갖고 있다. 동시성 문제를 확인하려면 동시에 여러번 호출해보면 된다. 이를 실행해본 결과를 살펴보면 다음과 같다.
2024-02-14T21:01:42.707+09:00 INFO 6084 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
2024-02-14T21:01:42.708+09:00 INFO 6084 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
2024-02-14T21:01:42.708+09:00 INFO 6084 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Completed initialization in 0 ms
2024-02-14T21:01:42.727+09:00 INFO 6084 --- [nio-8080-exec-1] h.advanced.trace.logtrace.FieldLogTrace : [06ef8125] OrderController.request()
2024-02-14T21:01:42.727+09:00 INFO 6084 --- [nio-8080-exec-1] h.advanced.trace.logtrace.FieldLogTrace : [06ef8125] |-->OrderService.orderItem()
2024-02-14T21:01:42.727+09:00 INFO 6084 --- [nio-8080-exec-1] h.advanced.trace.logtrace.FieldLogTrace : [06ef8125] | |-->OrderRepository.save()
2024-02-14T21:01:42.799+09:00 INFO 6084 --- [nio-8080-exec-2] h.advanced.trace.logtrace.FieldLogTrace : [06ef8125] | | |-->OrderController.request()
2024-02-14T21:01:42.799+09:00 INFO 6084 --- [nio-8080-exec-2] h.advanced.trace.logtrace.FieldLogTrace : [06ef8125] | | | |-->OrderService.orderItem()
2024-02-14T21:01:42.799+09:00 INFO 6084 --- [nio-8080-exec-2] h.advanced.trace.logtrace.FieldLogTrace : [06ef8125] | | | | |-->OrderRepository.save()
2024-02-14T21:01:43.731+09:00 INFO 6084 --- [nio-8080-exec-1] h.advanced.trace.logtrace.FieldLogTrace : [06ef8125] | |<--OrderRepository.save() time=1004ms
2024-02-14T21:01:43.731+09:00 INFO 6084 --- [nio-8080-exec-1] h.advanced.trace.logtrace.FieldLogTrace : [06ef8125] |<--OrderService.orderItem() time=1004ms
2024-02-14T21:01:43.731+09:00 INFO 6084 --- [nio-8080-exec-1] h.advanced.trace.logtrace.FieldLogTrace : [06ef8125] OrderController.request() time=1005ms
2024-02-14T21:01:43.809+09:00 INFO 6084 --- [nio-8080-exec-2] h.advanced.trace.logtrace.FieldLogTrace : [06ef8125] | | | | |<--OrderRepository.save() time=1010ms
2024-02-14T21:01:43.809+09:00 INFO 6084 --- [nio-8080-exec-2] h.advanced.trace.logtrace.FieldLogTrace : [06ef8125] | | | |<--OrderService.orderItem() time=1010ms
2024-02-14T21:01:43.809+09:00 INFO 6084 --- [nio-8080-exec-2] h.advanced.trace.logtrace.FieldLogTrace : [06ef8125] | | |<--OrderController.request() time=1010ms1초 이내에 http://localhost:8080/v3/request?itemId=hello를 두 번 접속해봤을 때, 기대했던 결과와는 전혀 다르다. 트랜잭션ID도 모두 동일하고, level도 많이 뒤죽박죽인 상태이다. 이는 동시성 문제로 인해 나타난 현상이다.
FieldLogTrace는 싱글톤으로 등록된 스프링 빈으로, 이렇게 하나만 존재하는 인스턴스의 FieldLogTrace.traceIdHolder 필드를 여러 쓰레드가 동시에 접근하기 때문에 문제가 발생하는 것이다.
ThreadLocal
쓰레드 로컬은 해당 쓰레드만 접근할 수 있는 특별한 저장소를 말한다. 즉, 위와 같이 하나만 존재하는 인스턴스의 필드를 여러 쓰레드가 동시에 접근하는 방식이 아닌, 쓰레드 로컬 방식은 각각의 쓰레드 별로 지정된 쓰레드 로컬에 접근하도록 한다. 일반적인 변수 필드는 여러 쓰레드가 그 변수에 접근할 때 이전 쓰레드가 보관한 데이터를 지울 수 있다. 쓰레드 로컬을 사용하면 각 쓰레드마다 별도의 내부 저장소를 제공하여 같은 인스턴스의 쓰레드 로컬 필드에 접근해도 문제 없다. 이로써 동시성 문제를 극복할 수 있다.
참고로 Java는 언어 차원에서 쓰레드 로컬을 지원하기 위한 java.lang.ThreadLocal 클래스를 제공한다.
이제 쓰레드 로컬을 사용해 ThreadLocalLogTrace를 새로 만들어보자.
ThreadLocalLogTrace.java
package hello.advanced.trace.logtrace;
import hello.advanced.trace.TraceId;
import hello.advanced.trace.TraceStatus;
import lombok.extern.slf4j.Slf4j;
@Slf4j
public class ThreadLocalLogTrace implements LogTrace {
private static final String START_PREFIX = "-->";
private static final String COMPLETE_PREFIX = "<--";
private static final String EX_PREFIX = "<X-";
// private TraceId traceIdHolder; //traceId 동기화, 동시성 이슈 발생
private ThreadLocal<TraceId> traceIdHolder = new ThreadLocal<>();
@Override
public TraceStatus begin(String message) {
syncTraceId();
TraceId traceId = traceIdHolder.get();
Long startTimeMs = System.currentTimeMillis();
log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);
return new TraceStatus(traceId, startTimeMs, message);
}
private void syncTraceId() {
TraceId traceId = traceIdHolder.get();
if (traceId == null) {
traceIdHolder.set(new TraceId());
} else {
traceIdHolder.set(traceId.createNextId());
}
}
@Override
public void end(TraceStatus status) {
complete(status, null);
}
@Override
public void exception(TraceStatus status, Exception e) {
complete(status, e);
}
private void complete(TraceStatus status, Exception e) {
Long stopTimeMs = System.currentTimeMillis();
long resultTimeMs = stopTimeMs - status.getStartTimeMs();
TraceId traceId = status.getTraceId();
if (e == null) {
log.info("[{}] {}{} time={}ms", traceId.getId(), addSpace(COMPLETE_PREFIX, traceId.getLevel()), status.getMessage(), resultTimeMs);
} else {
log.info("[{}] {}{} time={}ms ex={}", traceId.getId(), addSpace(EX_PREFIX, traceId.getLevel()), status.getMessage(), resultTimeMs, e.toString());
}
releaseTraceId();
}
private void releaseTraceId() {
TraceId traceId = traceIdHolder.get();
if (traceId.isFirstLevel()) {
traceIdHolder.remove(); //destroy
} else {
traceIdHolder.set(traceId.createPreviousId());
}
}
private static String addSpace(String prefix, int level) {
StringBuilder sb = new StringBuilder();
for (int i = 0; i < level; i++) {
sb.append( (i == level - 1) ? "|" + prefix : "| ");
}
return sb.toString();
}
}traceIdHolder가 필드에서 ThreadLocal로 변경되었다. 따라서 값을 저장 및 조회할 때에는 .set()과 .get()을 사용한다. 그리고 쓰레드 로컬을 모두 사용하고 나면 꼭 ThreadLocal.remove()를 호출해서 쓰레드 로컬에 저장된 값을 제거해주어야 한다. 안그러면 값이 그대로 저장된 쓰레드 로컬을 다른 쓰레드가 읽어버릴 수도 있다.
쓰레드 로컬 동기화 적용
LogTraceConfig.java
package hello.advanced;
import hello.advanced.trace.logtrace.LogTrace;
import hello.advanced.trace.logtrace.ThreadLocalLogTrace;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
@Configuration
public class LogTraceConfig {
@Bean
public LogTrace logTrace() {
return new ThreadLocalLogTrace();
}
}기존 LogTraceConfig.java에서 동시성 문제를 가진 FieldLogTrace 대신 ThreadLocalLogTrace를 스프링 빈으로 등록한다. 그리고 바로 실행 결과를 확인해보자.
2024-02-14T21:31:15.050+09:00 INFO 23572 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
2024-02-14T21:31:15.051+09:00 INFO 23572 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
2024-02-14T21:31:15.051+09:00 INFO 23572 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Completed initialization in 0 ms
2024-02-14T21:31:15.069+09:00 INFO 23572 --- [nio-8080-exec-1] h.a.trace.logtrace.ThreadLocalLogTrace : [cf69f2bc] OrderController.request()
2024-02-14T21:31:15.070+09:00 INFO 23572 --- [nio-8080-exec-1] h.a.trace.logtrace.ThreadLocalLogTrace : [cf69f2bc] |-->OrderService.orderItem()
2024-02-14T21:31:15.070+09:00 INFO 23572 --- [nio-8080-exec-1] h.a.trace.logtrace.ThreadLocalLogTrace : [cf69f2bc] | |-->OrderRepository.save()
2024-02-14T21:31:15.229+09:00 INFO 23572 --- [nio-8080-exec-2] h.a.trace.logtrace.ThreadLocalLogTrace : [78d5ba4d] OrderController.request()
2024-02-14T21:31:15.229+09:00 INFO 23572 --- [nio-8080-exec-2] h.a.trace.logtrace.ThreadLocalLogTrace : [78d5ba4d] |-->OrderService.orderItem()
2024-02-14T21:31:15.229+09:00 INFO 23572 --- [nio-8080-exec-2] h.a.trace.logtrace.ThreadLocalLogTrace : [78d5ba4d] | |-->OrderRepository.save()
2024-02-14T21:31:16.080+09:00 INFO 23572 --- [nio-8080-exec-1] h.a.trace.logtrace.ThreadLocalLogTrace : [cf69f2bc] | |<--OrderRepository.save() time=1010ms
2024-02-14T21:31:16.080+09:00 INFO 23572 --- [nio-8080-exec-1] h.a.trace.logtrace.ThreadLocalLogTrace : [cf69f2bc] |<--OrderService.orderItem() time=1010ms
2024-02-14T21:31:16.080+09:00 INFO 23572 --- [nio-8080-exec-1] h.a.trace.logtrace.ThreadLocalLogTrace : [cf69f2bc] OrderController.request() time=1011ms
2024-02-14T21:31:16.235+09:00 INFO 23572 --- [nio-8080-exec-2] h.a.trace.logtrace.ThreadLocalLogTrace : [78d5ba4d] | |<--OrderRepository.save() time=1006ms
2024-02-14T21:31:16.235+09:00 INFO 23572 --- [nio-8080-exec-2] h.a.trace.logtrace.ThreadLocalLogTrace : [78d5ba4d] |<--OrderService.orderItem() time=1006ms
2024-02-14T21:31:16.235+09:00 INFO 23572 --- [nio-8080-exec-2] h.a.trace.logtrace.ThreadLocalLogTrace : [78d5ba4d] OrderController.request() time=1006ms위 결과를 봤을 때 순서가 다소 뒤죽박죽처럼 보이지만, 자세히 살펴보면 각각의 쓰레드 nio-8080-exec-1과 nio-8080-exec-2 별로 트랜잭션ID가 cf69f2bc와 78d5ba4d로 정확히 분리된 것을 볼 수 있고, 깊이를 봤을 때에도 호출되는 계층별로 그 깊이가 정상적으로 나타난 것을 볼 수 있다. 이로써 쓰레드 로컬을 통해 동시성 문제를 해결하였다.
유랑하는 백엔드 개발자 새싹 블로그