제육's 휘발성 코딩
article thumbnail
Published 2022. 6. 15. 20:38
[Advanced] 스프링 - 쓰레드 로컬 🔷 Spring/Advanced
반응형

쓰레드 로컬

이전 포스팅에서 로그 추적기에서 트랜잭션 ID 동기화를 위해 TraceId 를 파라미터로 넘기도록 구현했었다. 동기화는 정상 동작했지만, 모든 메서드에 파라미터를 추가해야하는 문제가 발생했다. 이번엔 프로토타입이 아닌 정식 버전으로 개발해보자.

LogTrace

package hello.advanced.trace.logtrace;

import hello.advanced.trace.TraceStatus;

public interface LogTrace {

  TraceStatus begin(String message);

  void end(TraceStatus status);

  void exception(TraceStatus status, Exception e);
}
  • 다양한 구현체로 변경할 수 있도록 인터페이스를 만들자.

 

FieldLogTrace

package hello.advanced.trace.logtrace;

import hello.advanced.trace.TraceId;
import hello.advanced.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-";

  private TraceId traceIdHolder;

  @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) {
    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 syncTraceId() {
    if (traceIdHolder == null) {
      traceIdHolder = new TraceId();
    } else {
      traceIdHolder = traceIdHolder.createNextId();
    }
  }

  private void releaseTraceId() {
    if (traceIdHolder.isFirstLevel()) {
      traceIdHolder = null; //destroy
    } else {
      traceIdHolder = 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();
  }
}
  • syncTraceId() : TraceId를 새로 만들거나, 앞선 로그를 통해 level 증가
  • releaseTraceId() : 메소드 호출이 끝나면 level 감소

FieldLogTraceTest

package hello.advanced.trace.logtrace;

import hello.advanced.trace.TraceStatus;
import org.junit.jupiter.api.Test;

class FieldLogTraceTest {

  FieldLogTrace trace = new FieldLogTrace();

  @Test
  void begin_end_level2() {
    TraceStatus status1 = trace.begin("hello1");
    TraceStatus status2 = trace.begin("hello1");
    trace.end(status2);
    trace.end(status1);
  }

  @Test
  void begin_exception_level2() {
    TraceStatus status1 = trace.begin("hello1");
    TraceStatus status2 = trace.begin("hello1");
    trace.exception(status2, new IllegalStateException());
    trace.exception(status1, new IllegalStateException());
  }
}
  • 트랜잭션 ID와 level의 깊이가 잘 표현되는 것을 볼 수 있다.

 

필드 동기화 - 적용

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
public class LogTraceConfig {

  @Bean
  public LogTrace logTrace() {
    return new FieldLogTrace();
  }
}
  • LogTraceConfig를 생성하여 수동 빈 등록을 하자. 이 때 빈 등록을 하는 이유는 컴포넌트 스캔의 대상이 되어서 싱글톤으로 관리하기 위해서 사용한다.

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
@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;
    }
  }
}
  • 기존에 beginSync를 통해 traceId를 파라미터로 전달한 부분을 없애주자. 서비스와 레포지토리도 동일한 방식으로 변경하자.

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

 

OrderRepositoryV3

package hello.advanced.app.v3;

import hello.advanced.trace.TraceId;
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 IllegalStateException("예외 발생!");
      }
      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();
    }
  }
}

 

image

  • 다음과 같이 정상 응답, 예외 응답 모두 로그 추적기가 정상 출력된다. 하지만 동시성 문제가 발생할 수 있다.

image

  • 다음과 같이 동시성 문제가 발생한다. FieldLogTrace는 싱글톤으로 등록된 스프링 빈이다. 이 객체가 애플리케이션에 1개만 존재하는 데 여러 쓰레드가 동시에 접근하기 때문에 다음과 같이 문제가 발생한다.

 

동시성 문제 - 예시 코드

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

build.gradle

testCompileOnly 'org.projectlombok:lombok' 
testAnnotationProcessor 'org.projectlombok:lombok'
  • 다음과 같이 테스트에서도 롬복을 사용하기위한 설정을 dependencies에 넣어주자.

FieldService (src/test)

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초 쉰 다음 반환하는 로직이다.

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();
    sleep(2000);
    // sleep(100); 동시성 문제 발생
    threadB.start();

    sleep(3000);
    log.info("main exit");
  }

  private void sleep(int millis) {
    try {
      Thread.sleep(millis);
    } catch (InterruptedException e) {
      e.printStackTrace();
    }
  }
}
  • 쓰레드 sleep을 설정하여 동시성 문제를 확인해보자.

image

  • 다음과 같이 ThreadA의 값이 로직에서 1000ms를 쉬고 있을 때 ThreadB가 접근해버리면 ThreadA의 name 값이 ThreadB로 저장이 되버린다.

참고

