스프링 코어2 - 로그추적기(feat.Thread Local)

Thread Local

 

이전의 악취나는 로그 추적기 코드를 수정해보자.

먼저 새로운 HelloTrace인 FieldLogTrace를 만든다. FieldLogTrace는 이전과 거의 다 같고, 파라미터 대신 참조를 통해 traceId와 level의 정보를 알 수 있도록 했다. 하여 몇몇 메소드가 추가된다.

 

FieldLogTrace

import hello.advanced.app.trace.TraceId;
import hello.advanced.app.trace.TraceStatus;
import lombok.extern.slf4j.Slf4j;

@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 필드 추가 */
    private TraceId traceIdHolder; // traceId 동기화, 동시성 이슈 발생

    @Override
    public TraceStatus begin(String message) {
        syncTraceId();/*해당 부분 추가*/
        TraceId traceId = this.traceIdHolder;
        Long startTimeMs = System.currentTimeMillis();
        log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);
        return new TraceStatus(traceId, startTimeMs, message);
    }
    /*새로 추가*/
    private void syncTraceId(){
        this.traceIdHolder = (this.traceIdHolder == null) ? new TraceId() : this.traceIdHolder.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(){
        assert this.traceIdHolder != null;
        this.traceIdHolder = (this.traceIdHolder.isFirstLevel()) ? null : this.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();
    }
}

 

새로 추가된 부분을 살펴보자.

 

TraceId traceIdHolder : TraceId필드가 추가되었다. 이는 이전의 trace의 Id, level정보를 저장하기 위함이다. 만약 이렇게 필드에 넣어준다면 클라이언트에서 같은 FieldLogTrace객체를 사용한더면 필드에 traceId와 level정보가 저장되어 있어서 이를 사용하여 다음 로그에 활용할 수 있다.

 

syncTraceId 메서드 : syncTraceId는 이전에 하나의 트랜잭션에 대해 로그가 출력된 적이 있는지 확인한다. 이제 TraceId를 필드에 저장하므로, 이전에 출력된 적이 있다면 TraceId는 null이 아니고, 출력된 적이 없다면 TraceId는 null일 것이다. 하여 null이 아니라면 level을 한 단계 상승시킨 traceId를 traceIdHolder가 참조하도록하고, null이라면 level이 1인 새로운 TraceId객체를 생성하여 traceIdHolder가 참조하도록 한다.

 

releaseTraceId 메서드 : releaseTraceId는 traceIdHolder의 level을 검사하여 로그 출력 로직을 마치기 위해 필요하다. 만약 level이 1이라면 요청을 시작한곳까지 도달한 것이므로 traceIdHolder가 null을 참조하도록한다. null이 아니라면 level을 한 단계 줄인 traceId를 traceIdHolder가 참조하도록 한다.

 

 

이를 테스트 해보자.

import hello.advanced.app.trace.TraceStatus;
import org.junit.jupiter.api.Test;
import static org.junit.jupiter.api.Assertions.*;

class FieldLogTraceTest {

    FieldLogTrace trace = new FieldLogTrace();

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


    @Test
    void begin_exception_level2() {
        TraceStatus trace1 = trace.begin("hello1");
        TraceStatus trace2 = trace.begin("hello2");
        trace.exception(trace2, new IllegalStateException());
        trace.exception(trace1, new IllegalStateException());
    }
}

실행 결과는 아래와 같다.

콘솔창:

