[ 김영한 스프링 핵심 원리 - 고급편 #2 ] 쓰레드 로컬 - ThreadLocal (1)

이번 섹션에서는 [쓰레드 로컬 - ThreadLocal]에 대해서 알아보자.

👉 목차는 다음과 같다.

1) 필드 동기화 - 개발
2) 필드 동기화 - 적용
3) 필드 동기화 - 동시성 문제
4) 동시성 문제 - 예제 코드
5) ThreadLocal - 소개
6) ThreadLocal - 예제 코드
7) 쓰레드 로컬 동기화 - 개발
8) 쓰레드 로컬 동기화 - 적용
9) 쓰레드 로컬 - 주의사항
10) 정리

이번 섹션은 1) ~ 4), 5) ~ 10) 로 나눠서 포스팅하고자 한다.

바로 하나씩 확인해보자.

---

1) 필드 동기화 - 개발

앞서 로그 추적기를 만들면서 다음 로그를 출력할 때 트랜잭션ID 와 level 을 동기화하는 문제가 있었다. 이 문제를 해결하기 위해 TraceId 를 파라미터로 넘기도록 구현했다.

이렇게 해서 동기화는 성공했지만, 로그를 출력하는 모든 메서드에 TraceId 파라미터를 추가해야 하는 문제가 발생했다. TraceId 를 파라미터로 넘기지 않고 이 문제를 해결할 수 있는 방법은 없을까?

이런 문제를 해결할 목적으로 새로운 로그 추적기를 만들어보자.
이제 프로토타입 버전이 아닌 정식 버전으로 제대로 개발해보자.
향후 다양한 구현제로 변경할 수 있도록, LogTrace 인터페이스를 먼저 만들고, 구현해보자.

• LogTrace 인터페이스 생성: src > main > java > hello > advanced > trace > logtrace 패키지를 생성하고, 내부에 LogTrace 인터페이스를 생성하자.
  
  • LogTrace 인터페이스에는 로그 추적기를 위한 최소한의 기능인 begin() , end() , exception() 를 정의했다.
  • 이제 파라미터를 넘기지 않고 TraceId 를 동기화 할 수 있는 FieldLogTrace 구현체를 만들어보자.

• FieldLogTrace 생성: src > main > java > hello > advanced > trace > logtrace 패키지 내부에 FieldLogTrace 클래스를 생성하자.
  

 

✔️ FieldLogTrace 클래스

• FieldLogTrace 는 기존에 만들었던 HelloTraceV2 와 거의 같은 기능을 한다.
• TraceId 를 동기화 하는 부분만 파라미터를 전달하는 방식에서 TraceId traceIdHolder 필드를 사용하도록 변경되었다.
• 이제 직전 로그의 TraceId 는 파라미터로 전달되는 것이 아니라 FieldLogTrace 의 필드인 traceIdHolder 에 저장된다.
• 여기서 중요한 부분은 로그를 시작할 때 호출하는 syncTraceId() 와 로그를 종료할 때 호출하는 releaseTraceId() 이다.
  • syncTraceId()
    • TraceId 를 새로 만들거나 또는 앞선 로그의 TraceId 를 참고해서 동기화하고, level 도 증가한다.
    • 최초 호출이면 TraceId 를 새로 만든다.
    • 직전 로그가 있으면 해당 로그의 TraceId 를 참고해서 동기화하고, level 도 하나 증가한다.
    • 결과를 traceIdHolder 에 보관한다.
  • releaseTraceId()
    • 메서드를 추가로 호출할 때는 level 이 하나 증가해야 하지만, 메서드 호출이 끝나면 level 이 하나 감소해야 한다.
    • releaseTraceId() 는 level 을 하나 감소한다.
    • 만약 최초 호출( level==0 )이면 내부에서 관리하는 traceId 를 제거한다.
  • 참고)
    

 

👉 테스트 코드를 통해서 실행해보자.

• FieldLogTraceTest 생성: test > java > hello > advanced > trace > logtrace 패키지 내부에 FieldLogTraceTest 클래스를 생성하자.
  

• 실행해보자 - begin_end_level2()
  

• 실행해보자 - begin_exception_level2()
  

• 실행 결과를 보면 트랜잭션ID 도 동일하게 나오고, level 을 통한 깊이도 잘 표현된다.
• FieldLogTrace.traceIdHolder 필드를 사용해서 TraceId 가 잘 동기화되는 것을 확인할 수 있다. 이제 불필요하게 TraceId 를 파라미터로 전달하지 않아도 되고, 애플리케이션의 메서드 파라미터도 변경하지 않아도 된다.

---

2) 필드 동기화 - 적용

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

1) LogTrace 스프링 빈 등록

• FieldLogTrace 를 수동으로 스프링 빈으로 등록하자. 수동으로 등록하면 향후 구현체를 편리하게 변경할 수 있다는 장점이 있다.
• LogTraceConfig 클래스 생성: src > main > java > hello > advanced > config 패키지 내부에 LogTraceConfig 클래스를 생성하자.
  

2) 기존 코드를 유지하기 위해서 hello.advanced.app.v3 패키지를 새로 만들고, 기존 hello.advanced.app.v2 코드를 복사하자.

