필드 동기화

1. V2 : 이전 코드

TranceId를 파라미터로 넘기는 방식 사용

  • 로그 출력시 트랜잭션ID 와 level을 동기화 해야 해야 함

  • 해결 방안: TranceId를 파라미터로 넘기는 방식으로 동기화 성공

  • 단점: 로그 출력하는 모든 메서드에 TraceId 파라미터 추가해야 함

  • TraceId를 파라미터로 넘기지 않고 문제 해결 방법 없을까?

(1) 로그 추적기 : HelloTrace V2

@Slf4j
@Component
public class HelloTraceV2 {
		// 일부 코드 생략
    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 nextId = beforeTraceId.createNextId();
        Long startTimeMs = System.currentTimeMillis();
        log.info("[" + nextId.getId() + "] " + addSpace(START_PREFIX, nextId.getLevel()) + message);
        return new TraceStatus(nextId, startTimeMs, message);
    }
    
    public void end(TraceStatus status) {
        Long stopTimeMs = System.currentTimeMillis();
        long resultTimeMs = stopTimeMs - status.getStartTimeMs();
        TraceId traceId = status.getTraceId();
            log.info("[{}] {}{} time={}ms", traceId.getId(), addSpace(COMPLETE_PREFIX, traceId.getLevel()), status.getMessage(), resultTimeMs);
    } 
}

(2) Controller, Service, Repository

OrderControllerV0 비교 
@RestController // @Controller + @ResponseBody 합쳐진 것
@RequiredArgsConstructor
public class OrderControllerV0 {

    private final OrderServiceV0 orderService;

    @GetMapping("v0/request")
    public String request(String itemId){
        orderService.orderItem(itemId);
        return "ok";
    }

}
@RestController
@RequiredArgsConstructor
public class OrderControllerV2 {

    private final OrderServiceV2 orderService;
    private final HelloTraceV2 trace;

    @GetMapping("v2/request")
    public String request(String itemId){
        TraceStatus status = null;        
        status = trace.begin("OrderController.request()");
        orderService.orderItem(status.getTraceId(), itemId); // itemId 뿐만 아니라 traceId도 넘겨줌
        trace.end(status);
        return "ok";
    }
}
@Service
@RequiredArgsConstructor
public class OrderServiceV2 {

    private final OrderRepositoryV2 orderRepository;
    private final HelloTraceV2 trace;

    public void orderItem(TraceId traceId, String itemId) {
        TraceStatus status = null;
        status = trace.beginSync(traceId,"OrderService.orderItem()");
        orderRepository.save(status.getTraceId(), itemId);
        trace.end(status);
    }
}
@Repository
@RequiredArgsConstructor
public class OrderRepositoryV2 {

    private final HelloTraceV2 trace;

    public void save(TraceId traceId, String itemId) {
        TraceStatus status = null;
            status = trace.beginSync(traceId, "OrderRepository.save()");
            sleep(1000);
            trace.end(status);
    }
}

2. V3 : 파라미터 넘기지 않고 TraceId 동기화 방안

새로운 로그 추적기

  • 향후 다양한 구현체로 변경할 수 있도록 LogTrace 인터페이스 생성

  • 파라미터 넘기지 않고, TraceId 동기화 할 수 있는 FieldLogTrace 구현체 생성

(1) LogTrace 인터페이스

public interface LogTrace {
    TraceStatus begin(String message);
    void end(TraceStatus status);
    void exception(TraceStatus status, Exception e);
}

(2) FieldLogTrace 구현체

  • FieldLogTrace 역할 : 기존 HelloTraceV2와 거의 같은 기능 수행
  • TraceId 동기화 방식 변경
    • [기존] TraceId를 파라미터 통해서 넘김 → [변경] TraceId를 traceHolder에 보관해 놓고 사용하는 방식
    • 직전 로그의 TraceId는 파라미터로 전달되지 않고, FieldLogTrace의 필드인 traceHolder에 저장됨
  • 로그 시작시 SyncTraceId(), 로그 종료시 releaseTraceId() 호출
