[ 김영한 스프링 고급편 #1 ] - 로그 객체와 동시성 이슈

김영한님의 스프링 핵심 원리 고급편 강의를 듣고 있습니다. 이번 강의의 주제는 크게 쓰레드 로컬과 스프링의 디자인 패턴, 그리고 AOP에 관한 내용입니다.

이 중 먼저 쓰레드 로컬에 대해 배우는데요, 동시성 이슈된 내용입니다. 의도적으로 이 문제를 발생시키기 위해 로그 추적기를 생성했습니다. 컨트롤러부터 시작해 여러 계층에서 공유되면서 로그를 찍는 기능을 하죠.

가장 기본적인 형태의 로그 추적기는 아래와 같습니다.

@RestController
@RequiredArgsConstructor
public class OrderControllerV2 {

    private final OrderServiceV2 orderService;
    private final HelloTraceV1 trace;

    @GetMapping("/v2/request")
    public String request(String itemId) {
        TraceStatus status = null;

        try {
            status = trace.begin("OrderController.request()");
            // 서비스 계층에 파라미터로 로그 객체 전달
            orderService.orderItem(status.getTraceId(), itemId);
            trace.end(status);
            return "ok";
        } catch (Exception e) {
            trace.exception(status, e);
            throw e;
        }
    }
}

보면 컨트롤러->서비스->DB 각 계층별로 로그 객체를 전달하고 있습니다. 이 경우 아무런 문제가 발생하지는 않지만 매 파라미터에 로그 객체를 전달해야 하는 불편함이 있죠.

이를 해소하기 위해 로그 인터페이스를 만들고, 이를 구현하는 구현체를 만들었습니다.

public interface LogTrace {

    TraceStatus begin(String message);

    void end(TraceStatus status);

    void exception(TraceStatus status, Exception e);
}

@Slf4j
public class FieldLogTrace implements LogTrace {

    private TraceId traceIdHolder;

    private static final String START_PREFIX = "-->";
    private static final String COMPLETE_PREFIX = "<--";
    private static final String EX_PREFIX = "<X-";

    @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();
        }
    }

그리고 만든 FieldLogTrace 객체를 빈으로 등록했습니다.

@Configuration
public class LogTraceConfig {

    @Bean
    public LogTrace logTrace() {
        return new FieldLogTrace();
    }
}

이 방식은 계층간의 이동과 관련된 표시를 로그 객체 내부에 숨겨 사용하는 방식입니다. 그러니까 로그를 제일 처음 찍을 때, traceIdHolder를 확인해 null인지 아닌지를 판별합니다. 만약 null이면 새로운 객체를 할당하고, null이 아니면 기존 객체에서 계층을 더해주는 createNextId() 매서드를 호출하는 방식으로 계층 간 표시를 해줍니다. 더 이상 매서드의 파라미터에 로그 객체를 전달할 필요가 없어진 것이죠.

해당 방식으로 로그를 찍으면 아래와 같이 나오게 됩니다.

[nio-8080-exec-1] FieldLogTrace  : [6a15e89b] OrderController.request()
[nio-8080-exec-1] FieldLogTrace  : [6a15e89b] |-->OrderService.request()
[nio-8080-exec-1] FieldLogTrace  : [6a15e89b] | |-->OrderRepository.request()
[nio-8080-exec-1] FieldLogTrace  : [6a15e89b] | |<--OrderRepository.request() time=1007ms
[nio-8080-exec-1] FieldLogTrace  : [6a15e89b] |<--OrderService.request() time=1007ms
[nio-8080-exec-1] FieldLogTrace  : [6a15e89b] OrderController.request() time=1010ms

동일한 쓰레드에 "512a096e"라는 동일한 traceId가 찍힌 것과, 계층별 구분이 잘 되는 것을 확인할 수 있습니다.

그런데 만약 동시에 2번 요청을 보내면 어떻게 될까요? 그 결과 아래와 같이 로그가 찍히게 됩니다.

[nio-8080-exec-7] FieldLogTrace  : [a9c8a5ce] OrderController.request()
[nio-8080-exec-7] FieldLogTrace  : [a9c8a5ce] |-->OrderService.request()
[nio-8080-exec-7] FieldLogTrace  : [a9c8a5ce] | |-->OrderRepository.request()
[nio-8080-exec-8] FieldLogTrace  : [a9c8a5ce] | | |-->OrderController.request()
[nio-8080-exec-8] FieldLogTrace  : [a9c8a5ce] | | | |-->OrderService.request()
[nio-8080-exec-8] FieldLogTrace  : [a9c8a5ce] | | | | |-->OrderRepository.request()
[nio-8080-exec-7] FieldLogTrace  : [a9c8a5ce] | |<--OrderRepository.request() time=1001ms
[nio-8080-exec-7] FieldLogTrace  : [a9c8a5ce] |<--OrderService.request() time=1003ms
[nio-8080-exec-7] FieldLogTrace  : [a9c8a5ce] OrderController.request() time=1006ms
[nio-8080-exec-8] FieldLogTrace  : [a9c8a5ce] | | | | |<--OrderRepository.request() time=1015ms
[nio-8080-exec-8] FieldLogTrace  : [a9c8a5ce] | | | |<--OrderService.request() time=1015ms
[nio-8080-exec-8] FieldLogTrace  : [a9c8a5ce] | | |<--OrderController.request() time=1016ms

다른 쓰레드에 "a9c8a5ce"라는 동일한 traceId가 찍힌 걸 볼 수 있습니다. 이게 바로 동시성 이슈인데요, 여러 쓰레드가 하나의 자원을 두고 벌이는 경쟁입니다. 위에서 로그 객체를 빈으로 등록했기 때문에 오직 하나 밖에 없는 FieldLogTrace에 두 개의 쓰레드가 접근한 것이죠.

이번 글에서는 간단하게 로그 객체를 만들고 이를 이용해 여러 계층에서 사용했고, 이로 인해 동시성 이슈가 발생한 것을 확인했습니다. 다음 글에서는 이 동시성 이슈라는 게 정확히 어떻게 발생하는 것이고 또 어떻게 해결해야 하는지에 대해 알아보겠습니다.