• 참고)
  
  • 각 코드 내부 의존관계를 V3으로 변경하자.
  • OrderControllerV3 의 매핑 정보도 다음과 같이 변경하자. ( @GetMapping("/v3/request") )
  • HelloTraceV2 -> LogTrace 인터페이스 사용
  • TraceId traceId 파라미터를 모두 제거
  • beginSync() -> begin 으로 사용하도록 변경

• 실행해보자. ( 정상 실행 - http://localhost:8080/v3/request?itemId=hello )
  
  • 정상적으로 실행되는 것을 확인할 수 있다.

• 실행해보자. ( 예외 실행 - http://localhost:8080/v3/request?itemId=ex )
  
  • 정상적으로 실행되는 것을 확인할 수 있다.

traceIdHolder 필드를 사용한 덕분에 파라미터 추가 없는 깔끔한 로그 추적기를 완성했다.
이제 실제 서비스에 배포한다고 가정해보자.

---

3) 필드 동기화 - 동시성 문제

잘 만든 로그 추적기를 실제 서비스에 배포했다 가정해보자.
테스트 할 때는 문제가 없는 것 처럼 보였지만, 사실 FieldLogTrace 는 심각한 동시성 문제를 가지고 있다. 동시성 문제를 확인하려면 다음과 같이 동시에 여러번 호출해보면 된다.

동시성 문제 확인

• 1초 안에 2번 실행해보자. ( http://localhost:8080/v3/request?itemId=hello )
• 기대하는 결과
  
  • (참고) 참고로 동시에 여러 사용자가 요청하면 여러 쓰레드가 동시에 애플리케이션 로직을 호출하게 된다. 따라서 로그는 이렇게 섞여서 출력된다.
• 기대하는 결과 - 로그 분리해서 확인하기
  
  • 로그가 섞여서 출력되더라도 특정 트랜잭션ID로 구분해서 직접 분류해보면 이렇게 깔끔하게 분리된 것을 확인할 수 있다. 그런데 실제 결과는 기대한 것과 다르게 다음과 같이 출력된다.
• 실제 결과
  
  • 트랜잭션이 구분되지도 않고, 레벨이 표현되는 것도 뭔가 이상하다.
• 실제 결과 - 로그 분리해서 확인하기 (쓰레드로 구분)
  
  • 기대한 것과 전혀 다른 문제가 발생한다. 트랜잭션ID 도 동일하고, level 도 뭔가 많이 꼬인 것 같다.

 

🤔 분명히 테스트 코드로 작성할 때는 문제가 없었는데, 무엇이 문제일까?

✔️ 동시성 문제

• 사실 이 문제는 동시성 문제이다.
• FieldLogTrace 는 싱글톤으로 등록된 스프링 빈이다. 이 객체의 인스턴스가 애플리케이션에 딱 1개 존재한다는 뜻이다. 이렇게 하나만 있는 인스턴스의 FieldLogTrace.traceIdHolder 필드를 여러 쓰레드가 동시에 접근하기 때문에 문제가 발생한다.

---

4) 동시성 문제 - 예제 코드

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

• 먼저 테스트에서도 lombok을 사용하기 위해 다음 코드를 추가하자. ( build.gradle )
  • testCompileOnly 'org.projectlombok:lombok'
  • testAnnotationProcessor 'org.projectlombok:lombok'
  • 이렇게 해야 테스트 코드에서 @Slfj4 같은 애노테이션이 작동한다.
• FieldService 생성: test > java > hello > advanced > trace > threadlocal > code 패키지를 생성하고, 내부에 FieldService 클래스를 생성하자.
  
  • 매우 단순한 로직이다. 파라미터로 넘어온 name 을 필드인 nameStore 에 저장한다. 그리고 1초간 쉰 다음 필드에 저장된 nameStore 를 반환한다.
• FieldServiceTest 생성: test > java > hello > advanced > trace > threadlocal 패키지 내부에 FieldServiceTest 클래스를 생성하자.
  
  • 순서대로 실행
    • sleep(2000) 을 설정해서 thread-A 의 실행이 끝나고 나서 thread-B 가 실행되도록 해보자. 참고로 FieldService.logic() 메서드는 내부에 sleep(1000) 으로 1초의 지연이 있다. 따라서 1초 이후에 호출하면 순서대로 실행할 수 있다. 여기서는 넉넉하게 2초 (2000ms)를 설정했다.
    • 실행 결과
      
      • 실행해보면 문제가 없다.
      • thread-A 가 저장하고 조회한다. 그 다음 thread-B 가 저장하고 조회한다.
    • 그림으로 확인해보자.
      
      • 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 가 실행된다.
    • 실행 결과
      
      • 실행 결과를 보자. 저장하는 부분은 문제가 없다. 문제는 조회하는 부분에서 발생한다.
    • 그림으로 확인해보자.
      
      • 첫 번째 그림: 먼저 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 같은 공용 필드에 접근할 때 발생한다.

• 동시성 문제는 값을 읽기만 하면 발생하지 않는다. 어디선가 값을 변경하기 때문에 발생한다.

 

🤔 그렇다면 지금처럼 싱글톤 객체의 필드를 사용하면서 동시성 문제를 해결하려면 어떻게 해야할까? 다시 파라미터를 전달하는 방식으로 돌아가야 할까?

이럴 때 사용하는 것이 바로 쓰레드 로컬이다.

---

강의를 듣고 정리한 글입니다. 코드와 그림 등의 출처는 김영한 강사님께 있습니다.