로그추적기 - 동시성 문제

실제 결과 :

 

 

기대한 결과 :

[nio-8080-exec-3] [52808e46] OrderController.request()
[nio-8080-exec-3] [52808e46] |-->OrderService.orderItem()
[nio-8080-exec-3] [52808e46] |    |-->OrderRepository.save()
[nio-8080-exec-4] [4568423c] OrderController.request()
[nio-8080-exec-4] [4568423c] |-->OrderService.orderItem()
[nio-8080-exec-4] [4568423c] |     |-->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
[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

 

 

원인 : 동시성 문제

FieldLogTrace를 싱글톤 스프링 빈으로 등록되었기 때문이다 

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

 

 

동시성 문제 예제 코드 - 동시성 문제 발생 x

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

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

        sleep(3000); // 메인 thread 종료 대기
        log.info("main exit");
    }

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

 

 

동시성 문제 예제 코드 - 동시성 문제 발생 0

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

        sleep(3000); // 메인 thread 종료 대기
        log.info("main exit");
    }

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

>> Thread-A 입장에서 저장한 데이터와 조회한 데이터가 다른 문제가 발생한다

* 동시성 문제는 지역 변수에는 발생하지 않는다 (지역 변수는 각각 다른 메모리 영역이 할당된다)

* 동시성 문제가 발생하는 곳은 인스턴스의 필드(주로 싱글톤) 또는 static 같은 공용 필드에 접근할 때 발생한다

* 동시성 문제는 값을 변경하기 때문에 발생한다

 

 

동시성 문제 해결 - ThreadLocal

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

 

 

LogTrace 수정

@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-";

    // traceId 동기화 > 동기화 이슈 발생
    // private TraceId traceIdHolder;
    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);
    }

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

• 변경 전 : private TraceId traceIdHolder;
  • 변경 후 : private ThreadLocal<traceId> traceHolder = new ThreadLocal<>();

동시성 문제가 해결되었다 

 

 

cf. threadLocal 주의사항

WAS처럼 스레드 풀을 사용하는 경우 쓰레드 로컬 값을 사용 후 제거하지 않으면 큰 문제가 발생할 수 있다

1. 사용자A 저장 요청 > 사용자A 저장 요청 종료 

- WAS는 사용이 끝난 thread-A를 스레드 풀에 반환한다 

- 스레드를 생성하는 비용은 비싸기 때문에 쓰레드를 제거하지 않고 보통 쓰레드 풀을 통해서 재사용한다

- 따라서 쓰레드 로컬의 thread-A 전용 보관소에 사용자A 데이터도 함께 살아있다

2. 사용자B 조회 요청

- 사용자B에게 thread-A가 할당되었다

- 사용자B가 데이터를 조회하면 스레드 로컬은 thread-A 전용 보관소에 있는 사용자A 데이터를 반환한다

- 사용자B는 사용자A의 정보를 조회하게 된다

 

 

 

 

 

---

이번에 결제 프로세스 개발 실무를 하면서 궁금했던 점이다 

당시에는 멀티 스레드, 쓰레드 개념 자체도 헷갈리고 동시성 문제가 발생 안 하나? 하는 정리되지 않은 생각에 질문을 했더니 명쾌한 답변을 받을 수 없었다

 

이번 기회로 다시 정리해 본다

 

상황 :

포스 결제 시스템 개발 중, spring boot mvc 패턴

각각 결제 수단마다 service가 따로 존재

service 클래스에서 상단에 변수를 지정해서 아래에 로직 사용하고 있음 (예를 들어 총금액, boolean 값 등)

사용자A가 결제수단 A를 이용해 결제를 진행 중에 있음

사용자 B도 결제수단 A를 이용해서 동시에 결제를 진행 중에 있음

그러면 사용자A와 사용자B 모두 같은 service에서 결제를 진행 중인 상황임

 

여기서 동시성 문제가 발생하지 않을까?라는 생각이 들었다

지금 생각해도 강의 중 나온 이 상황과 똑같은 상황이지 않을까 싶다

 

첫 번째 헷갈렸던 건 프로세스와 스레드

포스기 1개당 결제 1건만 가능한 상황이기 때문에 포스A에서 결제하는 건 프로세스A가 하나 생성되고 포스B에서 결제하는건 프로세스B가 생성되니 어차피 스레드가 겹칠 일이 없는 건가?

 

[프로세스]