12:38:58.588 [Test worker] INFO hello.advanced.app.trace.logtrace.FieldLogTrace - [0d007f9a] hello1
12:38:58.593 [Test worker] INFO hello.advanced.app.trace.logtrace.FieldLogTrace - [0d007f9a] |-->hello2
12:38:58.593 [Test worker] INFO hello.advanced.app.trace.logtrace.FieldLogTrace - [0d007f9a] |<--hello2 time=0ms
12:38:58.593 [Test worker] INFO hello.advanced.app.trace.logtrace.FieldLogTrace - [0d007f9a] hello1 time=7ms
12:38:58.604 [Test worker] INFO hello.advanced.app.trace.logtrace.FieldLogTrace - [af47c657] hello1
12:38:58.604 [Test worker] INFO hello.advanced.app.trace.logtrace.FieldLogTrace - [af47c657] |-->hello2
12:38:58.604 [Test worker] INFO hello.advanced.app.trace.logtrace.FieldLogTrace - [af47c657] |<X-hello2 time=0ms ex=java.lang.IllegalStateException
12:38:58.604 [Test worker] INFO hello.advanced.app.trace.logtrace.FieldLogTrace - [af47c657] hello1 time=0ms ex=java.lang.IllegalStateException

 

 

이제 주문서비스에 직접 적용해보자.

 

먼저 LogFieldTrace를 사용하기 위해 bean으로 등록해야 한다. 아래와 같이 등록한다.

package hello.advanced.app;

import hello.advanced.app.trace.logtrace.FieldLogTrace;
import hello.advanced.app.trace.logtrace.LogTrace;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;

@Configuration
public class LogTraceConfig {

    @Bean /* 구체 타입이 아닌 인터페이스 타입으로 한다. */
    public LogTrace logTrace(){
        return new FieldLogTrace();
    }
}

이제 각 controller, service, repository들에서 이를 사용하면 된다.

 

OrderController

import hello.advanced.app.trace.TraceStatus;
import hello.advanced.app.trace.logtrace.LogTrace;
import lombok.RequiredArgsConstructor;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RestController;

@RequiredArgsConstructor
@RestController
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()");/*begin 사용*/
            orderService.orderItem(itemId);
            trace.end(status);
            return "ok";

        } catch (Exception e) {
            trace.exception(status, e);
            throw e;
        }
    }
}

 

OrderService

import hello.advanced.app.trace.TraceStatus;
import hello.advanced.app.trace.logtrace.LogTrace;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Service;

@RequiredArgsConstructor
@Service
public class OrderServiceV3 {
    private final OrderRepositoryV3 orderRepository;
    private final LogTrace trace;/*의존관계 주입받기*/

    public void orderItem(String itemId){
        TraceStatus status = null;
        try {
            status = trace.begin("OrderService.orderItem()");/* begin 사용 */
            orderRepository.save(itemId);
            trace.end(status);
        } catch (Exception e) {
            trace.exception(status, e);
            throw e;//예외를 반드시 던져줘야 한다.
        }
    }
}

 

OrderRepository

import hello.advanced.app.trace.TraceStatus;
import hello.advanced.app.trace.logtrace.LogTrace;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Repository;

@RequiredArgsConstructor
@Repository
public class OrderRepositoryV3 {
    private final LogTrace trace;/*의존 관계 주입받기*/

    public void save(String itemId) {
        TraceStatus status = null;
        try {
            status = trace.begin("OrderService.orderItem()");/* begin 사용 */
            // --- 저장 로직 ---
            if (itemId.equals("ex")) throw new IllegalStateException("예외 발생!");
            //저장 로직을 수행하는데 1초가 걸린다고 가정
            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();
        }
    }
}

이제 OrderController에서 OrderService의 orderItem 메서드를 호출하거나, OrderService에서 OrderRepository의 save 메서드를 호출할 때, traceId를 파라미터로 넘겨줄 필요가 없어졌다. 

controller, service, repository가 모두 같은 빈 객체인 LogFieldTrace의 traceId를 사용하고 있기 때문이다.

 

이제 한번 요청을 하고 결과를 보자.

 

정상 요청:

콘솔창 실행결과:

 

 

예외가 발생하는 요청:

콘솔창 실행결과:

로그가 잘 출력되는 것을 확인하였다.

 

---

동시성 문제

 

이미 눈치챘겠지만 해당 코드에는 실제로 사용하기에는 동시성 문제가 존재한다. 현재 모든 서비스 각 계층이 같은 FieldLogTrace를 사용하므로 하나의 객체에(싱글톤 빈 객체) 사용자들의 모든 요청에 대한 trace정보가 저장되는 것이다. 

