Spring 핵심원리 고급편 - ThreadLocal 적용
목차 Post not found: springboot/spring-aop/threadlocal/threadlocal-01 Post not found: springboot/spring-aop/threadlocal/threadlocal-02 Post not found: springboot/spring-aop/threadlocal/threadlocal-03 Post not found: springboot/spring-aop/threadlocal/threadlocal-04 Post not found: springboot/spring-aop/threadlocal/threadlocal-05 Post not found: springboot/spring-aop/threadlocal/threadlocal-06 ThreadLocal 적용@Slf4jpublic 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] hello115:20:49.179 [Test worker] INFO com.example.advancedspring.trace.logtrace.ThreadLocalLogTrace - [fb5762b8] |-->hello215:20:49.180 [Test worker] INFO com.example.advancedspring.trace.logtrace.ThreadLocalLogTrace - [fb5762b8] |<--hello2 time=3ms15:20:49.180 [Test worker] INFO com.example.advancedspring.trace.logtrace.ThreadLocalLogTrace - [fb5762b8] hello1 time=6ms @Configurationpublic 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=1002ms2021-12-06 02:15:38.488 INFO 21903 --- [nio-8080-exec-1] c.e.a.t.logtrace.ThreadLocalLogTrace : [0b8754c1] |<--OrderService.orderItem() time=1003ms2021-12-06 02:15:38.488 INFO 21903 --- [nio-8080-exec-1] c.e.a.t.logtrace.ThreadLocalLogTrace : [0b8754c1] OrderController.request() time=1003ms