ThreadLocal - 예제로 알아보는 쓰레드 로컬 (1)

ThreadLocal - 예제로 알아보는 쓰레드 로컬 (1)

2022. 7. 7. 18:21ㆍSpring 기초

쓰레드 로컬을 학습하기 위해 우선 간단한 예제 프로젝트를 만들어보자.
이번 포스팅은 예제 프로젝트를 작성하며 발생하는 문제점을 알아본다.
다음 포스팅에서 쓰레드 로컬로 해결하는 방법을 소개한다.
상품을 주문하는 프로세스로 가정하고, 일반적인 웹 애플리케이션에서 Controller --> Service --> Repository로 이어지는 흐름을 단순하게 작성한다.

@Repository
@RequiredArgsConstructor
public class OrderRepositoryV0 {
     public void save(String itemId) {
     //저장 로직
     if (itemId.equals("ex")) {
     	throw new IllegalStateException("예외 발생!");
     }
     sleep(1000);

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

리포지토리는 상품을 저장하는데 약 1초 정도 걸리는 것으로 가정하기 위해 1초 지연을 주었다. (1000ms)

다음은 서비스 계층이다.

@Service
@RequiredArgsConstructor
public class OrderServiceV0 {
 private final OrderRepositoryV0 orderRepository;
 
 public void orderItem(String itemId) {
 	orderRepository.save(itemId);
 }
}

예제에서는 단순함을 위해서 리포지토리에 저장을 호출하는 코드만 있다.

마지막으로 컨트롤러

@RestController
@RequiredArgsConstructor
public class OrderControllerV0 {
     private final OrderServiceV0 orderService;
     
     @GetMapping("/v0/request")
     public String request(String itemId) {
         orderService.orderItem(itemId);
         return "ok";
 }
}

메서드는 HTTP 파라미터로 itemId 를 받을 수 있다.

이제 이 초간단 흐름 위에서 로그 추적기를 도입할 예정이다.
로그를 출력하는데 조건은 아래와 같다.

모든 PUBLIC 메서드의 호출과 응답 정보를 로그로 출력한다.
메서드 호출에 걸린 시간과 메서드의 깊이를 로그에 표현한다.
HTTP 요청을 구분한다(HTTP 요청 단위로 특정 ID를 남겨 어떤 HTTP에서 요청한 것인지 구분할 수 있어야 한다)
정상 흐름과 예외 흐름을 구분한다. (예외 발생 시 정상 로직과 다른 로그를 남긴다)

대략 위의 조건을 만족시키는 예시는 아래와 같다.

정상 요청
[796bccd9] OrderController.request()
[796bccd9] |-->OrderService.orderItem()
[796bccd9] | |-->OrderRepository.save()
[796bccd9] | |<--OrderRepository.save() time=1004ms
[796bccd9] |<--OrderService.orderItem() time=1014ms
[796bccd9] OrderController.request() time=1016ms

예외 발생
[b7119f27] OrderController.request()
[b7119f27] |-->OrderService.orderItem()
[b7119f27] | |-->OrderRepository.save()
[b7119f27] | |<X-OrderRepository.save() time=0ms 
ex=java.lang.IllegalStateException: 예외 발생!
[b7119f27] |<X-OrderService.orderItem() time=10ms 
ex=java.lang.IllegalStateException: 예외 발생!
[b7119f27] OrderController.request() time=11ms 
ex=java.lang.IllegalStateException: 예외 발생!

소요 시간, 메소드의 깊이, 정상 - 예외 흐름 구분, 트랜잭션마다 다른 ID 등 요구사항을 만족하고있다.

이제 로그추적기를 개발해보자!!!
먼저 로그 추적기를 위한 기반 데이터를 가지고 있는 TraceId , TraceStatus 클래스를 작성한다.

import java.util.UUID;

public class TraceId {
     private String id;
     private int level;
     
     public TraceId() {
     	this.id = createId();
     	this.level = 0;
     }
     private TraceId(String id, int level) {
        this.id = id;
        this.level = level;
     }
     private String createId() {
     	//HTTP 요청을 구분할 수 있는 ID를 생성한다.
     	return UUID.randomUUID().toString().substring(0, 8);
     }
     public TraceId createNextId() {
     	return new TraceId(id, level + 1);
     }
     public TraceId createPreviousId() {
     	return new TraceId(id, level - 1);
     }
     public boolean isFirstLevel() {
     	return level == 0;
     }
     public String getId() {
     	return id;
     }
     public int getLevel() {
     	return level;
     }
}

TraceId 클래스는 HTTP 요청을 구분할 수 있는 ID와, 메소드의 깊이를 표현하는 level 인스턴스 변수를 갖고있다.

생성자에서 ID를 UUID로 생성해주는데, UUID가 너무 길어서 여기서는 앞 8자리만 사용한다.

ab99e16f-3cde-4d24-8241-256108c203a2 //생성된 UUID
ab99e16f //subString() 메소드로 앞 8자리만 사용한다.

createNextId()
다음 TraceId 를 만든다. 예제 로그를 잘 보면 깊이가 증가해도 트랜잭션ID는 같다. 대신에 깊이가 하나 증가한다.

실행 코드: new TraceId(id, level + 1)  --> id는 같은 값을 유지해야 한다.

[796bccd9] OrderController.request()
[796bccd9] |-->OrderService.orderItem() //트랜잭션ID가 같다. 깊이는 하나 증가한다.

createPreviousId()
createNextId() 의 반대 역할을 한다. id 는 기존과 같고, level 은 하나 감소한다.

isFirstLevel()
첫 번째 레벨 여부를 편리하게 확인할 수 있는 메서드다. 반환값이 true라면 로그의 처음과 끝임을 알 수 있다.

다음은 TraceStatus 클래스다.

public class TraceStatus {
     private TraceId traceId;
     private Long startTimeMs;
     private String message;
     
	 ...
}

TraceStatus 클래스는 로그의 상태 정보를 나타낸다.
traceId : 내부에 트랜잭션ID와 level을 가지고 있다.
startTimeMs : 로그 시작시간이다. 로그 종료시 이 시작 시간을 기준으로 시작~종료까지 전체 수행 시간을 구할 수 있다. message : 시작시 사용한 메시지이다. 이후 로그 종료시에도 이 메시지를 사용해서 출력한다.

로그를 시작하면 끝이 있어야 한다.

[796bccd9] OrderController.request() //로그 시작
[796bccd9] OrderController.request() time=1016ms //로그 종료

TraceStatus 는 로그를 시작할 때의 상태 정보를 가지고 있다. 이 상태 정보는 로그를 종료할 때 사용된다.

TraceId , TraceStatus 를 사용해서 실제 로그를 생성하고, 처리하는 기능을 개발해보자

package hello.advanced.trace.hellotrace;

import hello.advanced.trace.TraceId;
import hello.advanced.trace.TraceStatus;
import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Component;

@Slf4j
@Component
public class HelloTraceV2 {
    private static final String START_PREFIX = "-->";
    private static final String COMPLETE_PREFIX = "<--";
    private static final String EX_PREFIX = "<X-";

    public TraceStatus begin(String message) {
        TraceId traceId = new TraceId();
        Long startTimeMs = System.currentTimeMillis();
        log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX,
                traceId.getLevel()), message);
        return new TraceStatus(traceId, startTimeMs, message);
    }
    public TraceStatus beginSync(TraceId beforeTraceId, String message) {
//        TraceId traceId = new TraceId();
        TraceId traceId = beforeTraceId.createNextId();
        Long startTimeMs = System.currentTimeMillis();

        log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX,
                traceId.getLevel()), message);
        return new TraceStatus(traceId, startTimeMs, message);
    }
    public void end(TraceStatus status) {
        complete(status, null);
    }
    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());
        }
    }
    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();
    }
}

