[SPRING] 스프링 핵심 원리 고급편 | 쓰레드 로컬

필드 동기화 V3

이전 로그 추적기 V2는 메서드 간 파라미터 전달을 통해 TraceID 동기화를 실현

(이전 학습내용 2021.11.15 - [java/study] - [SPRING] 스프링 핵심 원리 고급편 | 프로젝트 생성과 로그 추적기)

[SPRING] 스프링 핵심 원리 고급편 | 프로젝트 생성과 로그 추적기

이렇게 하면 모든 메서드에 TraceId를 추가해줘야함으로 이 방식이 아니라 하나의 공통된 TraceId 필드를 만드는 방법으로 수정해보자

 

로그 추적을 위한 새로운 로그 인터페이스와 클래스 생성

🗂 trace > 🗂 logtrace > 📄 LogTrace

public interface LogTrace {

    TraceStatus begin(String message);
    void end(TraceStatus status);
    void exception(TraceStatus status, Exception e);
}

로그 추적을 위해 필요한 최소한의 메서드만 작성

 

🗂 trace > 🗂 logtrace > 📄 FieldLogTrace

@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-";

    private TraceId traceIdHolder;

    @Override
    public TraceStatus begin(String message) {
        syncTraceId();
        TraceId traceId = traceIdHolder; // sync 후 traceIdHolder를 불러와 사용
        Long startTimeMs = System.currentTimeMillis();
        log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);
        return new TraceStatus(traceId, startTimeMs, message);
    }

    @Override
    public void end(TraceStatus status) {
        complete(status, null);
    }

    @Override
    public void exception(TraceStatus status, Exception e) {
        complete(status, e);
    }
    
    private void syncTraceId() {
        if (traceIdHolder == null) {
            traceIdHolder = new TraceId(); // 처음에는 traceId 생성
        } else { // 이후 호출에는 다음 레벨로 증가
            traceIdHolder = traceIdHolder.createNextId();
        }
    }

    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() {
        if (traceIdHolder.isFirstLevel()) { 
            traceIdHolder = null; // 첫번째 레벨이라면(마지막에 도달, 로그가 끝남) -> traceId 제거
        } else {
            traceIdHolder = traceIdHolder.createPreviousId(); // 아직 첫번째 레벨이 아닌 중간 단계 -> 이전 level
        }
    }

    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를 메서드에 파라미터를 넘기는 방법 대신 FieldLogTrace의 TraceIdHolder에 저장

FieldLogTrace 수동으로 스프링 빈 등록

 

🗂 config > 📄 LogTraceConfig

@Configuration // @Component 
public class LogTraceConfig {

    @Bean // 수동으로 빈 등록
    public LogTrace logTrace() {
        return new FieldLogTrace(); 
    }
}

• @Configuration 해당 클래스가 스프링 환경 설정과 관련된 파일임을 알려주며, 스프링 빈 그 자체로도 인식 가능(내부적으로 @Component 포함되어있음)
• @Bean 스프링 빈 객체임을 알려줌(빈 등록)

 

스프링 컨테이너에 빈 등록 방법

• Component Scanning
  @SpringBootApplication 내부에 @ComponentScan이 포함되어있으며 이는 @Component 어노테이션이 붙은 클래스를 찾아 빈으로 등록 
• 설정파일에서 직접 등록 

@Configuration과 @Bean을 이용하여 직접 설정파일로 지정하고 빈을 등록한다.

 

로그 추적 실행을 위한 컨트롤러와 레퍼지토리, 서비스 작성(V2와 동일하나 HelloTraceV2 대신 위에서 작성한 LogTrace 사용)

🗂 app > 🗂 v3 > 📄 OrderServiceV3

@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; 
        }
    }
}

🗂 app > 🗂 v3 > 📄 OrderRepositoryV3

@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 IllegalStateException(("예외 발생!"));
            }
            sleep(1000);

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

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

🗂 app > 🗂 v3 > 📄 OrderControllerV3

@RestController 
@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";
        } catch (Exception e) {
            trace.exception(status, e);
            throw e;
        }
    }
}

정상 종료

예외 종료

 

** 문제 발생

현재 한번의 로직이 돌 때 1초가 소요되는데 1초 안에 여러번 요청이 들어오면 동시성 문제가 발생함

 

쓰레드는 요청에 따라 각각 생성되나 트랜잭션 아이디가 동일하여 로그가 이상하게 남는 모습을 확인할 수 있음

 

동시성 문제란

하나의 인스턴스 필드에 여러 쓰레드가 접근하여 생기는 문제로 특히 스프링 빈과 같이 싱글톤으로 등록된 필드를 수정할 때 많이 발생

동시성 문제는 지역 변수(각각 다른 메모리에 할당)에서는 발생하지 않지만 멤버 변수(필드)나 static 공용 필드에 접근할 때 발생함(특히 수정 시)