즉 FieldLogTrace.traceIdHolder 필드를 여러 쓰레드가 동시에 접근하기 때문에 문제가 발생하는 것이다.

단일 스레드 만을 사용하여 하나의 요청이 처리되고 난 뒤에 다음 요청을 처리한다면 이는 문제되지 않겠지만, 실제로 서비스를 제공할 때는 다수 사용자들이 동시 접속을 하여 동시에 요청하여 멀티 스레드 환경이 필수적이다. 이러한 상황에서는 각 트랜잭션들이 엉켜 정상적인 로그의 출력 결과도 기대할 수 없다.

 

이를 확인하기 위해 서로 다른 요청을 재빨리 해보았다.

 

결과는 다음과 같았다.

[e860d94d] OrderController.request()
[e860d94d] |-->OrderService.orderItem()
[e860d94d] |   |-->OrderService.orderItem()
[e860d94d] |   |   |-->OrderController.request()
[e860d94d] |   |   |   |-->OrderService.orderItem()
[e860d94d] |   |   |   |   |-->OrderService.orderItem()
[e860d94d] |   |<--OrderService.orderItem() time=1004ms
[e860d94d] |<--OrderService.orderItem() time=1004ms
[e860d94d] OrderController.request() time=1005ms
[e860d94d] |   |   |   |   |<--OrderService.orderItem() time=1003ms
[e860d94d] |   |   |   |<--OrderService.orderItem() time=1003ms
[e860d94d] |   |   |<--OrderController.request() time=1004ms

아주 엉터리 결과가 나온 것을 볼 수 있다. 두 개의 다른 요청인데 트랜잭션ID도 다르게 출력됐고, level도 이상하다. 또한 스레드ID(nio로 시작하는 부분)은 다른데, 트랜잭션ID는 같다.

 

우리가 "기대한 결과"는 아래와 같을 것이다.

[7c971f0c] OrderController.request()
[7c971f0c] |-->OrderService.orderItem()
[7c971f0c] |   |-->OrderService.orderItem()
[7c971f0c] |   |<--OrderService.orderItem() time=1005ms
[7c971f0c] |<--OrderService.orderItem() time=1005ms
[7c971f0c] OrderController.request() time=1005ms
[9bb27355] OrderController.request()
[9bb27355] |-->OrderService.orderItem()
[9bb27355] |   |-->OrderService.orderItem()
[9bb27355] |   |<--OrderService.orderItem() time=1004ms
[9bb27355] |<--OrderService.orderItem() time=1005ms
[9bb27355] OrderController.request() time=1005ms

 

 

참고
이러한 동시성 문제는 필드 변수에서는 발생하지 않는다. 지역 변수는 쓰레드마다 각각 다른 메모리 영역이 할당된다.
동시성 문제가 발생하는 곳은 같은 인스턴스의 필드(주로 싱글톤에서 자주 발생), 또는 static같은 공용 필드에 접근할 때 발생한다. 
동시성 문제는 값을 읽기만 하면 발생하지 않는다. 어디선가 값을 변경하기 때문에 발생한다.

 

하여 이러한 문제를 Thread Local로 해결해보자.

---

Thread Local

 

쓰레드 로컬은 해당 쓰레드만 사용할 수 있는 특별한 저장소를 말한다. 여러 쓰레드가 같은 저장소를 사용하더라도 저장소가 쓰레드를 구분하게 하여 쓰레드 별로 각 쓰레드만의 저장소에 접근하게 된다.

 

쓰레드 로컬을 사용하지 않고, User의 정보를 저장하는 코드를 한 번 테스트해보자.

FieldService는 단순히 logic메서드로 받은 문자열을 nameStore에 저장하고, 1초 뒤, 현재 nameStore에 저장된 데이터를 출력해준다.

