7 분 소요

 인프런 스프링 핵심 원리 - 고급편을 학습하고 정리한 내용 입니다.

필드 동기화 - 개발

앞서 로그 추적기를 만들면서 다음 로그를 출력하기 위해서 트랜잭션ID, level을 동기화 하는 문제가 있었다.

그래서 모든 메서드에서 TraceId를 넘기도록 구현했다.

이런 문제를 해결할 목적으로 새로운 로그 추적기를 만들어 보자.

이제 프로토타입 버전이 아닌 정식 버전으로 제대로 개발해 보자.

향후 다양한 구현체로 변경할 수 있도록 LogTrace인터페이스를 먼저 만들고 구현해 보자.

LogTrace

다음과 같이 패키지 구성

1
2
3
4
5
6

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

LogTrace 인터페이스에는 로그 추적기를 위한 최소한의 기능인 begin(), end(), exception()을 정의했다.

이제 파라미터를 넘기지 않고 TraceId를 동기화 할 수 있는 FieldLogTrace구현체를 만들어 보자.

FieldLogTrace

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67

@Slf4j  
public class FiledLogTrace 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);  
    }  
  
    private void syncTraceId() {  
        if (traceIdHolder == null) {  
            traceIdHolder = new TraceId();  
        } else {  
            traceIdHolder = traceIdHolder.createNextId();  
        }  
    }  
  
    @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 releaseTraceId() {  
        if (traceIdHolder.isFirstLevel()) {  
            traceIdHolder = null; // 파괴  
        } 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();  
    }  
}

일단 기존에 구현했던 HelloTraceV1과 거의 유사하다.

TraceId를 동기화 하는 부분만 파라미터를 사용하는 것에서 TraceId traceIdHolder필드 변수를 사용하도록 변경 되었다.

이제 직전 로그의 TraceId는 파라미터로 전달되는 것이 아니라 FieldLogTrace의 필드인 traceIdHolder에 저장된다.

여기서 중요한 부분은 로그를 시작할 때 호출하는 syncTraceId()와 로그를 종료할 때 호출하는 releaseTraceId()이다.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15

private void syncTraceId() {  
	if (traceIdHolder == null) {  
		traceIdHolder = new TraceId();  
	} else {  
		traceIdHolder = traceIdHolder.createNextId();  
	}  
}

private void releaseTraceId() {  
	if (traceIdHolder.isFirstLevel()) {  
		traceIdHolder = null; // 파괴  
	} else {  
		traceIdHolder = traceIdHolder.createPreviousId(); // 레벨 감소  
	}  
}
  • syncTraceId()
    • TraceId를 새로 만들거나 앞선 로그의 TraceId를 참고해서 동기화하고, level도 증가한다.
    • 최초 호출이면 TraceId를 새로 만든다.
    • 결과를 traceIdHolder에 보관한다.
  • releaseTraceId()
    • 메서드를 추가로 호출할 때는 level이 하나 증가해야 하지만, 메서드 호출이 끝나면 level이 하나 감소 해야 한다.
    • 만약 최초 호출(level==0)이면 내부에서 관리하는 traceId 를 제거한다.

하지만 이 코드는 동시성 이슈가 따라올 수 밖에 없다..

일단 테스트 코드를 보자.

FieldLogTraceTest

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21

class FiledLogTraceTest {  
    FiledLogTrace trace = new FiledLogTrace();  
  
    @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("hello1");  
        TraceStatus status2 = trace.begin("hello2");  
  
        trace.exception(status2, new IllegalStateException());  
        trace.exception(status1, new IllegalStateException());  
    }  
}

다음과 같이 이제 traceId를 안 넘기고 동기화가 잘 되는지 보자.

트랜잭션ID와 level이 잘 표현 되었다.

필드 동기화 - 적용

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

LogTrace 스프링 빈 등록

FieldLogTrace를 수동으로 스프링 빈으로 등록하자. 수동으로 등록하면 향후 구현체를 편리하게 변경할 수 있다는 장점이 있다.

LogTraceConfig

1
2
3
4
5
6
7

@Configuration  
public class LogTraceConfig {  
    @Bean  
    public LogTrace logTrace() {  
        return new FiledLogTrace();  
    }  
}

이러면 싱글톤으로 FiledLogTrace를 등록한다.

V2 -> V3 복사 예제 적용

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23

@RestController  
@RequiredArgsConstructor  
public class OrderControllerV3 {  
  
    private final OrderServiceV3 orderService;  
    private final LogTrace trace;  
  
    @GetMapping("/v3/request")  
    public String request(@RequestParam("itemId") String itemId) {  
  
        TraceStatus status = null;  
        try {  
            status = trace.begin("OrderControllerV3.request()");  
            orderService.orderItem(itemId);  
            trace.end(status);  
            return "ok";  
  
        } catch (Exception e) {  
            trace.exception(status, e);  
            throw e;  
        }  
    }  
}
  • HelloTraceV2 → LogTrace로 변경.
  • trace.beginSync() → trace.begin()으로 변경
  • service나 repository에 traceId넘기는 부분 삭제.

실행

TraceId, level이 잘 표현 됐다.

필드 동기화 - 동시성 문제

잘 만든 로그 추적기를 실제 서비스에 배포했다 가정해 보자.

테스트 할 때는 문제가 없는 것처럼 보인다. 사실 방금 만든 FieldLogTrace는 심각한 동시성문제를 가지고 있다.

동시성 문제를 확인해 보려면 동시에 여러번 호출해 보면 된다.

