ThreadLocal

1. 필드 동기화
2. 동시성 문제 - 예제 코드
3. ThreadLocal
4. 쓰레드 로컬 동기화

1. 필드 동기화

1-1. 개발

• 저번 시간 프로토타입 로그 추적기가 아닌 정식 버전으로 만들어 보자.
• 향후 다양한 구현제로 변경할 수 있도록 LogTrace인터페이스를 먼저 만들고, 구현해보자.

LogTrace

package com.example.springadvanced.trace.logtrace;

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

FieldLogTrace(구현체)

package com.example.springadvanced.trace.logtrace;

import com.example.springadvanced.trace.TraceId;
import com.example.springadvanced.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; //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) {
        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();
    }
}

• TraceId를 동기화 하는 부분만 파라미터를 사용하는 것에서 TraceId traceIdHolder필드를 사용하도록 변경되었다.
• 이제 직전 로그의 TraceId는 파라미터로 전달되는 것이 아니라 FieldLogTrace의 필드인 traceIdHolder에 저장된다.

• syncTraceId()
  • TraceId를 새로 만들거나 앞선 로그의 TraceId를 참고해서 동기화하고, level도 증가한다.
  • 최초 호출이면 TraceId를 새로 만든다.
  • 직전 로그가 있으면 해당 로그의 TraceId를 참고해서 동기화하고, level도 하나 증가한다.
  • 결과를 traceIdHolder에 보관한다.
• releaseTraceId()
  • 메서드를 추가로 호출할 때는 level이 하나 증가해야 하지만, 메서드 호출이 끝나면 level이 하나 감소해야 한다.
  • releaseTraceId()는 level을 하나 감소한다.
  • 만약 최초 호출(level==0)이면 내부에서 관리하는 traceId를 제거한다.

FieldLogTraceTest

package com.example.springadvanced.trace.logtrace;

import com.example.springadvanced.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("hello2");
        trace.end(status2);
        trace.end(status1);
    }

    @Test
    void begin_exception_level2() {
        TraceStatus status1 = trace.begin("hello");
        TraceStatus status2 = trace.begin("hello2");
        trace.exception(status2, new IllegalStateException());
        trace.exception(status1, new IllegalStateException());
    }
}

• 실행 결과를 보면 트랜잭션ID 도 동일하게 나오고, level을 통한 깊이도 잘 표현된다
• FieldLogTrace.traceIdHolder필드를 사용해서 TraceId가 잘 동기화 되는 것을 확인할 수 있다.

1-2. 적용

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

스프링 빈으로 등록
LogTraceConfig

package com.example.springadvanced;

import com.example.springadvanced.trace.logtrace.FieldLogTrace;
import com.example.springadvanced.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();
    }
}

V3를 생성 했고 LogTrace인터페이스 사용하는 걸로 코드를 변경했다.
OrderControllerV3

package com.example.springadvanced.app.v3;

import com.example.springadvanced.trace.TraceStatus;
import com.example.springadvanced.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; //예외를 꼭 다시 던져주어야 한다.
        }
    }
}

애플리케이션 정상 실행

예외 실행

• traceIdHolder필드를 사용한 덕분에 파라미터 추가 없는 깔끔한 로그 추적기를 완성

어떤 문제가 남아 있을까?

1-3. 동시성 문제

• 사실 직전에 만든 FieldLogTrace 는 심각한 동시성 문제를 가지고 있다.
• 확인해 보려면 애플리케이션 실행(localhost:8080/v3/request?itemId=hello)을 연속으로 해보자.

• 동시에 여러 사용자가 요청하면 여러 쓰레드가 동시에 애플리케이션 로직을 호출하게 된다. 따라서 로그는 이렇게 섞여서 출력된다.
• 위에 로그를 자세히 보면 쓰레드가 다른데도 트랜잭션ID가 동일하고, level도 많이 꼬여서 나온다.

무엇이 문제일까?

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

2. 동시성 문제 - 예제 코드

테스트 예제 코드를 통해서 동시성 문제를 확인해보자

FieldService

