스프링 핵심 원리(고급편)

Ch02. 쓰레드 로컬(ThreadLocal) - 필드 동기화

webmaster 2022. 4. 8. 10:40
728x90

파라미터를 넘기지 않고 문제를 해결해 보자

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 TraceId traceIdHandler;
    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 = traceIdHandler;
        long startTimeMs = System.currentTimeMillis();
        //로그 출력
        log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);
        return new TraceStatus(traceId, startTimeMs, message);
    }

    private void syncTraceId(){
        if(traceIdHandler == null){
            traceIdHandler = new TraceId();
        }else{
            traceIdHandler = traceIdHandler.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(traceIdHandler.isFirstLevel()){
            traceIdHandler = null; //destroy
        }else{
            traceIdHandler = traceIdHandler.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();
    }
}
  • TraceId를 동기화하는 부분을 파라미터를 사용하는 것에서 TraceId traceIdHandler 필드를 사용하도록 변경
  • 이제 TraceId는 파라미터로 전달되는 것이 아니라 FieldLogTrace의 필드인 traceIdHandler에 저장된다.
  • syncTraceId() 
    • TraceId를 새로 만들거나 앞선 로그의 TraceId를 참고해서 동기화하고, level 도 증가한다.
    • 최초 호출이면 TraceId 를 새로 만든다.
    • 직전 로그가 있으면 해당 로그의 TraceId를 참고해서 동기화하고, level 도 하나 증가한다.
    • 결과를 traceIdHolder 에 보관한다
  • releaseTraceId()
    • 메서드를 추가로 호출할 때는 level 이 하나 증가해야 하지만, 메서드 호출이 끝나면 level 이 하나 감소해야 한다.
    • releaseTraceId() 는 level을 하나 감소한다.
    • 만약 최초 호출( level==0 )이면 내부에서 관리하는 traceId를 제거한다.

Test

class FieldLogTraceTest {

    FieldLogTrace trace = new FieldLogTrace();

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

    @Test
    public void beginExceptionLevel2(){
        TraceStatus status1 = trace.begin("hello1");
        TraceStatus status2 = trace.begin("hello2");
        trace.exception(status2, new IllegalStateException());
        trace.exception(status1, new IllegalStateException());
    }
}

적용

수동 빈 등록(LogTraceConfig)

@Configuration
public class LogTraceConfig {

    @Bean
    public LogTrace logTrace(){
        return new FieldLogTrace();
    }
}
  • 싱글톤으로 등록이 된다.

controller

@RestController
@RequiredArgsConstructor
public class OrderControllerV3 {

    private final OrderServiceV3 orderService;
    private final LogTrace trace;

    @GetMapping("/v3/request")
    public String request(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; //예외를 꼭 다시 던져주어야 한다.
        }
    }
}

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("OrderController.request()");
            orderRepository.save(itemId);
            trace.end(status);
        }catch (Exception e){
            trace.exception(status, e);
            throw e; //예외를 꼭 다시 던져주어야 한다.
        }
    }
}

repository

@Repository
@RequiredArgsConstructor
public class OrderRepositoryV3 {

    private final LogTrace trace;

    public void save(String itemId){
        TraceStatus status = null;
        try{
            status = trace.begin("OrderController.request()");
            //저장 로직
            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();
        }
    }
}

동시성 문제

문제가 없을거 같지만 일 초 안에 2번 실행한다면?

2022-04-08 10:42:13.327  INFO 19584 --- [nio-8080-exec-1] h.advanced.trace.logtrace.FieldLogTrace  : [63124477] OrderController.request()
2022-04-08 10:42:13.327  INFO 19584 --- [nio-8080-exec-1] h.advanced.trace.logtrace.FieldLogTrace  : [63124477] |-->OrderController.request()
2022-04-08 10:42:13.328  INFO 19584 --- [nio-8080-exec-1] h.advanced.trace.logtrace.FieldLogTrace  : [63124477] | |-->OrderController.request()
2022-04-08 10:42:13.761  INFO 19584 --- [nio-8080-exec-2] h.advanced.trace.logtrace.FieldLogTrace  : [63124477] | | |-->OrderController.request()
2022-04-08 10:42:13.761  INFO 19584 --- [nio-8080-exec-2] h.advanced.trace.logtrace.FieldLogTrace  : [63124477] | | | |-->OrderController.request()
2022-04-08 10:42:13.761  INFO 19584 --- [nio-8080-exec-2] h.advanced.trace.logtrace.FieldLogTrace  : [63124477] | | | | |-->OrderController.request()
2022-04-08 10:42:14.343  INFO 19584 --- [nio-8080-exec-1] h.advanced.trace.logtrace.FieldLogTrace  : [63124477] | |<--OrderController.request() time=1015ms
2022-04-08 10:42:14.343  INFO 19584 --- [nio-8080-exec-1] h.advanced.trace.logtrace.FieldLogTrace  : [63124477] |<--OrderController.request() time=1016ms
2022-04-08 10:42:14.343  INFO 19584 --- [nio-8080-exec-1] h.advanced.trace.logtrace.FieldLogTrace  : [63124477] OrderController.request() time=1016ms
2022-04-08 10:42:14.765  INFO 19584 --- [nio-8080-exec-2] h.advanced.trace.logtrace.FieldLogTrace  : [63124477] | | | | |<--OrderController.request() time=1004ms
2022-04-08 10:42:14.765  INFO 19584 --- [nio-8080-exec-2] h.advanced.trace.logtrace.FieldLogTrace  : [63124477] | | | |<--OrderController.request() time=1004ms
2022-04-08 10:42:14.765  INFO 19584 --- [nio-8080-exec-2] h.advanced.trace.logtrace.FieldLogTrace  : [63124477] | | |<--OrderController.request() time=1004ms

로그가 이상하게 찍힌다 -> 빈은 싱글톤으로  JVM 안에 하나의 인스턴스 밖에 없지만 2개의 스레드에서 접근을 해서 발생하는 문제이다.

 

728x90

'스프링 핵심 원리(고급편)' 카테고리의 다른 글

Ch02. 쓰레드 로컬(ThreadLocal) - ThreadLocal  (0) 2022.04.08
Ch02. 쓰레드 로컬(ThreadLocal) - 동시성 문제(예제 코드)  (0) 2022.04.08
Ch01. 예제 만들기 - 로그 추적기(3)  (0) 2022.04.07
Ch01. 예제 만들기 - 로그 추적기(2)  (0) 2022.04.07
Ch01. 예제 만들기 - 로그 추적기(1)  (0) 2022.04.07

'스프링 핵심 원리(고급편)'의 다른글

  • 현재글Ch02. 쓰레드 로컬(ThreadLocal) - 필드 동기화

관련글

댓글

티스토리툴바