[스프링 핵심원리- 고급편] #2. 스레드로컬 - ThreadLocal(2)

[Pracrobo]

필드 동기화 - 적용

지금까지 만든 FieldLogTrace 를 애플리케이션에 적용해보자

LogTrace 스프링 빈 등록

FieldLogTrace를 수동으로 스프링 빈으로 등록하자. 수동으로 등록하면 향후 구현체를 편리하게 변경할 수 있다는 장점이 있다.

LogTraceConfig

package hello.advanced;

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

@Configuration // @Component 가 있어 SpringBean의 대상이 된다.
public class LogTraceConfig {
    @Bean
    public LogTrace logTrace() {
        return new FieldLogTrace(); //Singleton으로 등록됨
    }

}

OrderControllerV3

package hello.advanced.app.v3;

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

@RestController // @Controller + @ResponseBody
@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"; // @RestController 이기 때문에 문자
        } catch (Exception e) {
            trace.exception(status, e); // 예외를 가지고 있음
            throw e;//예외를 다시 던져줘야 한다.
        }
    }

}

OrderRepositoryV3

package hello.advanced.app.v3;

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

@Repository
@RequiredArgsConstructor
public class OrderRepositoryV3 {
    private final LogTrace trace;

    public void save(String itemId) {
        TraceStatus status = null;
        try {
            status = trace.begin("OrderRepository.save()");
            // 저장로직
            if (itemId.equals("ex")) {
                throw new IllegalArgumentException("예외발생! ");
            }
            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();
        }
    }
}

OrderServiceV3

package hello.advanced.app.v3;

import hello.advanced.trace.TraceStatus;
import hello.advanced.trace.logtrace.LogTrace;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.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("OrderService.orderItem()");
            orderRepository.save(itemId);
            trace.end(status); //예외터졌을때 이 부분 안나옴
        } catch (Exception e) {
            trace.exception(status, e); // 예외를 가지고 있음
            throw e;//예외를 다시 던져줘야 한다.
        }

    }
}

[정상결과]

[예외결과]

traceIdHolder 필드를 사용한 덕분에 파라미터 추가 없는 깔끔한 로그 추적기를 완성했다.

이제 실제 서비스에 배포한다고 가정해보자.

필드 동기화 - 동시성 문제

잘 만든 로그 추적기를 실제 서비스에 배포했다 가정해보자

테스트 할때는 문제가 없는 것처럼 보인다. 사실 직전에 만든 FieldLogTrace 는 심각한 동시성 문제를 가지고 잇다.

동시성 문제를 확인해보려면 다음과 같이 동시에 여러번 호출해보면 된다.

동시성 문제 확인

다음 로직을 1초 안에 2번 실행해보자.

http://localhost:8082/v3/request?itemId=hello

http://localhost:8082/v3/request?itemId=hello

[기대한 결과]

[실제 결과]

스레드 실행된 하나의 것: [nio-port-exec-숫자]

• 트랜잭션 ID도 동일하고 level도 많이 꼬인것 같다.
• 분명히 테스트 코드로 짝성할때는 문제가 없었는데 무엇이 문제일까

동시성 문제

FieldLogTrace 는 싱글톤으로 등록된 스프링 빈이다. 이 객체의 인스턴스가 애플리케이션에 딱 1개 존재한다는 뜻이다. 이렇게 하나만 있는 인스턴스의 FieldLogTrace.traceIdHolder 필드를 여러 스레드가 동시에 접근하기 때문에 문제가 발생한다. 실무에서 한번 나타ㅏ나면 개발자를 가장 괴롭히는 문제도 이런 동시성 문제이다.

동시성 문제 - 예제 코드

동시성 문제가 어떻게 발생하는지 단순화해서 알아보자

build.gradle 에서 test : lombok을 사용

testCompileOnly 'org.projectlombok:lombok'
testAnnotationPr~ocessor 'org.projectlombok:lombok'

lombok → 테스트 코드에서 @Slfj4 와 같은 애노테이션이 작동한다.