package com.example.springadvanced.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();
        }
    }
}

FieldServiceTest

package com.example.springadvanced.trace.threadlocal;

import com.example.springadvanced.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(); //A실행
        sleep(2000); //동시성 문제 발생X
        //sleep(100); //동시성 문제 발생O

        threadB.start(); //B실행
        sleep(3000); //메인 쓰레드 종료 대기
        log.info("main exit");
    }

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

실행결과 sleep(2000)

실행 결과를 보면 문제가 없다.

• Thread-A는 userA를 nameStore에 저장했다.
• Thread-A는 userA를 nameStore에서 조회했다.
• Thread-B는 userB를 nameStore에 저장했다.
• Thread-B는 userB를 nameStore에서 조회했다.

실행결과 sleep(100)
thread-A의 작업이 끝나기 전에 thread-B가 실행

정리하면 다음과 같다.
1. Thread-A는 userA를 nameStore에 저장했다.
2. Thread-B는 userB를 nameStore에 저장했다.
3. Thread-A는 userB를 nameStore에서 조회했다.
4. Thread-B는 userB를 nameStore에서 조회했다.

• thread-A의 호출이 끝나면서 nameStore의 결과를 반환받는데, 이때 nameStore는 앞의 2번에서 userB의 값으로 대체되었다. 따라서 기대했던 userA의 값이 아니라 userB의 값이 반환된다.
• thread-B의 호출이 끝나면서 nameStore의 결과인 userB를 반환받는다.

결과적으로 Thread-A입장에서는 저장한 데이터와 조회한 데이터가 다른 문제가 발생한다. 이처럼 여러 쓰레드가 동시에 같은 인스턴스의 필드 값을 변경하면서 발생하는 문제를 동시성 문제라 한다. 이런 동시성 문제는 여러 쓰레드가 같은 인스턴스의 필드에 접근해야 하기 때문에 트래픽이 적은 상황에서는 확률상 잘 나타나지 않고, 트래픽이 점점 많아질 수 록 자주 발생한다.

• 이런 동시성 문제는 지역 변수에서는 발생하지 않는다. 지역 변수는 쓰레드마다 각각 다른 메모리 영역이 할당된다.
• 동시성 문제가 발생하는 곳은 같은 인스턴스의 필드(주로 싱글톤에서 자주 발생), 또는 static같은 공용 필드에 접근할 때 발생한다.

그렇다면 어떻게 해결해야 될까?
이럴 때 사용하는 것이 바로 쓰레드 로컬이다.

3. ThreadLocal

3-1. 소개

• 쓰레드 로컬은 해당 쓰레드만 접근할 수 있는 특별한 저장소를 말한다. 쉽게 이야기해서 물건 보관 창구를 떠올리면 된다.
• 사용자A, 사용자B 모두 창구 직원을 통해서 물건을 보관하고, 꺼내지만 창구 지원이 사용자에 따라 보관한 물건을 구분해주는 것이다.

쓰레드 로컬을 사용하면 각 쓰레드마다 별도의 내부 저장소를 제공한다. 따라서 같은 인스턴스의 쓰레드 로컬 필드에 접근해도 문제 없다.

3-2. 예제 코드

ThreadLocalService

package com.example.springadvanced.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();
        }
    }
}

• nameStore필드가 일반 String타입에서 ThreadLocal을 사용하도록 변경되었다.

해당 쓰레드가 쓰레드 로컬을 모두 사용하고 나면 ThreadLocal.remove()를 호출해서 쓰레드 로컬에 저장된 값을 제거해주어야 한다.

ThreadLocalServiceTest
FieldServiceTest과 거의 비슷하다.

실행결과 sleep(100)

• 쓰레드 로컬 덕분에 쓰레드 마다 각각 별도의 데이터 저장소를 가지게 되었다. 결과적으로 동시성 문제도 해결되었다.

4. 쓰레드 로컬 동기화

4-1. 개발

• FieldLogTrace에서 발생했던 동시성 문제를 ThreadLocal로 해결해보자
• TraceId traceIdHolder필드를 쓰레드 로컬을 사용하도록 ThreadLocal<TraceId> traceIdHolder로 변경하면 된다.