import lombok.extern.slf4j.Slf4j;

@Slf4j
public class FieldService {

    private String nameStore;

    public String logic(String name){
        log.info("저장 name={} --> 이전에 nameStore에 저장된 데이터는 <{}>입니다. ", name, nameStore);
        nameStore = name;
        sleep(1000);
        log.info("조회 nameStore={}", nameStore);
        return nameStore;
    }

    private void sleep(int millis) {
        try {
            Thread.sleep(millis);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

 

이를 아래와 같이 테스트한다. (정상적으로 저장과 조회가 이루어짐)

import hello.advanced.app.trace.thread_local.code.FieldService;
import lombok.extern.slf4j.Slf4j;
import org.junit.jupiter.api.Test;

@Slf4j
public class FieldServiceTest {
    private final FieldService fieldService = new FieldService();

    @Test
    void field(){
        log.info("main start");
        Runnable userA = ()-> fieldService.logic("userA");
        Runnable userB = ()-> fieldService.logic("userB");

        Thread threadA = new Thread(userA);
        threadA.setName("thread-A");
        Thread threadB = new Thread(userB);
        threadB.setName("thread-B");

        threadA.start();
        sleep(2000);/*2000일 때: A가 완전히 끝난 후에 B를 실행한다.*/
        threadB.start();

        sleep(3000);//메인 쓰레드 종료 대기
        log.info("main exit");
    }

    private void sleep(int millis) {
        try {
            Thread.sleep(millis);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

실행결과 : 

15:26:36.007 [Test worker] INFO hello.advanced.app.trace.thread_local.FieldServiceTest - main start
15:26:36.011 [thread-A] INFO hello.advanced.app.trace.thread_local.code.FieldService - 저장 name=userA --> 이전에 nameStore에 저장된 데이터는 <null>입니다. 
15:26:37.017 [thread-A] INFO hello.advanced.app.trace.thread_local.code.FieldService - 조회 nameStore=userA
15:26:38.015 [thread-B] INFO hello.advanced.app.trace.thread_local.code.FieldService - 저장 name=userB --> 이전에 nameStore에 저장된 데이터는 <userA>입니다. 
15:26:39.020 [thread-B] INFO hello.advanced.app.trace.thread_local.code.FieldService - 조회 nameStore=userB
15:26:41.016 [Test worker] INFO hello.advanced.app.trace.thread_local.FieldServiceTest - main exit

현재는 threadA.start()를 한 후, threadB는 2초 뒤에 실행되므로 아무 문제가 없이 userA가 nameStore에 저장한 "userA"를 조회할 떄 userA가 조회된다. 하지만 sleep메서드를 threadA가 로직을 모두 실행하고 마치기 전인 0.1초로 바꾸면 결과는 바뀐다.

 

(정상적으로 저장, 조회가 이루어지지 않는 상황)

import hello.advanced.app.trace.thread_local.code.FieldService;
import lombok.extern.slf4j.Slf4j;
import org.junit.jupiter.api.Test;

@Slf4j
public class FieldServiceTest {
    private final FieldService fieldService = new FieldService();

    @Test
    void field(){
        log.info("main start");
        Runnable userA = ()-> fieldService.logic("userA");
        Runnable userB = ()-> fieldService.logic("userB");

        Thread threadA = new Thread(userA);
        threadA.setName("thread-A");
        Thread threadB = new Thread(userB);
        threadB.setName("thread-B");

        threadA.start();
        sleep(100);/* 100일 때 : 동시성 문제가 발생한다. */
        threadB.start();

        sleep(3000);//메인 쓰레드 종료 대기
        log.info("main exit");
    }

    private void sleep(int millis) {
        try {
            Thread.sleep(millis);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

실행결과:

15:25:03.205 [Test worker] INFO hello.advanced.app.trace.thread_local.FieldServiceTest2 - main start
15:25:03.208 [thread-A] INFO hello.advanced.app.trace.thread_local.code.ThreadLocalService - 저장 name=userA --> 이전에 nameStore에 저장된 데이터는 <null>입니다. 
15:25:03.311 [thread-B] INFO hello.advanced.app.trace.thread_local.code.ThreadLocalService - 저장 name=userB --> 이전에 nameStore에 저장된 데이터는 <userA>입니다. 
15:25:04.212 [thread-A] INFO hello.advanced.app.trace.thread_local.code.ThreadLocalService - 조회 nameStore=userB
15:25:04.313 [thread-B] INFO hello.advanced.app.trace.thread_local.code.ThreadLocalService - 조회 nameStore=userB
15:25:06.313 [Test worker] INFO hello.advanced.app.trace.thread_local.FieldServiceTest2 - main exit

결과를 보면 userA가 nameStore를 조회할 때, 이미 "userB"가 저장되어 본인이 저장한 값을 덮어버리게 된것이다.

 

이제 해당 테스트에 ThreadLocal을 적용해보자.

간단하게 이전의 FieldService에 ThreadLocal<String> 타입의 nameStore를 사용해주면 된다.

import lombok.extern.slf4j.Slf4j;

@Slf4j
public class ThreadLocalService {
	/* ThreadLocal 사용 */
    private ThreadLocal<String> nameStore = new ThreadLocal<>();

    public String logic(String name){
        log.info("저장 name={} --> 이전에 nameStore에 저장된 데이터는 <{}>입니다. ", name, nameStore.get());
        nameStore.set(name);
        sleep(1000);
        log.info("조회 nameStore={}", nameStore.get());
        return nameStore.get();
    }

    private void sleep(int millis) {
        try {
            Thread.sleep(millis);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

이제 이를 다시 테스트해보자.

import hello.advanced.app.trace.thread_local.code.ThreadLocalService;
import lombok.extern.slf4j.Slf4j;
import org.junit.jupiter.api.Test;

@Slf4j
public class FieldServiceTest2 {
    private final ThreadLocalService fieldService = new ThreadLocalService();

    @Test
    void field(){
        log.info("main start");
        Runnable userA = ()-> fieldService.logic("userA");
        Runnable userB = ()-> fieldService.logic("userB");

        Thread threadA = new Thread(userA);
        threadA.setName("thread-A");
        Thread threadB = new Thread(userB);
        threadB.setName("thread-B");

        threadA.start();
        sleep(100);/*이제는 100일 때도 동시성 문제가 발생하지 않는다. */
        threadB.start();

        sleep(3000);//메인 쓰레드 종료 대기
        log.info("main exit");
    }

    private void sleep(int millis) {
        try {
            Thread.sleep(millis);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

실행결과:

15:30:23.631 [Test worker] INFO hello.advanced.app.trace.thread_local.FieldServiceTest2 - main start
15:30:23.635 [thread-A] INFO hello.advanced.app.trace.thread_local.code.ThreadLocalService - 저장 name=userA --> 이전에 nameStore에 저장된 데이터는 <null>입니다. 
15:30:23.738 [thread-B] INFO hello.advanced.app.trace.thread_local.code.ThreadLocalService - 저장 name=userB --> 이전에 nameStore에 저장된 데이터는 <null>입니다. 
15:30:24.637 [thread-A] INFO hello.advanced.app.trace.thread_local.code.ThreadLocalService - 조회 nameStore=userA
15:30:24.744 [thread-B] INFO hello.advanced.app.trace.thread_local.code.ThreadLocalService - 조회 nameStore=userB
15:30:26.738 [Test worker] INFO hello.advanced.app.trace.thread_local.FieldServiceTest2 - main exit

 

 

ThreadLocal을 적용한 TraceLogService는 아래와 같다.

ThreadLocalLogService

package hello.advanced.app.trace.logtrace;

import hello.advanced.app.trace.TraceId;
import hello.advanced.app.trace.TraceStatus;
import lombok.extern.slf4j.Slf4j;

@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 = new ThreadLocal<>(); // ThreadLocal을 사용하여 동시성 문제 해소

    @Override
    public TraceStatus begin(String message) {
        syncTraceId();
        TraceId traceId = this.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 = this.traceIdHolder.get();
        if(traceId == null) this.traceIdHolder.set(new TraceId());//set메서를 사용하여 값을 저장한다.
        else this.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 = this.traceIdHolder.get();
        assert traceId != null;
        if(traceId.isFirstLevel()) this.traceIdHolder.remove();/* remove를 해서 현재 쓰레드의 value를 완전히 삭제한다. */
        else this.traceIdHolder.set(traceId.createPreviousId());//set으로 값을 저장
    }

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

ThreadLocal<TraceId>를 사용하는 것 외에는 수정된 것이 거의 없다. 다만 이제 값을 저장할 때 ThreadLocal.set(value) 메서드를 사용하여 저장해야 한다.

또한 반드시 ThreadLocal 저장소를 모두 사용했다면 remove메서드를 통해 저장소를 비워줘야 한다. (releaseTraceId 메서드 참고)

 

이제 각 controller, service, repository가 ThreadLocalLogService를 사용하도록 해보자.

 

ThreadLocalLogService가 빈으로 등록되기 위해 아래와 같이 빈 객체로 등록해준다.

import hello.advanced.app.trace.logtrace.LogTrace;
import hello.advanced.app.trace.logtrace.ThreadLocalLogTrace;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;

@Configuration
public class LogTraceConfig {

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

controller, service, repository는 이전과 바뀐것이 아예 없으므로 코드는 생략한다. (위에서 Bean등록 객체를 바꿔줬으므로 자동으로 의존관계가 ThreadLocalLogTrace 객체로 변경된다.)

 

이제 두개의 요청을 빠르게 날려 결과를 보자.

 

결과는 다음과 같았다.

[701d49e4] OrderController.request()
[701d49e4] |-->OrderService.orderItem()
[701d49e4] |   |-->OrderService.orderItem()
[63e1af77] OrderController.request()
[63e1af77] |-->OrderService.orderItem()
[63e1af77] |   |-->OrderService.orderItem()
[701d49e4] |   |<--OrderService.orderItem() time=1002ms
[701d49e4] |<--OrderService.orderItem() time=1003ms
[701d49e4] OrderController.request() time=1003ms
[63e1af77] |   |<--OrderService.orderItem() time=1001ms
[63e1af77] |<--OrderService.orderItem() time=1001ms
[63e1af77] OrderController.request() time=1002ms

물론 멀티 쓰레드 환경이라 각 트랜잭션 별로 나란히 출력되진 않았지만 각 트랜잭션ID가 구별되었도 level도 알맞게 출력된 것을 확인할 수 있다.

 

 

---

ThreadLocal 사용시 주의사항

 

ThreadLocal을 사용하여 데이터를 저장했다면 다 쓰고 난 뒤 반드시 저장소를 비워줘야 한다. 비우지 않을 시에 어떤 문제가 발생하는지  그림과 함께 살펴보자.

 

1. 사용자A가 자신의 정보를 입력한 뒤 저장해달라는 요청을 했다. 이때 쓰레드 풀에 있던 쓰레드A가 선택되어 사용자A의 정보를 쓰레드A용 ThreadLocal저장소에 저장하고 저장소를 비우지 않았다. 그리고 요청은 종료된다.

 

2. 다음으로 사용자B가 자신의 정보에 대한 요청을 한다. 그런데 이때 하필 쓰레드A가 선택된다.

 

3. 하여 쓰레드A는 ThreadLocal 저장소에 저장되어있는 사용자A의 정보를 사용자B에게 응답해주게되는 문제가 발생한다.

 

이와 같은 상황을 방지하기 위해서 ThreadLocal 저장소를 마지막에 반드기 remove를 해줘야 한다.

 

 

 

 

김영한님의 인프런 강의와 PDF를 바탕으로 정리하였습니다.