로그가 막 섞여서 출력 된다.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15

[52808e46] 
[nio-8080-exec-3] [52808e46] OrderController.request() 
[nio-8080-exec-3] [52808e46] |-->OrderService.orderItem() 
[nio-8080-exec-3] [52808e46] | |-->OrderRepository.save() 
[nio-8080-exec-3] [52808e46] | |<--OrderRepository.save() time=1001ms 
[nio-8080-exec-3] [52808e46] |<--OrderService.orderItem() time=1001ms 
[nio-8080-exec-3] [52808e46] OrderController.request() time=1003ms 

[4568423c] 
[nio-8080-exec-4] [4568423c] OrderController.request() 
[nio-8080-exec-4] [4568423c] |-->OrderService.orderItem() 
[nio-8080-exec-4] [4568423c] | |-->OrderRepository.save() 
[nio-8080-exec-4] [4568423c] | |<--OrderRepository.save() time=1000ms 
[nio-8080-exec-4] [4568423c] |<--OrderService.orderItem() time=1001ms 
[nio-8080-exec-4] [4568423c] OrderController.request() time=1001ms

이런 식으로 로그가 나오길 원했을 것이다.

쓰레드로 구분해야 될 것 같다.

동시성 문제

FiledLogTrace는 싱글톤으로 등록된 스프링 빈이다.

이 객체의 인스턴스가 애플리케이션에 딱 1개만 존재한다는 뜻이다.

이렇게 하나만 있는 인스턴스의 FieldLogTrace.traceIdHolder필드를 여러 쓰레드가 동시에 접근하기 때문에 문제가 발생한다.

동시성 문제 - 예제 코드

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

테스트에서도 lombok을 사용하기 위해 다음 코드를 추가하자.

build.gradle

1
2
3
4
5
6
7

dependencies { 

	... 
	//테스트에서 lombok 사용 
	testCompileOnly 'org.projectlombok:lombok' 
	testAnnotationProcessor 'org.projectlombok:lombok' 
}

이제 예제 코드를 test에 만들 건데

다음과 같이 treadlocal 패키지를 만들고, 그 아래 code 패키지엔 테스트 할 코드 FieldService를 작성

그 밖에 다가 테스트 코드 FieldServiceTest를 만들었다.

FieldService

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22

@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(long millis) {  
        try {  
            Thread.sleep(millis);  
        } catch (InterruptedException e) {  
            e.printStackTrace();  
        }  
    }  
}

매우 단순한 로직 이다.

파라미터로 넘어온 name을 필드인 nameStore에 저장한다.

그리고 1초 간 쉰 다음 필드에 저장된 nameStore를 반환한다. (조회)

FieldServiceTest

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39

@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); // 메인 쓰레드 종료 대기 (junit에서는 그냥 절차대로 읽고 종료 시키기 때문에 좀 기다려 줘야 조회까지 가능)
        log.info("main exit");  
    }  
  
    private void sleep(long millis) {  
        try {  
            Thread.sleep(millis);  
        } catch (InterruptedException e) {  
            e.printStackTrace();  
        }  
    }  
}

Thread, Runnalbe은 Java에 기능이기 때문에 따로 알아 보자.
참고 1 : 망나니개발자님 - [Java] Thread와 Runnable에 대한 이해 및 사용법
참고 2 : 개발냥발님 - [Java] Runnable과 Thread의 차이

아무튼 쓰레드 2개를 만들고 실행해보자.

순서대로 실행

1
2
3
4

threadA.start();  
sleep(2000);  // 동시성 문제가 발생 안하는 코드  
//sleep(100); // 동시성 문제가 발생하는 코드 
threadB.start()

FieldService는 저장 -> 리턴 이 1초가 걸리기 때문에

지금 상황에선 threadA가 끝나고 나서 threadB가 실행 될 것이다.

보면 threadA가 실행 된 후에 threadB가 잘 실행 됐다.

그림으로 보면 다음과 같다.

아무런 겹치는 구간이 없는 것이다.

그럼 이제 동시성 문제를 일으켜 보자.

동시성 문제 발생 코드

1
2
3
4

threadA.start();  
//sleep(2000);  // 동시성 문제가 발생 안하는 코드  
sleep(100); // 동시성 문제가 발생하는 코드 
threadB.start()

저장은 큰 문제가 없다. 그런데 조회하는 부분에서 문제가 발생했다.

  • 먼저 thread-A가 userA 값을 nameStore에 저장한다.

  • 0.1초 이후 thread-B가 userB의 값을 nameStore에 보관한다. 기존에 nameStore에 보관되어 있던 userA값은 사라지고 userB 값이 저장된다.

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

동시성 문제

결과적으로 thread-A입장에서는 저장한 데이터와 조회한 데이터가 다른 문제가 발생한다.

이처럼 여러 쓰레드가 동시에 같은 인스턴스의 필드 값을 변경하면서 발생하는 문제를 동시성 문제라고 한다.

이런 동시성 문제는 여러 쓰레드가 같은 인스턴스의 필드에 접근해야 하기 때문에 트래픽이 적은 상황에서는 확률 상 잘 나타나지 않고, 트래픽이 점점 많아질 수록 자주 발생한다.

특히 스프링 빈처럼 싱글톤 객체의 필드를 변경하며 사용할 때 이러한 동시성 문제를 조심해야 한다.

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

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

다음 시간에 쓰레드 로컬에 대해 알아보자.

댓글남기기

참고