멤버 변수란? 메서드 밖에서 선언된 변수를 의미하며 메서드 안의 변수는 지역변수라고 한다.
멤버 변수는 클래스 변수와 인스턴스로 변수로 나뉘며 모든 객체가 공통적인 속성을 지닐 때 클래스, 개별적인 속성을 지녀야할 때 인스턴스 변수를 선언한다.

 

위의 경우 FieldLogTrace가 싱글톤으로 등록된 스프링 빈이기 때문에 여러 스레드가 동시에 접근하려하면 문제가 발생함

 

간단한 예제를 통한 동시성 문제 확인

테스트시 lombok 사용 허용

📄 build.gradle

dependencies {
    ...
    
	// 테스트에서 lombok 사용
	testCompileOnly 'org.projectlombok:lombok'
	testAnnotationProcessor 'org.projectlombok:lombok'
}

 

이름을 저장하는 간단한 테스트 서비스 작성(테스트 폴더에 위치)

📄 FieldService

@Slf4j
public class FieldService {

    private String nameStore;

    public String logic(String name) {
        log.info("저장 name={} -> nameStore={}", name, nameStore);
        nameStore = name;
        sleep(1000); // 저장하는데 1초 걸린다고 가정
        log.info("조회 nameStore={}", nameStore);
        return nameStore;
    }

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

sleep() 메서드를 작성하여  이름을 저장하는데 1초가 걸린다고 가정

 

📄 FieldServiceTest

@Slf4j
public class FieldServiceTest {

    private FieldService fieldService = new FieldService();

    @Test
    void field(){
        log.info("main start");
        Runnable userA = new Runnable() { 
            @Override
            public void run() {
                fieldService.logic("userA");
            }
        };
        Runnable userB = () -> { 
            fieldService.logic("userB");
        };
        
        Thread threadA = new Thread(userA);
        threadA.setName("thread-B");
        Thread threadB = new Thread(userB);
        threadB.setName("thread-B");
        
        threadA.start();
        sleep(2000); // A가 완전히 끝난 후 B 실행
        threadB.start(); 
        sleep(3000); // 메인 스레드 종료 대기, sleep하지 않을 경우 메인 스레드 바로 종료
        log.info("main exit");

    }
}

마지막에 sleep(3000) 을 하지 않으면 메인 스레드가 바로 종료됨으로 threadB가 종료될 때 까지 대기해줘야함

이름 저장에 1초가 걸리나 threadA와 threadB 사이 sleep(2000) 을 통해 둘 사이 동시성 문제가 현재 발생하지 않음

 

테스트 실행 결과 이름이 각각 쓰레드에 맞게 잘 출력(저장)되는 것을 알 수 있음

 

하지만 sleep(2000)이 아니라 sleep(100)으로 수정할 경우

threadA.start();
sleep(100); // A가 완전히 끝나기 전에 B 실행됨 -> 동시성 문제 발생
threadB.start(); 
sleep(3000);
log.info("main exit");

ThreadA는 저장한 정보와 조회한 정보가 다른 문제가 발생한다.

 

그림에서처럼 threadA가 저장한 userA가 반환되기 전 userB가 다시 저장되어 잘못된 값을 반환하게 된다.

 

 

간단한 예제를 통핸 ThreadLocal 소개

쓰레드 로컬(ThreadLocal)은 각각의 쓰레드만 사용 가능한 보관소로 자바 언어 차원에서 java.lang.ThreadLocal를 제공한다.

 

쓰레드로컬를 이용한 동시성 문제 테스트 해결

📄 ThreadLocalService

@Slf4j
public class ThreadLocalService {

//    private String nameStore;
    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();
        }
    }
}

ThreadLocal은 클래스임으로 값을 사용해야할 때 get(), set() 을 이용해야 함

 

📄 ThreadLocalServiceTest

@Slf4j
public class ThreadLocalServiceTest {

    private ThreadLocalService threadLocalService = new ThreadLocalService();

    @Test
    void field(){
        log.info("main start");
        
        Runnable userA = new Runnable() { 
            @Override
            public void run() {
                threadLocalService.logic("userA");
            }
        };
        
        Runnable userB = () -> { // 람다식 이용
            threadLocalService.logic("userB");
        };
        
        Thread threadA = new Thread(userA);
        threadA.setName("thread-B");
        Thread threadB = new Thread(userB);
        threadB.setName("thread-B");
        
        threadA.start();
        sleep(100); // 동시성 문제가 발생할 때
        threadB.start(); 
        sleep(3000);
        log.info("main exit");

    }
}

각자 저장한 이름에 맞춰 올바르게 조회된 것을 볼 수 있다.

 

이처럼 ThreadLocal을 이용하면 각 쓰레드마다 저장소가 있기 때문에 동시에 접근하더라도 문제가 없다.

 

 

쓰레드 로컬 동기화 적용 V4

다시 로그 추적을 위한 클래스 생성 (위의 FieldLogTrace와 동일하나 traceIdHolder를 ThreadLocal로 생성한다.)

📄 ThreadLocalLogTrace

@Slf4j
public class ThreadLocalLogTrace implements LogTrace {