begin

메서드의 메인 로직 전에 호출한다. begin 은 호출 깊이가 0인 메서드에서만 실행된다. 여기서 TraceId를 생성하며 메소드의 깊이가 달라져도 같은 Id를 사용하기 때문이다. 그리고 생성한 Id 와 message 를 출력한다.

beginSync

begin 과 마찬가지로 메서드 시작시 호출할 메서드다. 상위 메서드에서 생성한 TraceId 를 파라미터로 받는다. 동일한 Id를 갖으므로 TraceId 의 level 만 1을 증가시켜서 사용한다. 마찬가지로 Id 와 message를 출력한다.
단도직입으로 말하자면 우리의 예제에서 begin() 메소드는 가장 먼저 실행되는 컨트롤러, beginSync는 그 다음에 오는 서비스와 리포지토리에서 실행된다.

end

메서드의 메인 로직이 끝나고 정상적으로 종료되었을 경우 호출하는 메서드로 complete() 를 호출한다.

complete

메서드 종료시 공통적으로 호출하는 메서드이다. 정상 종료시 현재 level 에서 id, 소요시간, 메시지를 출력한다. 비정상 종료시 동일한 정보와 추가로 예외를 출력한다.

exception

메서드에서 예외가 발생해 비정상 종료되었을 경우 호출하는 메서드이다. complete를 호출한다.