• 편의점A에서 포스 프로그램을 실행하면 운영체제 위에 하나의 프로세스 생성
• 편의점B, 편의점C에서도 각각 독립적인 프로세스가 생성
• 편의점 A 프로세스 ↔ 편의점 B 프로세스 ↔ 편의점 C 프로세스
  • 서로 메모리/리소스를 전혀 공유하지 않고 완전히 분리된 실행 환경
  • 프로세스 간에는 직접적인 동시성 충돌이 일어나지 않는다

 

[프로세스/스레드]

• 하나의 포스 프로그램(프로세스) 안에서도 동시에 여러 작업을 처리
  • 스레드1 : 상품 바코드 스캔 처리
  • 스레드2 : 결제 승인  API 호출
  • 스레드3 : 재고 DB 업데이트
• 하나의 프로세스 안에서 여러 스레드가 실행되면 공유 메모리(heap)을 동시에 건드릴 수 있기 때문에 동시성 문제 발생

 

[동시성 문제가 생길 수 있는 경우?]

• 같은 편의점 안에서 하나의 프로세스가 여러 스레드를 돌리며 동시에 같은 데이터를 수정할 때
• 여러 편의점이 같은 서버/DB에 접근해 동시에 데이터 갱신할 때

 

 

두 번째로 만약 첫 번째 가정이 틀려서 서버 1개당 프로세스 1개가 생성되어 포스A와 포스B 결제 건이 각각 하나의 프로세스 안에서 두 개의 스레드가 생기는 거라면 동시성 문제가 발생하지 않는가? 였다

• 동일한 DB를 여러 매장에서 쓰면 동시성 이슈가 있을 수 있다
• Spring @Service 빈이 기본 singleton이라면 클래스 빌드에 결제 진행 중 동시성 문제가 발생할 수 있음
• 레이스 컨디션 

 

[Spring MVC 웹앱에서 요청 처리의 기본]

• HTTP 요청 1건 - Tomcat의 스레드 1개 처리
• @Controller @Service @Repository는 기본이 싱글톤 인스턴스 1개
• 싱글톤 빈의 인스턴스 필드는 모든 요청 스레드가 공유 
• 특정 결제 service안에 private int totalAmt 같은 상태를 두면 사용자A와 사용자B의 요청 스레드가 같은 필드를 동시에 읽고 쓰게 되어 값이 뒤섞인다 
• 같은 service를 사용한다 = 같은 인스턴스 필드를 공유
  • 서비스/컨트롤러에 비즈니스 상태를 절대 저장하지 않기
  • 진행 중인 값은 지역변수/파라미터/Dto로 가지고 다니기
  • 무상태(stateless)하게 설계해야 함

 

그렇다면 각 편의점 프로세스의 스레드들과 WAS의 스레드들이 어떻게 연결되고 스레드 풀과의 관계는 뭘까 ?

• WAS는 서버 쪽 프로세스
• 이 프로세스 안에는 스레드 풀이 있어서 들어오는 HTTP 요청을 스레드가 나눠서 처리 
• 편의점A -> 서버로 HTTP 요청 보냄
• 편의점B -> 서버로 HTTP 요청 보냄
  • 같은 서버 프로세스(WAS)로 들어옴
  • WAS 프로세스 안의 스레드 풀에서 서로 다른 스레드가 배정되어 요청을 동시에 처리
  • 공유되는 건 서버 인스턴스(WAS 인스턴스)의 메모리 공간
  • 그래서? service 싱글톤 빈 같은 객체가 여러 요청에 동시에 접근할 수 있음

 

클라이언트-서버의 구조를 크게 못 보고 지엽적으로 생각하려고 하니까 헷갈렸던 것 같다 

결론은 처음 생각했던 것과 마찬가지로 동시성 문제가 발생할 수 있는 거였고 왜 그렇게 설계하셨을까 궁금해지네  

 

 

마지막으로 어노테이션이 적용됐을 때 어떻게 싱글톤으로 만들어지는지 앞 쪽이 가물가물해서 정리해 봤다

• 스프링부트 시작 > 스프링 컨테이너 생성 > 컨테이너가 빈 팩토리 역할을 하면서 어노테이션을 스캔해서 객체 만들면서 관리
• @SpringBootApplication 안에 @ComponentScan이 포함되어 있어 패키지 루트를 보면서 어노테이션이 붙은 클래스를 자동 등록
• 스프링은 해당 클래스를 메타 정보로 저장 (클래스 이름, 생성자, 의존성 주입 방법 등)
• 특별한 지정을 하지 않는다면 빈 스코프는 싱클톤 (컨테이너 안에 인스턴스 하나만 생성해서 공유) > 자바의 싱글톤 패턴과는 다름
• application.yml 같은 설정 파일은 컨테이너가 만들어지기 전에 로드되면서 environment에 바인딩됨