Spring Core - 쓰레드 로컬(필드 동기화, 동시성 문제1)

쓰레드 로컬 - 필드 동기화

앞서 로그 추적기를 만들면서 다음 로그를 출력할 때 트랜잭션ID와 level을 동기화 하는 문제가 있었다.

이 문제를 해결하기 위해 TraceId를 파라미터로 넘기도록 구현했다.

이렇게 해서 동기화는 성공했지만, 로그를 출력하는 모든 메서드에 TraceId 파라미터를 추가해야 하는 문제가 발생했다.

TraceId를 파라미터로 넘기지 않고 이 문제를 해결할 수 있는 방법은 없을까?

 

이런 문제를 해결할 목적으로 새로운 로그 추적기를 만들어보자.

향후 다양한 구현체로 변경할 수 있도록 LogTrace 인터페이스를 먼저 만들고, 구현해보자.

 

LogTrace 인터페이스

public interface LogTrace {

    TraceStatus begin(String message);
    void end(TraceStatus status);
    void exception(TraceStatus status, Exception e);

}

 

LogTrace 인터페이스에는 로그 추적기를 위한 최소한의 기능인 begin(), end(), exception()를 정의했다. 이제 파라미터를 넘기지 않고, TraceId를 동기화 할 수 있는 FileLogTrace 구현체를 만들어 보자.

 

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-";

    //traceId를 어딘가에는 저장하고 있어야 한다.
    //traceId를 파라미터로 넘기는 것이 아니라 holder에 보관
    private TraceId traceIdHolder; // traceId 동기화, 동시성 이슈 발생

    /**
     * traceId를 동기화하는 메서드를 만든다.
     */
    private void syncTraceId(){
        if(traceIdHolder == null){
            //traceIdHolder가 null 일때는 새로 생성
            traceIdHolder = new TraceId();
        } else {
            //null이 아닐 경우 level에 + 1 해준다.
            traceIdHolder = traceIdHolder.createNextId();
        }
    }


    @Override
    public TraceStatus begin(String message) {
        syncTraceId();
        //동기화를 하고 나면
        //traceIdHolder에 값이 들어가 있는 것이 보장된다.
        TraceId traceId = traceIdHolder;
        Long startTimeMs = System.currentTimeMillis();
        log.info("[{}] {}{}",traceId.getId(),addSpace(START_PREFIX,traceId.getLevel()),
        message);

        return new TraceStatus(traceId, startTimeMs, message);
    }

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

        //complete메서드를 불러 올 때는
        //traceIdHolder에 level의 값을 -1 해줄것이다.
        releaseTraceId();

    }

    private void releaseTraceId() {
        if(traceIdHolder.isFirstLevel()){
            //end나 exception에서 부른
            //traceIdHolder의 level이 0이라는것은
            //해당 트랜잭션이 끝나기 전에 호출되었 다는 것이다.
            traceIdHolder = null; //destory
        }else{
            //해당 트랜잭션이 끝나기 직전에 호출된 것이 아니라면
            //traceIdHolder의 level에 -1을 해준다.
            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();
    }
}

 

FeildLogTrace는 기존에 만들었던 HelloTraceV2와 거의 같은 기능을 한다. TraceId를 동기화 하는 부분만 파라미터를 사용하는 것에서 TraceId traceHolder 필드를 사용하도록 변경되었다.

이제 직전 로그의 TraceId는 파라미터로 전달되는 것이 아니라 FeildLogTrace의 필드인 traceIHolder에 저장된다.

 

여기서 중요한 부분은 로그를 시작할 때 호출하는 syncTraceId()와 로그를 종료할 때 호출하는 releaseTraceId()이다.

• syncTraceId()
  • TraceId를 새로 만들거나 앞선 로그의 TraceId를 참고해서 동기화하고, level도 증가시킨다.
  • 최초 호출이면 TraceId를 새로 만든다.
  • 직전 로그가 있으면 해당 로그의 TraceId를 참고해서 동기화하고 level도 하나 증가한다.
  • 결과를 traceIdHolder에 보관한다.
