SpringSpring 고급편ThreadLocal

Spring 핵심원리 고급편 - ThreadLocal 적용

목차

ThreadLocal 적용

@Slf4j
public class ThreadLocalLogTrace implements LogTrace {

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

    private ThreadLocal<TraceId> traceIdHolder; // traceId 동기화, 동시성 이슈

    @Override
    public TraceStatus begin(String message) {

        syncTraceId();
        TraceId traceId = traceIdHolder.get();
        
        Long startTimeMs = System.currentTimeMillis();
        log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX,
                traceId.getLevel()), message);
        
        return new TraceStatus(traceId, startTimeMs, message);
    }

    private void syncTraceId(){
        TraceId traceId = traceIdHolder.get();

        if(traceId == null){
            traceIdHolder.set(new TraceId());
        }else{
            traceIdHolder.set(traceId.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() {
        TraceId traceId = traceIdHolder.get();

        if(traceId.isFirstLevel()){
            traceIdHolder.remove(); // destroy
        }else{
            traceIdHolder.set(traceId.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();
    }
}
class ThreadLocalLogTraceTest {

    ThreadLocalLogTrace trace = new ThreadLocalLogTrace();

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

        trace.end(status2);
        trace.end(status1);
    }

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

        trace.exception(status2, new IllegalStateException());
        trace.exception(status1,  new IllegalStateException());
    }

}
15:20:49.175 [Test worker] INFO com.example.advancedspring.trace.logtrace.ThreadLocalLogTrace - [fb5762b8] hello1
15:20:49.179 [Test worker] INFO com.example.advancedspring.trace.logtrace.ThreadLocalLogTrace - [fb5762b8] |-->hello2
15:20:49.180 [Test worker] INFO com.example.advancedspring.trace.logtrace.ThreadLocalLogTrace - [fb5762b8] |<--hello2 time=3ms
15:20:49.180 [Test worker] INFO com.example.advancedspring.trace.logtrace.ThreadLocalLogTrace - [fb5762b8] hello1 time=6ms
@Configuration
public class LogTraceConfig {

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

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

Thread 별로 로그가 정확하게 나눠진 것을 확인할 수 있다.

2021-12-06 02:15:37.485  INFO 21903 --- [nio-8080-exec-1] c.e.a.t.logtrace.ThreadLocalLogTrace     : [0b8754c1] OrderController.request()
2021-12-06 02:15:37.485  INFO 21903 --- [nio-8080-exec-1] c.e.a.t.logtrace.ThreadLocalLogTrace     : [0b8754c1] |-->OrderService.orderItem()
2021-12-06 02:15:37.486  INFO 21903 --- [nio-8080-exec-1] c.e.a.t.logtrace.ThreadLocalLogTrace     : [0b8754c1] |   |-->OrderRepository.save()
2021-12-06 02:15:38.488  INFO 21903 --- [nio-8080-exec-1] c.e.a.t.logtrace.ThreadLocalLogTrace     : [0b8754c1] |   |<--OrderRepository.save() time=1002ms
2021-12-06 02:15:38.488  INFO 21903 --- [nio-8080-exec-1] c.e.a.t.logtrace.ThreadLocalLogTrace     : [0b8754c1] |<--OrderService.orderItem() time=1003ms
2021-12-06 02:15:38.488  INFO 21903 --- [nio-8080-exec-1] c.e.a.t.logtrace.ThreadLocalLogTrace     : [0b8754c1] OrderController.request() time=1003ms
2021-12-06 02:15:37.648  INFO 21903 --- [nio-8080-exec-2] c.e.a.t.logtrace.ThreadLocalLogTrace     : [9e39132f] OrderController.request()
2021-12-06 02:15:37.648  INFO 21903 --- [nio-8080-exec-2] c.e.a.t.logtrace.ThreadLocalLogTrace     : [9e39132f] |-->OrderService.orderItem()
2021-12-06 02:15:37.648  INFO 21903 --- [nio-8080-exec-2] c.e.a.t.logtrace.ThreadLocalLogTrace     : [9e39132f] |   |-->OrderRepository.save()
2021-12-06 02:15:38.652  INFO 21903 --- [nio-8080-exec-2] c.e.a.t.logtrace.ThreadLocalLogTrace     : [9e39132f] |   |<--OrderRepository.save() time=1004ms
2021-12-06 02:15:38.653  INFO 21903 --- [nio-8080-exec-2] c.e.a.t.logtrace.ThreadLocalLogTrace     : [9e39132f] |<--OrderService.orderItem() time=1005ms
2021-12-06 02:15:38.653  INFO 21903 --- [nio-8080-exec-2] c.e.a.t.logtrace.ThreadLocalLogTrace     : [9e39132f] OrderController.request() time=1005ms
Share