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

ThreadLocalLogTrace

@Slf4j
public class ThreadLocalLogTrace implements LogTrace{

    //private TraceId traceIdHandler;
    private ThreadLocal<TraceId> traceHolder = new ThreadLocal<>();
    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 = traceHolder.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 = traceHolder.get();
        if(traceId == null){
            traceHolder.set(new TraceId());
        }else{
            traceHolder.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 = traceHolder.get();
        if(traceId.isFirstLevel()){
            traceHolder.remove(); //destroy
        }else{
            traceHolder.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();
    }
}

• TesttraceIdHolder 가 필드에서 ThreadLocal로 변경되었다. 따라서 값을 저장할 때는 set(..)을 사용하고, 값을 조회할 때는 get()을 사용한다
• threadLocal.remove()
  • 쓰레드 로컬을 모두 사용하고 나면 꼭 ThreadLocal.remove()를 호출해서 스레드 로컬에 저장된 값을 제거해주어야 한다
  • traceId.isFirstLevel() ( level==0 )인 경우 ThreadLocal.remove() 를 호출해서 스레드 로컬에 저장된 값을 제거해준다

LogTraceConfig 주입된 의존관계 수정

의존 관계 수정

• 해당값만 바뀌어도 OCP를 지키며 완벽하게 구현체가 변경된다.

2022-04-08 11:49:12.225  INFO 3000 --- [nio-8080-exec-2] h.a.trace.logtrace.ThreadLocalLogTrace   : [695860ba] OrderController.request()
2022-04-08 11:49:12.225  INFO 3000 --- [nio-8080-exec-2] h.a.trace.logtrace.ThreadLocalLogTrace   : [695860ba] |-->OrderController.request()
2022-04-08 11:49:12.226  INFO 3000 --- [nio-8080-exec-2] h.a.trace.logtrace.ThreadLocalLogTrace   : [695860ba] | |-->OrderController.request()
2022-04-08 11:49:12.714  INFO 3000 --- [nio-8080-exec-3] h.a.trace.logtrace.ThreadLocalLogTrace   : [c6bed746] OrderController.request()
2022-04-08 11:49:12.714  INFO 3000 --- [nio-8080-exec-3] h.a.trace.logtrace.ThreadLocalLogTrace   : [c6bed746] |-->OrderController.request()
2022-04-08 11:49:12.715  INFO 3000 --- [nio-8080-exec-3] h.a.trace.logtrace.ThreadLocalLogTrace   : [c6bed746] | |-->OrderController.request()
2022-04-08 11:49:13.234  INFO 3000 --- [nio-8080-exec-2] h.a.trace.logtrace.ThreadLocalLogTrace   : [695860ba] | |<--OrderController.request() time=1008ms
2022-04-08 11:49:13.234  INFO 3000 --- [nio-8080-exec-2] h.a.trace.logtrace.ThreadLocalLogTrace   : [695860ba] |<--OrderController.request() time=1009ms
2022-04-08 11:49:13.234  INFO 3000 --- [nio-8080-exec-2] h.a.trace.logtrace.ThreadLocalLogTrace   : [695860ba] OrderController.request() time=1009ms
2022-04-08 11:49:13.723  INFO 3000 --- [nio-8080-exec-3] h.a.trace.logtrace.ThreadLocalLogTrace   : [c6bed746] | |<--OrderController.request() time=1008ms
2022-04-08 11:49:13.724  INFO 3000 --- [nio-8080-exec-3] h.a.trace.logtrace.ThreadLocalLogTrace   : [c6bed746] |<--OrderController.request() time=1010ms
2022-04-08 11:49:13.724  INFO 3000 --- [nio-8080-exec-3] h.a.trace.logtrace.ThreadLocalLogTrace   : [c6bed746] OrderController.request() time=1010ms

• 로그를 스레드 별로 구분해 보면 정확하게 동작한 것을 확인할 수 있다.

주의 사항

쓰레드스레드 로컬의 값을 사용 후 제거하지 않고 그냥 두면 WAS(톰캣)처럼 스레드 풀을 사용하는 경우에 심각한 문제가 발생할 수 있다.

사용자 A 요청

사용자 A Thread 요청

• 사용자 A가 Thread 풀에서 ThreadA를 받아 ThreadA의 ThreadLocal에 데이터를 저장한다.

사용자 A 저장 후 remove하지 않고 Thread 반환

사용자 A  ThreadA 반환

• 사용자 A가 사용한 threadA의  ThreadLocal를 비우지 않고 Thread를 반환

사용자 B가 ThreadA를 통해 조회 요청

사용자 B가 ThreadA를 통해 조회 요청

• 사용자 B가 조회 요청을 하였는데 ThreadPool에서 ThreadA를 할당해줄 경우 사용자 B는 사용자 A가 ThreadLocal에 저장한 값을 보게 되는 심각한 문제가 있다.
• 이런 문제를 예방하려면 사용자A의 요청이 끝날 때 스레드 로컬의 값을 ThreadLocal.remove()를 통해서 꼭 제거해야 한다.
  
  • 인터셉터나 필터에서 remove()를 해주어도 된다.