동시성 문제는 지역 변수에서는 발생하지 않는다. 그 이유는 지역 변수는 각 쓰레드 마다 고유의 영역에 할당되기 때문이다. 동시성 문제가 발생하는 곳은 같은 인스턴스 필드 (주로 싱글톤), 또는 static 같은 공용 필드에 접근할 때 발생한다. 운영체제에서 임계영역이라고 불리는 곳을 떠올리면 된다.

 

ThreadLocal - 소개

image

  • 쓰레드 로컬은 각 쓰레드별 별도의 보관소에서 값을 보관하고 반환해준다. 자바는 쓰레드 로컬을 지원하기 위한 java.lang.ThreadLocal 클래스를 제공한다.

 

ThreadLocal - 예제 코드

ThreadLocalService

package hello.advanced.trace.threadlocal.code;

import lombok.extern.slf4j.Slf4j;

@Slf4j
public class ThreadLocalService {

  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();
    }
  }
}
  • FieldService 와 같은 코드인데 String 타입에서 ThreadLocal로 변경하며 set, get, remove 등을 사용해서 값을 가져오거나 반환한다. 참고로 쓰레드 로컬을 모두 사용하고 나면 remove를 호출해서 저장된 값을 반드시 제거해줘야 한다.

ThreadLocalServiceTest

@Slf4j
public class ThreadLocalServiceTest {

  private ThreadLocalService service = new ThreadLocalService();

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

    Runnable userB = () -> {
      service.logic("userB");
    };

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

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

    threadA.start();
    sleep(100);

    threadB.start();
    sleep(3000);
    log.info("main exit");
  }

  private void sleep(int millis) {
    try {
      Thread.sleep(millis);
    } catch (InterruptedException e) {
      e.printStackTrace();
    }
  }
}
  • 쓰레드 로컬을 사용하니 동시성 문제가 해결되는 것을 볼 수 있다.

 

쓰레드 로컬 동기화 - 개발

FieldLogTrace 에서 발생했던 동시성 문제를 ThreadLocal로 해결해보자.

ThreadLocalLogTrace

package hello.advanced.trace.logtrace;

import hello.advanced.trace.TraceId;
import hello.advanced.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<>();

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

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

  private void releaseTraceId() {
    TraceId traceId = traceIdHolder.get();
    if (traceId.isFirstLevel()) {
      traceIdHolder.remove();//destroy
    } else {
      traceIdHolder.set(traceId.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();
  }
}
  • traceIdHolder를 ThreadLocal로 변경한 코드이다. complete() 부분을 보면 기존에는 0레벨이면 null을 넣었지만 remove를 넣어서 쓰레드 로컬에 저장된 값을 제거해주어야 한다.

 

쓰레드 로컬 동기화 - 적용

LogTraceConfig

@Bean
public LogTrace logTrace() {
  //        return new FieldLogTrace();
  return new ThreadLocalLogTrace();
}
  • 동시성 문제를 해결한 ThreadLocalLogTrace 를 스프링 빈으로 수동 등록하자.

image

  • 각각의 쓰레드 별로 로그가 정확하게 나누어 진 것을 확인할 수 있다.

 

쓰레드 로컬 - 주의 사항

쓰레드 로컬의 값을 사용 후 제거하지 않고 두면 WAS처럼 쓰레드 풀을 사용하는 경우에 심각한 문제가 발생할 수 있다.

사용자A 저장 요청

image

  • 사용자A가 저장 요청 -> WAS는 쓰레드 풀에서 쓰레드 하나 조회 -> Thread-A 할당
  • ThreadA는 사용자A의 데이터를 쓰레드 로컬에 저장 -> 쓰레드 로컬은 thread-A 전용 보관소에 데이터 보관

사용자A 저장 요청 종료

image

  • 사용자A의 HTTP 응답 종료 -> WAS는 Thread-A를 쓰레드 풀에 반환 (재사용)
  • Thread-A의 전용 보관소가 남아있는 상황이 된다.

사용자B 조회 요청

image

  • 사용자B의 새로운 요청에서 ThreadA를 할당 받는 경우 사용자B는 사용자A의 정보를 조회하게 된다. 즉, 다음과 같은 장애를 방지하기 위해 ThreadLocal.remove()를 통해서 꼭 제거해야 한다.

REFERENCES

https://www.inflearn.com/course/%EC%8A%A4%ED%94%84%EB%A7%81-%ED%95%B5%EC%8B%AC-%EC%9B%90%EB%A6%AC-%EA%B3%A0%EA%B8%89%ED%8E%B8

반응형
저작자표시
profile

제육's 휘발성 코딩

@sasca37

포스팅이 좋았다면 "좋아요❤️" 또는 "구독👍🏻" 해주세요! 맞구독은 언제나 환영입니다^^

검색 태그

자바
JPA
이펙티브자바
프로그래머스
jpql
javascript
스프링
자료구조
자바스크립트
AOP

티스토리툴바