이제 초간단 예제로 다시 돌아가서, 로그 추적기를 도입해보자.

컨트롤러


@RestController
@RequiredArgsConstructor
public class OrderControllerV2 {
    private final OrderServiceV2 orderServiceV2;
    private final HelloTraceV2 trace;

    @GetMapping("/v2/request")
    public String request(String itemId){
        TraceStatus status = null;
        try{
            status = trace.begin("OrderController.begin");
            TraceId traceId = status.getTraceId();

            orderServiceV2.orderItem(itemId, traceId);
            trace.end(status);
            return "OK";
        }catch(Exception e){
            trace.exception(status, e);
            throw e;
        }

    }


}

서비스

@Service
@RequiredArgsConstructor
public class OrderServiceV2 {
    private final OrderRepositoryV2 orderRepository;
    private final HelloTraceV2 trace;

    public void orderItem(String itemId, TraceId traceId){
        TraceStatus status = null;
        try{
            status = trace.beginSync(traceId, "OrderService.orderItem()");
            orderRepository.save(itemId, status.getTraceId());
            trace.end(status);
        }catch (Exception e){
            trace.exception(status, e);
        }
    }
}

리포지토리

@Repository
@RequiredArgsConstructor
public class OrderRepositoryV2 {
    private final HelloTraceV2 trace;

    public void save(String itemId, TraceId traceId){
        TraceStatus status = null;
        try{
            status = trace.beginSync(traceId, "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 mills) {
        try {
            Thread.sleep(mills);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

실행 로그

[0314baf6] hello1
[0314baf6] |-->hello2
[0314baf6] |<--hello2 time=2ms
[0314baf6] hello1 time=25ms

로그를 출력할 때, 레벨이 0 인 컨트롤러에서만 TraceId를 생성한다. 이후 생성한 TraceId를 매개변수로 Service와 Repository에 넘겨주어서 같은 Id 값을 유지할 수 있다. 달라지는 것은 level 뿐이다.

하지만 이렇게 일일이 파라미터로 Id와 level을 넘겨주는 것은 명백한 한계가 있다. 일단 모든 메서드가 Id와 level을 받도록 수정해야 하며, 만약 컨트롤러에서 메소드 호출이 없이 서비스나 리포지토리가 실행된다면 traceId는 없는 상태이므로 에러가 발생한다.

다음 포스팅에서는 TraceId 를 파라미터로 넘기지 않고 Id와 level을 동기화해본다.
쓰레드 로컬은 곧 등장할 것이다..

저작자표시

'Spring 기초' 카테고리의 다른 글

Spring Boot CLI 로 프로젝트 생성하기 (0)	2022.10.31
Redirect VS Forward (0)	2022.09.28
@Profile 어노테이션 (0)	2022.07.06
[Spring] API - 컬렉션 조회(1 : N) (0)	2022.04.17
[Spring] 빈(Bean) 생명주기 콜백+ 빈 의존관계 주입 후 콜백 (0)	2022.04.16

미스터포포

태그

최근글

댓글

공지사항

아카이브