syncTraceId와 releaseTraceId 메서드 로직 
    private void syncTraceId(){
        if(traceIdHolder == null){
            traceIdHolder = new TraceId(); // 최초 호출시 traceId 새로 생성
        } else{
            traceIdHolder = traceIdHolder.createNextId();
        }
    }
    
    private void releaseTraceId(){
        if(traceIdHolder.isFirstLevel()){
            traceIdHolder = null; // 내부에서 관리하는 traceId 제거
        } else{
            traceIdHolder = traceIdHolder.createPreviousId();
        }
    }
- **syncTraceId 역할**
    - 최초 호출시, traceId를 새로 생성함
    - 직전 로그가 있으면, 해당 로그의 TraceId를 참고해서 동기화 하고, level을 하나 증가함
    - 결과를 traceIdHolder에 보관
- **releaseTraceId 역할**
    - 메서드 호출될 때마다 level이 하나씩 증가하는 반면, 메서드 호출이 끝날 경우 level이 하나씩 감소해야 함
    - releaseTraceId 메소드는 level을 하나씩 감소하는 역할
    - 만약 최초 호출(level==0)일 경우, 내부에서 관리하는 traceId를 제거함

-

@Slf4j
public class FieldLogTrace implements LogTrace{

    private TraceId traceIdHolder; // traceId 동기화

    @Override
    public TraceStatus begin(String message) {
        syncTraceId(); // 로그 시작시 호출
        
        TraceId traceId = 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) {
        Long stopTimeMs = System.currentTimeMillis();
        long resultTimeMs = stopTimeMs - status.getStartTimeMs();
        TraceId traceId = status.getTraceId();
        log.info("[{}] {}{} time={}ms", traceId.getId(), addSpace(COMPLETE_PREFIX, traceId.getLevel()), status.getMessage(), resultTimeMs);
        
        releaseTraceId(); // 로그 종료시 호출
    }
}

(3) FieldLogTrace 수동 스프링빈 등록

  • @ComponentScan 사용하지않고, 직접 스프링 빈으로 등록함
  • 수동 등록하면 향후 구현체를 편리하게 변경할 수 있다는 장점이 있음
// FieldLogTrace를 수동으로 스프링 빈으로 등록
// @Configuration 내부에도 @Component가 존재하므로 컴포넌트 스캔 자동 대상이 됨
// @Bean이 있으면 스프링컨테이너가 자동으로 읽어서 FieldLogTrace를 자동으로 스프링 빈으로 등록함 (싱글톤으로 등록됨)
@Configuration
public class LogTraceConfig {

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

(3) 동시성 문제

동시성 이슈

  • 동시에 여러 사용자가 요청하면, 여러 쓰레드가 동시에 Application 로직을 호출하게 됨

  • 로그가 섞여서 출력되는 문제 발생

  • 원인

image.png

  • 동시성 문제 예시
    • Thread-A 입장
      • 저장한 데이터와 조회한 데이터가 다른 문제 발생
      • Thread-B가 “B” 라는 값을 저장하면, 직전에 Thread-A가 저장한 값 ”A”는 사라지기 때문
    • 여러 쓰레드가 동시에 같은 인스턴스의 필드 값을 변경하면서 발생하는 문제를 동시성 문제라고 함
    • 스프링빈 처럼 싱글톤 객체의 필드를 변경하며 사용할 때 동시성 문제 조심해야 함

image.png

동시성 문제 발생하는 곳

  • 여러 쓰레드가 같은 인스턴스의 필드에 접근해야 하기 때문에 트래픽이 많아질수록 자주 발생함

  • 지역 변수에서는 발생하지 않음

2. Thread Local을 통한 동시성 문제 해결

동시성 문제 해결 : Thread Local 사용

  • Thread Local은 해당 쓰레드만 접근할 수 있는 특별한 저장소

  • 쓰레드 로컬을 사용하면 각 쓰레드 마다 별도의 내부 저장소를 제공함

