내가 공부한것을 올리며, 중요한 단원은 저 자신도 곱씹어 볼겸 상세히 기록하고 얕은부분들은 가겹게 포스팅 하겠습니다.
1. 필드 동기화 - 개발
지난번 구현에서는 트랜잭션ID 와 level을 동기화하기 위해서 TraceId를 파라미터로 넘기도록 구현했었다.
이를 파라미터로 넘기지 않고 해결할 방법은 없을까?
향후 다양한 구현체를 만들기 위해 우선 LogTrace 인터페이스부터 만들자.
▶ LogTrace
public interface LogTrace {
TraceStatus begin(String message);
void end(TraceStatus status);
void exception(TraceStatus status, Exception exception);
}가장 최소한의 기능인 begin, end, exception만 구현하였다.
다음으로는 FieldLogTrace 구현체를 만들어보자
▶ FieldLogTrace
@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; // tracId 동기화, 동시성 발생 가능 지점
@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();
}
}FieldLogTrace는 지난번에 만든 HelloTraceV2와 거의 비슷하다.
다만 TraceId를 동기화할 때, 파라미터를 전달하던 방식에서 -> TraceId traceIdHolder 필드를 사용하도록 변경되었다.
이제 직전 로그의 TraceId는 파라미터로 전달되는 것이 아니라 FieldLogTrace의 필드인 traceIdHolder에 저장된다.
(예상이 되듯 동시성 문제가 거의 100%로 발생할 것이다, 이후에 수정해 보자!)
중요한 부분은 로그를 시작할 때 호출하는 syncTraceId()와 종료할 때 호출하는 releaseTraceId()이다.
메서드를 추가로 호출할 때는 level 이 하나 증가해야 하지만, 메서드 호출이 끝나면 level 이 하나 감소해야 한다.
1) syncTraceId() : level 이 증가
syncTraceId는 begin()이 호출되면 가장 먼저 실행된다.
private void syncTraceId() {
if(traceIdHolder == null) {
traceIdHolder = new TraceId();
} else {
traceIdHolder = traceIdHolder.createNextId();
}
}이때 traceHolder가 null이면 새롭게 TraceId를 할당해주고, 이미 값이 있다면, createNextId()를 호출해준다!
2) releaseTraceId() : level 이 감소
해당 메서드는 complete() 호출 시, 가장 마지막에 실행되는 메서드이다.
private void releaseTraceId() {
if(traceIdHolder.isFirstLevel()) {
traceIdHolder = null;
} else {
traceIdHolder = traceIdHolder.createPreviousId();
}
}traceIdHolder에 있는 TraceId가 만약 최초 호출( level==0 )이면 내부에서 관리하는 traceId를 제거한다.
실행결과를 확인해보자!
class FieldLogTraceTest {
FieldLogTrace trace = new FieldLogTrace();
@Test
public 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());
}
}실행 결과는 다음과 같다!
원하던 결과가 출력되는 것을 확인할 수 있다!
2. 필드 동기화 - 적용
직전에 만든 FieldLogTrace를 애플리케이션에 적용시켜보자!
우선 FieldLogTrace를 수동으로 Bean으로 등록시켜보자!
@Configuration
public class LogTraceConfig {
@Bean
public LogTrace logTrace() {
return new FieldLogTrace();
}
}싱글톤 빈으로 등록되었다!
이를 우리의 애플리케이션에 적용시켜보자!
▶ OrderControllerV3
@RestController
@RequiredArgsConstructor
public class OrderControllerV3 {
private final OrderServiceV3 orderService;
private final LogTrace trace;
@GetMapping("/v3/request")
public String request(@RequestParam 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;
}
}
}
▶ OrderServiceV3
@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
@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();
}
}
}
V2에서의 파라미터로 TraceId를 전달받던 부분이 전부 제거되었다!
실행결과는 다음과 같다.
http://localhost:8080/v3/request?itemId=hello
이번에는 예외를 발생시켜보자!
http://localhost:8080/v3/request?itemId=ex
원하던 결과가 나왔다!
불필요하게 TraceId를 파라미터로 전달하지 않아도 되고, 애플리케이션의 메서드 파라미터도 변경하지 않아도 된다.
하지만 우리의 코드는 동시성 문제가 발생할 위험이 있다! 이를 다음 단락에서 해결해보자!
3. 필드 동기화 - 동시성 문제
직전에 말했듯 심각한 동시성 문제가 도사리고 있다.
우리의 애플리케이션에게 1초에 2번 연속해서 request요청을 보내보자! 결과는 다음과 같다.
(ps. 새로고침은 cmd + r)
박스 친 부분의 exec-숫자에서 숫자로 Thread를 구별할 수 있다. Tomcat의 Thread Pool에 사전에 생성되어있던 Thread의 번호이다.
일단 Transaction ID가 구분이 안된다. 또한 level도 이상하다.
위 결과를 각 Thread 별로 분리하여 확인하면 다음과 같다.
첫 번째 request의 로그
[nio-8080-exec-4] [aaaaaaaa] OrderController.request()
[nio-8080-exec-4] [aaaaaaaa] |-->OrderService.orderItem()
[nio-8080-exec-4] [aaaaaaaa] | |-->OrderRepository.save()
[nio-8080-exec-4] [aaaaaaaa] | |<--OrderRepository.save() time=1001ms
[nio-8080-exec-4] [aaaaaaaa] |<--OrderService.orderItem() time=1002ms
[nio-8080-exec-4] [aaaaaaaa] OrderController.request() time=1002ms
두 번째 request의 로그
[nio-8080-exec-5] [aaaaaaaa] | | |-->OrderController.request()
[nio-8080-exec-5] [aaaaaaaa] | | | |-->OrderService.orderItem()
[nio-8080-exec-5] [aaaaaaaa] | | | | |-->OrderRepository.save()
[nio-8080-exec-5] [aaaaaaaa] | | | | |<--OrderRepository.save() time=1005ms
[nio-8080-exec-5] [aaaaaaaa] | | | |<--OrderService.orderItem() time=1005ms
[nio-8080-exec-5] [aaaaaaaa] | | |<--OrderController.request() time=1007ms분리된 결과를 보면 Thread 5번의 결과가 이상하다는 것을 알 수 있다.
우선 Level처리가 잘못되었다. 4번, 5번 Thread 모두 동일한 depth를 출력해줘야 정상이다.
하지만 동시성 문제로 인하여 공유자원을 사용해버렸기 때문에 이러한 문제가 발생하였다.
우리의 FieldLogTrace는 싱글톤으로 등록된 스프링 빈이다. 이 객체의 인스턴스가 애플리케이션에 딱 1개 존재한다는 뜻이다.
이렇게 하나만 있는 인스턴스의 FieldLogTrace.traceIdHolder 필드를 여러 스레드가 동시에 접근하기 때문에 문제가 발생한다.
4. 동시성 문제 - 예제 코드
우선 다음 예시 코드를 살펴보자!
▶ FieldService
@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();
}
}
}logic 메서드는 인자로 받은 name을 nameStore에 저장한 후, 1초간 sleep 한 후, 다시 nameStore의 값을 반환하게 된다.
실행할 로직을 표현한 테스트 코드는 다음과 같다.
@Slf4j
public class FieldServiceTest {
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); // 2초간 sleep하는 동안 A종료
threadB.start(); // B실행
sleep(3000); // 3초간 sleep하는 동안 B종료
log.info("main exit"); // 메인 종료
}
private void sleep(int millis) {
try {
Thread.sleep(millis);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}실행결과는 다음과 같다.
Thread-A 가 실행된 이후, Thread-B 가 실행되어 정상 종료되는 것 을 확인할 수 있다.
이를 그림으로 보면 다음과 같다.
1) Thread-A는 userA를 nameStore에 저장했다.
2) Thread-A는 userA를 nameStore에서 조회했다.
3) Thread-B는 userB를 nameStore에 저장했다.
4) Thread-B는 userB를 nameStore에서 조회했다.
이번에는 sleep(100)을 설정해서 thread-A의 작업이 끝나기 전에 thread-B 가 실행되도록 해보자.
동시성 문제가 발생하도록 하는 것이다.
다음과 같이 코드의 일부분을 변경하자! sleep(200)으로 변경하였다.
threadA.start(); // A실행
sleep(200); // 0.2초간 sleep하는 동안 A종료
threadB.start(); // A실행중인 상황에서 B실행
sleep(3000); // 3초간 sleep실행 결과는 다음과 같다.
Thread-A가 종료되지 않은 상황에서 B를 호출했기 때문에 B가 저장을 할 때 공통의 nameStroe에 userB를 저장하게 된다,
따라서 Thread-A, B 둘 다 모두 "userB"를 출력하게 되었다.
이를 그림으로 확인하면 다음과 같다.
1) 먼저 thread-A 가 userA 값을 nameStore nameStore에 저장한다.
2) 0.2초 이후에 thread-B 가 userB의 값을 nameStore에 보관한다.
기존에 nameStore에 보관되어 있던 userA 값은 userB로 덮어져 버린다.
3) thread-A 의 호출이 끝나면서 nameStore nameStore의 결과를 반환받는데, userA의 값이 아니라 userB의 값이 반환된다.
4) thread-B의 호출이 끝나면서 nameStore의 결과인 userB를 반환받는다.
▶ 동시성 문제
Thread-A 입장에서는 저장한 데이터와 조회한 데이터가 다른 문제가 발생한다.
이처럼 여러 Thread가 동시에 같은 자원의 값을 변경하면서 발생하는 문제를 동시성 문제라 한다.
이런 동시성 문제는 여러 스레드가 같은 인스턴스의 필드에 접근해야 하기 때문에 트래픽이 적은 상황에서는 확률상 잘 나타나지 않고, 트래픽이 점점 많아질 수 록 자주 발생한다.
특히 스프링 빈처럼 싱글톤 객체의 필드를 변경하며 사용할 때 이러한 동시성 문제를 조심해야 한다.
이러한 동시성 문제를 Spring에서 어떠한 방식으로 해결할까?
Thread Local
'BackEnd > Spring' 카테고리의 다른 글
| [Spring] 템플릿 메서드 패턴 (0) | 2022.08.06 |
|---|---|
| [Spring] 쓰레드 로컬 - ThreadLocal - 2 (0) | 2022.08.05 |
| [Spring] 예제 만들기 (0) | 2022.08.03 |
| [Spring] 스프링의 3대 요소 (IoC/DI, PSA, AOP) (7) | 2022.07.22 |
| [Spring] Spring 환경변수 설정파일 선택하기 (2) | 2022.06.12 |
댓글