    ...
   
    private ThreadLocal<TraceId> traceIdHolder = new ThreadLocal<>();

    @Override
    public TraceStatus begin(String message) {
        syncTraceId();
        TraceId traceId = traceIdHolder.get(); // get() 이용하여 traceId 조회
    }
   
   ...

    private void syncTraceId() {
        TraceId traceId = traceIdHolder.get(); // get() 이용하여 traceId 조회
        if (traceId == null) {
            traceIdHolder.set(new TraceId()); // set() 이용하여 traceId 새로 생송
        } else {
            traceIdHolder.set(traceId.createNextId()); // set() 이용하여 traceId 다음 레벨 추가
        }
    }

    private void releaseTraceId() {
        TraceId traceId = traceIdHolder.get();
        if (traceId.isFirstLevel()) {
            traceIdHolder.remove(); // 첫 레벨에 도착하여 로그가 끝나면 쓰레드로컬 비워줌
        } else {
            traceIdHolder.set(traceId.createPreviousId());
       }
    }
    
    ...
}

 

ThreadLocalLogTrace 스프링 빈으로 등록

🗂 config > 📄 LogTraceConfig

@Configuration 
public class LogTraceConfig {

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

 

실행하여 동시성 문제가 해결되었는지 확인

이처럼 각 스레드에 맞게 트랜잭션 아이디가 부여되고 레벨도 잘 표현되었음을 확인할 수 있다.!

로그를 분리해서 확인해서 보면 더 확실히 보여진다.

// TraceId 1244782c
INFO 2362 --- [nio-8080-exec-3] h.a.trace.logtrace.ThreadLocalLogTrace   : [1244782c] OrderController.request()
INFO 2362 --- [nio-8080-exec-3] h.a.trace.logtrace.ThreadLocalLogTrace   : [1244782c] |-->OrderService.orderItem()
INFO 2362 --- [nio-8080-exec-3] h.a.trace.logtrace.ThreadLocalLogTrace   : [1244782c] |   |-->OrderRepository.save()
INFO 2362 --- [nio-8080-exec-3] h.a.trace.logtrace.ThreadLocalLogTrace   : [1244782c] |   |<--OrderRepository.save() time=1005ms
INFO 2362 --- [nio-8080-exec-3] h.a.trace.logtrace.ThreadLocalLogTrace   : [1244782c] |<--OrderService.orderItem() time=1006ms
INFO 2362 --- [nio-8080-exec-3] h.a.trace.logtrace.ThreadLocalLogTrace   : [1244782c] OrderController.request() time=1006ms

// TraceId 4b4c3f63
INFO 2362 --- [nio-8080-exec-4] h.a.trace.logtrace.ThreadLocalLogTrace   : [4b4c3f63] OrderController.request()
INFO 2362 --- [nio-8080-exec-4] h.a.trace.logtrace.ThreadLocalLogTrace   : [4b4c3f63] |-->OrderService.orderItem()
INFO 2362 --- [nio-8080-exec-4] h.a.trace.logtrace.ThreadLocalLogTrace   : [4b4c3f63] |   |-->OrderRepository.save()
INFO 2362 --- [nio-8080-exec-4] h.a.trace.logtrace.ThreadLocalLogTrace   : [4b4c3f63] |   |<--OrderRepository.save() time=1003ms
INFO 2362 --- [nio-8080-exec-4] h.a.trace.logtrace.ThreadLocalLogTrace   : [4b4c3f63] |<--OrderService.orderItem() time=1004ms
INFO 2362 --- [nio-8080-exec-4] h.a.trace.logtrace.ThreadLocalLogTrace   : [4b4c3f63] OrderController.request() time=1004ms

 

 

ThreadLocal 사용 시 주의사항

WAS는 쓰레드풀(Thread Pool)을 사용하여 쓰레드를 배정받아 사용한 뒤 다 사용하면 다시 반환하고 그 스레드를 재사용한다.

스레드 로컬을 비우지 않으면 이전에 사용했던 스레드가 아닌 다른 스레드가 사용할 때 이전값이 남아 잘못된 정보를 반환할 수 있다.

따라서 스레드로컬을 사용할 때에는 사용 완료 후 ThreadLocal.remove() 를 통해 스레드 로컬에 저장된 값을 비워주어야 한다.!

 

Thread Pool(쓰레드 풀)

작업 처리에 사용되는 스레드를 제한된 개수만큼 정해 놓고 작업 큐(Queue)에 들어오는 작업들을 하나씩 스레드가 맡아 처리하는 것을 말한다.

• 다수의 사용자 요청을 처리하고 스레드를 생성/수거하는 부담을 덜어 전체적인 퍼포먼스를 상승시키지만
• 많은 병렬처리를 예상해 너무 많은 스레드를 생성하였다던가 일이 적어 노는 스레드가 발생하는 경우 메모리 낭비로 이어진다.
• 또한 위와 같이 스레드로컬에 쓰레기값이 남아 잘못된 정보를 반환할수도 있다.