로그 추적기 필드 동기화 - 동시성 문제 발생

이전 게시글에 로그 추적기를 만들어서 로그를 출력했다. 트랜잭션 ID와 level을 동기화하기 위해서 traceId를 파라미터로 넘기도록 구현했었는데 동기화는 되었지만 로그를 출력하는 모든 메서드에 traceId 파라미터를 추가해야하는 문제가 있었다.

 

 

LogTrace 인터페이스

public interface LogTrace {

    TraceStatus begin(String message);

    void end(TraceStatus status);

    void exception(TraceStatus status, Exception e);
}

 

FieldLogTrace 구현체

@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(); // 1씩 증가
        }
    }

    @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(); // 1씩 감소
        }
    }

    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는 이전의 LogTrace들과 비슷하다. 차이점이 있다면  beginSync()가 필요없고 begin()으로 traceId가 하나로 일치하게 만들어줬다는 변화가 있다. syncTraceId()와 releaseTraceId()로 level을 변화시키며 private TraceId traceIdHolder로 traceId를 하나로 설정해두었는데, 이러한 방식은 동시성 문제를 야기한다.

 

 

 

 

 

 

동시성 문제

다른 사용자가 동시에 로직을 호출하면 두 사용자가 같은 UUID를 받는다는 치명적인 단점이 있다. 이것이 동시성 문제이며 실제 상황에서 이러한 문제가 생기면 큰일나게 된다.

 

이유는 FieldLogTrace는 싱글톤으로 등록된 스프링 빈인데, 이 객체의 인스턴스가 애플리케이션에 딱 1개 존재하기 때문에 여러 쓰레드가 동시에 접근하면서 문제가 발생하게 된다.

 

 

테스트에서 호출할 logic이 있는 FieldService

@Slf4j
public class FieldService {

    private String nameStore;

    public String logic(String name) {
        log.info("저장 name={} -> nameStore={}", name, nameStore);
        nameStore = name;
        sleep(1000);
        log.info("조회 nameStore={}", nameStore);
        return nameStore;
    }

    private void sleep(int millis) {
        try {
            Thread.sleep(millis);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

 

Test 코드

@Test
    void field() {
        log.info("main start");
        Runnable userA = () -> {
            fieldService.logic("userA");
        };
        Runnable userB = () -> {
            fieldService.logic("userB");
        };

        Thread threadA = new Thread(userA);
        threadA.setName("thread-A");
        Thread threadB = new Thread(userB);
        threadB.setName("thread-B");

        threadA.start();
        // sleep(2000); // 동시성 문제 발생 X
        sleep(100); // 동시성 문제 발생
        threadB.start();

        sleep(3000); // 메인 쓰레드 종료 대기
        log.info("main exit");
    }

sleep()을 2000ms로 했을 때에는 동시성 문제가 발생하지 않는다. 하지만 100ms로 실행하면 동시성 문제가 발생한다.

userA와 userB가 있다고 할 때, userA의 UUID를 반환하고 로직을 실행하는 도중에 인스턴스가 반환이 안된 상태에서 userB의 UUID가 반환되면 userA는 로직을 종료할 때 userB때문에 변경된 UUID가 나오게 된다. 트래픽이 적은 상황에서는 확률상 잘 발생하지 않는데, 트래픽이 점점 많아질 수록 동시성 문제가 자주 발생하게 된다.

 

출처 : 인프런 스프링 강의

 

 

동시성 문제는 지역 변수에서는 발생하지 않고 인스턴스의 필드(주로 싱글톤), 또는 static 같은 공용 필드에 접근할 때 발생한다. 그리고 값을 변경하기 때문에 동시성 문제가 발생한다.

 

이러한 문제점을 봤을 때에는 이전 포스팅에서처럼 계속 파라미터로 전달하는 방식이 나을 수도 있다고 생각할 수도 있는데, 이러한 문제점을 해결하기 위해 쓰레드 로컬이라는 기능이 존재한다.