  • 같은 인스턴스의 쓰레드 로컬 필드에 접근해도 문제 없음

(1) Thread Local 동작 흐름

  • Thread-A가 “A” 값을 저장하면, 쓰레드 로컬은 Thread-A 전용 보관소에 데이터 보관함
  • Thread-B가 다른 값을 저장해도 Thread-A 저장소와 무관
  • 쓰레드 로컬을 통해 데이터 조회할 때도 thread-A가 조회하면 쓰레드 로컬은 Thread-A 전용 보관소에서 데이터를 반환함

image.png

(2) Thread Local 적용 로직

  • ThreadLocalLogTrace
    • 동시성 문제가 발생하는 FieldLogTrace 대신 ThreadLocalLogTrace 생성
    • ThreadLocalLogTrace는 필드 대신 쓰레드 로컬을 사용해서 데이터 동기화함
    • [기존] TraceId traceIdHolder 필드 사용 → [변경] ThreadLocal<TraceId> traceIdHolder 쓰레드 로컬 사용
@Slf4j
public class ThreadLocalLogTrace implements LogTrace {

		// 필드 대신 쓰레드 로컬 사용으로 변경
    //private TraceId traceIdHolder;
    private ThreadLocal<TraceId> traceIdHolder = new ThreadLocal<>();

    @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 = new TraceId();
            traceIdHolder.set(new TraceId());
        } else {
            // traceIdHolder = traceIdHolder.createNextId();
            traceIdHolder.set(traceId.createNextId());
        }
    }

    @Override
    public void end(TraceStatus status) {
        Long stopTimeMs = System.currentTimeMillis();
        long resultTimeMs = stopTimeMs - status.getStartTimeMs();
        TraceId traceId = status.getTraceId();
        log.info("[{}] {}{} time={}ms", traceId.getId(), addSpace(COMPLETE_PREFIX, traceId.getLevel()), status.getMessage(), resultTimeMs);
        releaseTraceId();
    }

    private void releaseTraceId() {
        TraceId traceId = traceIdHolder.get();
        if (traceId.isFirstLevel()) {
		        // traceIdHolder = null;
		        traceIdHolder.remove(); // 쓰레드 로컬에 해당 쓰레드가 저장한 데이터는 모두 삭제됨
        } else {
            traceIdHolder.set(traceId.createPreviousId());
        }
    }
}
@Configuration
public class LogTraceConfig {

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

(3) Thread Local 주의 사항

다 사용한 쓰레드 로컬의 값은 반드시 제거하기!

  • 발생 문제

  • 해결 방안

  • 문제 발생 예시
    • 사용자-A 저장 HTTP 요청
      • WAS는 쓰레드 풀에서 쓰레드 하나를 조회함
      • 여러 쓰레드 중 thread-A가 할당되었다고 하면, Thread-A는 사용자A의 데이터를 전용 보관소에 저장함
    • 사용자-A 저장 요청 종료
      • 사용자A의 HTTP 응답이 끝남
      • WAS는 사용이 끝난 thread-A를 쓰레드 풀에 반환함
      • 쓰레드 생성 비용은 비싸기 때문에 쓰레드 제거하지 않음 → 보통 쓰레드 풀을 통해 쓰레드를 재사용 함
      • 즉, 반환된 thread-A는 아직 쓰레드 풀에 살아있기 때문에 쓰레드 로컬의 thread-A 전용 보관소에 저장되어 있는 사용자A 데이터 도 함께 살아있게 됨
    • 사용자-B가 조회를 위해 새로운 HTTP 요청을 할 경우
      • WAS는 쓰레드 풀에서 쓰레드를 하나 조회 하는데, 만약 여러 쓰레드 중에서 thread-A가 할당된다면?
      • 조회 요청이므로 thread-A는 쓰레드 로컬에서 데이터 조회함 → thread-A 전용 보관소에 있는 사용자A의 데이터를 반환함
      • 결과적으로 사용자B는 사용자 A의 정보를 조회하게 됨

image.png