ThreadLocalLogTrace

package com.example.springadvanced.trace.logtrace;

import com.example.springadvanced.trace.TraceId;
import com.example.springadvanced.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로 변경되었다. 따라서 값을 저장할 때는 set(..)을 사용하고, 값을 조회할 때는 get()을 사용한다.
• 쓰레드 로컬을 모두 사용하고 나면 꼭 ThreadLocal.remove()를 호출해서 쓰레드 로컬에 저장된 값을 제거해주어야 한다.

ThreadLocalLogTraceTest

package com.example.springadvanced.trace.logtrace;

import com.example.springadvanced.trace.TraceStatus;
import lombok.extern.slf4j.Slf4j;
import org.junit.jupiter.api.Test;

@Slf4j
class ThreadLocalLogTraceTest {

    ThreadLocalLogTrace trace = new ThreadLocalLogTrace();

    @Test
    void begin_end_level2() {
        TraceStatus status1 = trace.begin("hello1");
        TraceStatus status2 = trace.begin("hello2");
        trace.end(status2);
        trace.end(status1);
    }
    
    @Test
    void begin_exception_level2() {
        TraceStatus status1 = trace.begin("hello");
        TraceStatus status2 = trace.begin("hello2");
        trace.exception(status2, new IllegalStateException());
        trace.exception(status1, new IllegalStateException());
    }
}

4-2. 적용

애플리케이션에 적용해보자.

LogTraceConfig - 수정

package com.example.springadvanced;

import com.example.springadvanced.trace.logtrace.LogTrace;
import com.example.springadvanced.trace.logtrace.ThreadLocalLogTrace;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;

@Configuration
public class LogTraceConfig {

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

동시성 문제 확인을 위해(localhost:8080/v3/request?itemId=hello)을 연속으로 해보자.

• 쓰레드 별로 트랜잭션ID와 level이 정상적으로 나오는 것을 확인 할 수 있다.

4-3. 주의사항

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

사용자A 저장 요청

1. 사용자A가 저장 HTTP를 요청했다.
2. WAS는 쓰레드 풀에서 쓰레드를 하나 조회한다.
3. 쓰레드 thread-A가 할당되었다.
4. thread-A는 사용자A 의 데이터를 쓰레드 로컬에 저장한다.
5. 쓰레드 로컬의 thread-A전용 보관소에 사용자A 데이터를 보관한다.

사용자A 저장 요청 종료

1. 사용자A의 HTTP 응답이 끝난다.
2. WAS는 사용이 끝난 thread-A를 쓰레드 풀에 반환한다. 쓰레드를 생성하는 비용은 비싸기 때문에 쓰레드를 제거하지 않고, 보통 쓰레드 풀을 통해서 쓰레드를 재사용한다.
3. thread-A는 쓰레드풀에 아직 살아있다. 따라서 쓰레드 로컬의 thread-A전용 보관소에 사용자A 데이터도 함께 살아있게 된다.

사용자B 조희 요청

1. 사용자B가 조회를 위한 새로운 HTTP 요청을 한다.
2. WAS는 쓰레드 풀에서 쓰레드를 하나 조회한다.
3. 쓰레드 thread-A가 할당되었다. (물론 다른 쓰레드가 할당될 수 도 있다.)
4. 이번에는 조회하는 요청이다. thread-A는 쓰레드 로컬에서 데이터를 조회한다.
5. 쓰레드 로컬은 thread-A전용 보관소에 있는 사용자A 값을 반환한다.
6. 결과적으로 사용자A 값이 반환된다.
7. 사용자B는 사용자A의 정보를 조회하게 된다.

이런 문제를 예방하려면 사용자A의 요청이 끝날 때 쓰레드 로컬의 값을 ThreadLocal.remove()를 통해서 꼭 제거해야 한다.

참고
김영한: 스프링 핵심 원리 - 고급편(인프런)
Github - https://github.com/b2b2004/Spring_ex