필드 동기화 - 개발

바로 이전에 했던 로그 추적기에는 문제가 있다.
트랜잭션ID를 맞추기 위해 파라미터로 TraceId를 넘겼는데,
이렇게 넘기는 방식은 로직에 관여를 해야 하기 때문에 좋지 않은 방법이다.
TraceId 를 파라미터로 넘기지 않고 이 문제를 해결할 수 있는 방법이 있을까?

LogTrace

FieldLogTrace

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를 FieldLogTrace가 traceIdHolder를 통해 관리한다는 것이다.

syncTraceId()와 releaseTraceId()가 있는데
syncTraceId()는

• begin()에서 호출됨
• 최초 호출이면 TraceId를 새로 생성.
• 아니면 TraceId를 동기화하고 level하나 증가

releaseTraceId()는

• end -> complete()에서 호출됨
• 맨 처음 레벨이면 TraceId 제거
• 아니면 TraceId를 통기화하고 level 하나 감소

[c80f5dbb] OrderController.request() //syncTraceId(): 최초 호출 level=0
[c80f5dbb] |-->OrderService.orderItem() //syncTraceId(): 직전 로그 있음 level=1 증가
[c80f5dbb] | |-->OrderRepository.save() //syncTraceId(): 직전 로그 있음 level=2 증가
[c80f5dbb] | |<--OrderRepository.save() time=1005ms //releaseTraceId(): level=2->1 감소
[c80f5dbb] |<--OrderService.orderItem() time=1014ms //releaseTraceId(): level=1->0 감소
[c80f5dbb] OrderController.request() time=1017ms //releaseTraceId(): level==0, traceId 제거

테스트

잘 나온다. 이제는 TraceId를 파라미터로 넣을 필요없이 잘 출력되는 것을 확인할 수 있다.

필드 동기화 - 적용

컨트롤러

서비스

리포지토리

잘 되는 것을 확인할 수 있다.
그런데 이 방법에서는 동시성 문제가 발생한다.

동시성 문제

위 로그는 sleep으로 인해서 처음 로직이 돌때 1초가 걸리는데
1초안에 두 번 접속하게 되면 나오는 로그이다.

트랜잭션 아이디가 구분이 안되고,
컨트롤러 -> 서비스 -> 리포지토리 -> 컨트롤러
와 같이 레벨도 꼬인다.

어 근데 톰캣이 지원하는 쓰레드는 구분이 잘된다.
즉, 동시성 문제가 발생한 것이다.

동시성 문제 - 예제 코드

FieldService

FieldServiceTest

실행 결과

sleep을 2초를 주었기 때문에 userA가 로직을 마칠때까지 정지된 상태로 있다가, userB로 넘어가 정상적으로 동작하는 것을 확인할 수 있다.

동시성 발생

실행 결과

A 쓰레드가 userA를 저장하고 1초 후에 nameStore를 조회하는데,
그 전에 B 쓰레드가 userB를 저장해버려서 nameStore를 조회할때, userB가 조회되는 현상이 발생한다.

동시성 문제
이처럼 여러 쓰레드가 동시에 같은 인스턴스의 필드 값을 변경하면서 발생하는 문제를 동시성 문제라 한다. 이런 동시성 문제는 여러 쓰레드가 같은 인스턴스의 필드에 접근해야 하기 때문에 트래픽이 적은 상황에서는 확률상 잘 나타나지 않고, 트래픽이 점점 많아질수록 자주 발생한다.

특히 스프링 빈처럼 싱글톤 객체의 필드를 변경하며 사용할 때 이러한 동시성 문제를 조심해야 한다.

그렇다면 싱글톤 객체의 필드를 쓰면서 동시성 문제를 해결하려면?
이럴때 사용하는 것이 쓰레드 로컬이다.