FieldService

package hello.advanced.trace.threadlocal.code;

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

• 매우 단순한 로직
• 파라미터로 넘어온 name 을 필드인 nameStore에 저장한다. 그리고 1초간 쉰 다음 필드에 저장된 namveStore를 반환한다.

FieldServiceTest

package hello.advanced.trace.threadlocal;

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

@Slf4j
public class FieldServiceTest {

    private 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(); // A 실행
        sleep(2000); // 동시성 문제 발생 X
        threadB.start(); // B 실행
        sleep(3000); // 메인 스레드 종료 대기
        log.info("main exit");

    }

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

    }
}

순서대로 실행

• sleep(2000)을 설정해서 thread-A의 실행이 끝나고 나서 thread-B 가 실행되도록 해보자
• 참고로 FieldService.logic() 메서드는 내부에 sleep(1000) 으로 1초의 지연이 있다.
• 따라서 1초 이후에 호출하면 순서대로 실행할 수 있다. 여기서는 넉넉하게 2초를 설정했다.

sleep(2000); // 동시성 문제 발생 X

[실행]

로직 전체 보기

실행결과를 보면 문제가 없다.

• Thread-A 는 userA를 nameStore에 저장했다.
• Thread-A는 userA를 nameStore에서 조회했다.
• Thread-B는 userB를 nameStore에 저장했다.
• Thread-B는 userB를 nameStore에 조회했다.

동시성 문제 발생 코드

이번에는 sleep(100)을 설정해서 thread-A 의 작업이 끝나기 전에 thread-B 가 실행되도록 해보자.

참고로 FieldService.logic() 메서드는 내부에 sleep(1000)으로 1초의 지연이 있다.

따라서 1초 이후에 호출하면 순서대로 실행할 수 있다. 다음에 설정할 100(ms)는 0.1이기 때문에 thread-A의작업이 끝나기 전에 thread-B가 실행된다.

sleep(100); // 동시성 문제 발생O

실행 결과를 보자. 저장하는 부분은 문제가 없다. 문제는 조회하는 부분에서 발생한다.

• 먼저 thread-A가 userA값을 nameStore에 보관한다.

• 0.1 초 이후에 thread-B가 userB의 값을 nameStore에 보관한다. 기존에 nameStore에 보관되어 있던 userA값은 제거되고 userB값이 저장된다.

• thread-A의 호출이 끝나면서 nameStore 의 결과를 반환받는데 이때 nameStore는 앞의2번에서 userB의 값으로 대체되었다. 따라서 기대했던 userA의 값이 아니라 userB의 값이 반환된다.
• thread-B 의 호출이 끝나면서 nameStore의 결과인 userB를 반환받는다.

정리

1. Thread-A는 userA를 nameStore에 저장했다.
2. Thread-B 는 userB를 nameStore에 저장했다.
3. Thread-A는 userB 를 nameStore 에서 조회했다.
4. Thread-B는 userB를 nameStore 에서 조회했다.

동시성 문제

결과적으로 Thread-A 입장에서는 저장한 데이터와 조회한 데이터가 다른 문제가 발생한다. 이처럼 여러 스레드가 동시에 같은 인스턴스의 필드 값을 변경하면서 발생하는 문제를 동시성 문제라 한다. 이런 동시성 문제는 여러 스레드가 같은 인스턴스의 필드에 접근해야 하기 때문에 트래픽이 적은 상황에서는 확률상 잘 나타나지 않고 트래픽이 점점 많아질수록 자주 발생한다.

특히 스프링 빈처럼 싱글톤 객체의 필드를 변경하며 사용할때 이러한 동시성 문제를 조심해야 한다.

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

그렇다면 지금처럼 싱글톤 객체의 필드를 사용하면서 동시성 문제를 해결하려면 어떻게 해야할까?

다시 파라미터를 전달하는 방식으로 돌아가야 할까? 이럴때 사용하는 것이 바로 스레드 로컬이다.