• releaseTraceId()
  • 메서드를 추가로 호출할 때는 level이 하나 증가해야 하지만, 메서드 호출이 끝내면 level이 하나 감소해야 한다.
  • releaseTraceId()는 level을 하나 감소시킨다.
  • 만약 최초 호출(level == 0)이면 내부에서 관리하는 traceId를 제거한다.

 

테스트 코드를 통해서 실행해보자.

 

FieldLogTraceTest

class FieldLogTraceTest {

    FieldLogTrace trace = new FieldLogTrace();

    @Test
    void begin_end_level2(){
        TraceStatus status1 = trace.begin("hello1");
        TraceStatus status2 = trace.begin("hello2");
        trace.end(status2);
        trace.end(status1);
    }

    @Test
    void begin_exception_level2(){
        TraceStatus status1 = trace.begin("hello1");
        TraceStatus status2 = trace.begin("hello2");
        trace.exception(status2, new IllegalStateException("오류 발생!"));
        trace.exception(status1, new IllegalStateException("오류 발생!"));
    }


}

 

 

begin_end_level2() - 실행결과

 

 

befin_exception_level2() - 실행 결과

 

실행 결과를 보면 트랜잭션ID도 동일하게 출력되고, level을 통한 깊이도 잘 표현된다.

FieldLogTrace.traceIdHolder 필드를 사용해서 TraceId가 잘 동기화 되는 것을 확인할 수 있다.

이제 불필요하게 TraceId를 파라미터로 전달하지 않아도 되고, 애플리케이션의 메서드 파라미터도 변경하지 않아도 된다.

 

---

필드 동기화 - 적용

지금까지 만든 FieldLogTrace를 애플리케이션에 적용해보자.

 

LogTrace 스프링 빈 등록

FieldLogTrace를 수동으로 스프링 빈으로 등록하자 수동으로 등록하면 향후 구현체를 편리하게 변경할 수 있다는 장점이 있다.

 

LogTraceConfig

@Configuration
public class Configration {

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

 

⭐traceIdHolder 필드를 사용한 덕분에 파라미터 추가 없는 깔금한 추적기를 완성했다. 이제 실제 서비스에 배포한다고 가정해보자.

 

❗이때 어떤 문제가 발생할까??? → ⭐⭐ 동시성 문제

(면접 빈출 질문, 실무에서 발생하는 문제)

---

필드 동기화 - 동시성 문제

잘 만든 로그 추적기를 실제 서비스에 배포했다. 가정해보자.

테스트 할 때는 문제가 없는 것 처럼 보인다. 사실 직전에 만든 FieldLog는 심각한 동시성 문제를 가지고 있다. 

동시성 문제를 확인하려면 다음과 같이 오시에 여러번 호출해 보면 된다.

 

동시성 문제 확인

다음 로직을 1초 안에 2번 실행해 보자.

• http://localhost:7000/v3/order?itemId=hello
• http://localhost:7000/v3/order?itemId=hello

기대하는 결과

 

동시에 여러 사용자가 요청하면 여러 쓰레드가 동시에 애플리케이션 로직을 호출하게 된다. 따라서 로그는 위와 같이 섞여서 출력하게 된다.

 

실제 결과

 

실제로 빠른 시간 안에 2번 해당 로직을 실행한 후에 출력결과를 확인하면 추적로그의 depth가 뒤죽박죽이다. 또한 하나의 트랜잭션ID가 두개의 쓰레드에서 사용되었다는 것을 확인할 수 있다.

 

동시성 문제

사실 이 문제는 동시성 문제다.

FieldLogTrace는 싱글톤으로 등록된 스프링 빈이다. 해당 객체 인스턴스가 애플리케이션에 딱 1개 존재한다는 의미이다. 이렇게 하나만 존재하는  FieldLogTrace.traceIdHolder 필드를 여러 쓰레드가 동시에 접근하기 때문에 문제가 발생한다.

 

 

[출처 - 스프링 핵심원리-고급편, 저 김영한]

https://www.inflearn.com/course/%EC%8A%A4%ED%94%84%EB%A7%81-%ED%95%B5%EC%8B%AC-%EC%9B%90%EB%A6%AC-%EA%B3%A0%EA%B8%89%ED%8E%B8

스프링 핵심 원리 - 고급편 강의 - 인프런