Post

Spring SSE와 @Transactional의 경쟁 조건 문제

Spring AOP와 트랜잭션 동기화로 트러블슈팅하기

Posted
By Yeonhu Lee
23 min read
Spring SSE와 @Transactional의 경쟁 조건 문제

Spring SSE와 트랜잭션 동기화: 트랜잭션 처리하기

실시간 기능을 위해 SSE(Server-Sent Events)를 도입했지만, 데이터가 간헐적으로만 갱신되는, 예측 불가능한 문제가 생겼다. @Transactional 어노테이션이 ACID를 보장해 줄 것이라 믿었지만 실제로는 데이터 정합성 문제가 나타났다. 아래는 Spring이 트랜잭션을 처리하는 방식, SSE와 트랜잭션에서 발생한 경쟁 조건(Race Condition), 그리고 Spring의 트랜잭션 동기화 메커니즘으로 문제를 해결한 과정을 다룬다.

문제: 간헐적으로 작동하는 실시간 투표 갱신

실시간 기능의 목표는 한 사용자가 투표 정보를 변경하면, SSE로 연결된 모든 참여자의 화면에 해당 내용이 실시간으로 반영되는 것이었다. 이를 위해 투표 갱신 서비스 메서드에 @Transactional을 적용했다.

이상적인 시나리오는 다음과 같았다.

  1. 트랜잭션 시작: 사용자가 투표를 갱신하면 @Transactional 메서드가 호출된다.
  2. 데이터베이스 저장: 모든 DB 변경사항이 하나의 트랜잭션으로 처리되어 안전하게 저장(Commit)된다.
  3. SSE 전송: 서버가 클라이언트들에게 “데이터가 변경되었다”는 SSE 메시지를 보낸다.
  4. 클라이언트 데이터 갱신: 클라이언트는 메시지를 받아 최신 데이터를 다시 요청(GET)하고, 데이터을 갱신한다.

하지만 실제 현상은 예상과 달랐다. 어떤 때는 즉시 갱신이 되었지만, 대다수의 경우 경우 사용자가 직접 새로고침을 해야만 변경사항이 보였다.

“무엇”이 문제인지 분석하기

이처럼 간헐적으로 발생하는 버그를 잡기 위해 가장 기본적인 기능부터 오작동한다고 가정해 하나씩 검증해 나갔다.

로컬에 클라이언트(프론트엔드) 환경을 설치해, 실제 클라이언트에서 문제를 재현하는 방식으로 원인을 분석했다.

가정 1: 불안정한 SSE 연결

가장 먼저 실시간 통신의 기반인 SSE 연결 자체를 의심했다. 네트워크 문제로 연결이 끊어지거나, 서버가 클라이언트를 놓쳐 메시지가 유실되는 상황을 가정했다.

  • 검증: 서버의 SSE 커넥션 관리 로그와 브라우저 개발자 도구를 통해 클라이언트의 연결 상태를 추적했다.
  • 결론: 연결은 올바르게 작동했다. 모든 클라이언트는 정상적으로 연결을 수립하고 안정적으로 유지하고 있었다.

가정 2: 서버 핵심 로직의 실패

다음으로 투표 갱신을 처리하는 서버의 핵심 로직 자체에 결함이 있을 가능성을 점검했다. 데이터가 DB에 저장되지 않았거나, 저장은 성공했지만 SSE 알림을 보내지 못하는 상황을 가정했다.

  • 검증
    1. DB 저장 확인: DB 쿼리 로깅 라이브러리(p6spy)를 통해 INSERT 쿼리가 예외 없이 모두 실행되었음을 확인했다.
    2. SSE 전송 확인: 서버 로그를 통해, 특정 대상에게 SSE 메시지가 성공적으로 발행(publish)되었음을 확인했다.
    3. 클라이언트 수신 확인: 클라이언트 로그를 통해, SSE 메시지를 수신한 이후 fetch API가 호출되는 것을 확인했다.
  • 결론: 모든 핵심 로직은 정상 작동했다. 데이터 저장, 알림 전송, 알림에 따른 클라이언트의 후속 요청까지 각 기능은 모두 의도대로 움직이고 있었다.

“언제” 문제인지 분석하기

SSE 연결, DB 저장, SSE 메시지 전송, 갱신 데이터 수신 등 시스템의 각 구성 요소는 올바르게 작동하고 있었다. 즉 “무엇(What)”이 아닌 “언제(When)”의 문제로 언제 이런 현상이 발생하는 지 확인해야 했다. 로그를 확인한 결과 “데이터 갱신이 완료되기 이전에 클라이언트는 ‘투표 변경’ SSE 메시지를 받고 갱신 전 데이터를 다시 GET 요청한다”는 결정적인 현상을 관찰했다.

이를 통해 문제 원인이 기능의 성공/실패 여부 때문이 아닌, 각 기능이 실행되는 순서와 타이밍의 문제, 즉 여러 작업이 아주 짧은 시간 안에 얽히면서 발생하는 경쟁 조건(Race Condition) 때문이라는 것을 깨달았다.

문제 사례 1: 경쟁 조건으로 인한 데이터 불일치

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

...

2025-09-23T15:01:14.529+09:00  INFO 11478 --- [nio-8080-exec-8] c.e.common.sse.application.SseSender     : [SSE][PUBLISH] room=0N1DG5SEV73HM event=vote-changed targets=4
2025-09-23T15:01:14.533+09:00  INFO 11478 --- [nio-8080-exec-2] com.estime.common.logging.ApiLogFilter   : [REQ] layer=filter | ip=192.168.0.10 | method=GET | uri=/api/v1/rooms/0N1DG5SEV73HM/statistics/date-time-slots | ua=Mozilla/5.0 (Windows NT 10.0; Win64; x64) ...
2025-09-23T15:01:14.533+09:00  INFO 11478 --- [nio-8080-exec-8] p6spy                                      : #1663912874533 | took 4ms | statement | connection 51| url: jdbc:h2:mem:testdb
    insert into vote (date_time_slot, participant_id) values ('2025-09-26T00:00:00.000+0900', 15);

2025-09-23T15:01:14.543+09:00  INFO 11478 --- [nio-8080-exec-2] p6spy                                      : #1663912874543 | took 2ms | statement | connection 52| url: jdbc:h2:mem:testdb
    select v1_0.date_time_slot, v1_0.participant_id from vote v1_0 where v1_0.participant_id in (14, 15);
    
2025-09-23T15:01:14.545+09:00  INFO 12490 --- [nio-8080-exec-8] c.e.c.logging.ControllerLoggingAspect    : [RES] layer=controller | method=RoomApplicationService.updateParticipantVotes | duration=21ms | result=Update success
2025-09-23T15:01:14.546+09:00  INFO 11478 --- [nio-8080-exec-2] p6spy                                      : #1663912874546 | took 0ms | commit | connection 52| url: jdbc:h2:mem:testdb
2025-09-23T15:01:14.547+09:00  INFO 11478 --- [nio-8080-exec-8] p6spy                                      : #1663912874547 | took 5ms | commit | connection 51| url: jdbc:h2:mem:testdb
2025-09-23T15:01:14.547+09:00  INFO 11478 --- [nio-8080-exec-2] c.e.c.logging.ControllerLoggingAspect    : [RES] layer=controller | method=RoomController.getDateTimeSlotStatisticBySession | duration=14ms | result=CustomApiResponse(code=200, success=true, message=null, data=DateTimeSlotStatisticResponse[participantCount=1, statistic=[DateTimeSlotVotesResponse[dateTimeSlot=2025-09-25T10:00, participantNames=[유저1){: style="width: 80%; display: block; margin: 0 auto;" }){: style="width: 80%; display: block; margin: 0 auto;" })

...

시간대별 분석

  • Writer: [nio-8080-exec-8]
  • Reader: [nio-8080-exec-2]
  • 시간대별 동작
    • .529 (Writer): [SSE][PUBLISH] ... event=vote-changed
      • 트랜잭션이 아직 끝나지 않아 ‘유저2’의 데이터 변경이 아직 DB에 커밋되지 않은 상태에서, 변경되었다는 SSE 메세지를 먼저 전송한다.
    • .533 (Reader): [REQ] ... method=GET ...
      • SSE 메시지를 수신한 클라이언트가 갱신된 데이터를 얻기 위해 GET 요청을 보낸다.
    • .533 (Writer): insert into vote ...
      • Reader의 GET 요청과 거의 동시에, Writer는 이제서야 갱신할 정보를 DB에 INSERT 한다. 이 작업은 아직 커밋되지 않은 트랜잭션 내에서 일어난다.
    • .543 (Reader): select ... from vote ...
      • Reader가 DB에서 데이터를 조회한다. 하지만 DB의 READ_COMMITED 격리 수준에 따라 Writer의 트랜잭션이 아직 커밋되지 않았기 때문에 Writer의 INSERT로 인한 변경 사항은 보이지 않는다.
    • .546 (Reader): commit
      • Reader는 결국 변경 전 데이터를 조회한 채로 자신의 읽기 트랜잭션을 먼저 커밋해 종료한다.
    • .547 (Writer): commit
      • Reader가 클라이언트에 응답하기 직전 Writer가 마침내 자신의 쓰기 트랜잭션을 커밋한다. 하지만 이미 Reader의 DB 조회가 끝난 상태다.
    • .547 (Reader): [RES] ... participantCount=1
      • Reader는 갱신 정보가 누락된, 변경 전 데이터를 클라이언트에게 최종 응답한다. 이로 인해 데이터 불일치가 발생한다.

실패 결과 분석

Reader의 데이터 조회(SELECT at .543)가 Writer의 트랜잭션 종료(COMMIT at .547)보다 단 4ms 먼저 실행되었다. DB는 READ_COMMITTED 격리 수준에 따라 는 커밋되지 않은 데이터를 다른 트랜잭션에게 보여주지 않도록 설계되었기 때문에 Reader는 당연히 변경 전의 데이터를 읽었던 것이다.

문제 사례 2: 경쟁 조건이지만 우연히 데이터 일치

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

...

2025-09-23T15:31:11.967+09:00  INFO 12490 --- [nio-8080-exec-2] c.e.r.a.service.RoomApplicationService   : [SSE][PUBLISH] room=0N1DPPCQWQ9TE event=vote-changed targets=4

2025-09-23T15:31:11.971+09:00  INFO 12490 --- [nio-8080-exec-2] p6spy                                      : #1663914671971 | took 3ms | statement | connection 45| url: jdbc:h2:mem:testdb
    insert into vote (date_time_slot, participant_id) values ('2025-09-25T01:00:00.000+0900', 5);

2025-09-23T15:31:11.985+09:00  INFO 12490 --- [nio-8080-exec-2] c.e.c.logging.ControllerLoggingAspect    : [RES] layer=controller | method=RoomApplicationService.updateParticipantVotes | duration=21ms | result=Update success

2025-09-23T15:31:11.986+09:00  INFO 12490 --- [nio-8080-exec-2] p6spy : #1663914671986 | took 1ms | commit | connection 45| url: jdbc:h2:mem:testdb

2025-09-23T15:31:11.992+09:00  INFO 12490 --- [nio-8080-exec-9] com.estime.common.logging.ApiLogFilter   : [REQ] layer=filter | ip=192.168.0.12 | method=GET | uri=/api/v1/rooms/0N1DPPCQWQ9TE/statistics/date-time-slots | ua=Mozilla/5.0 ...

2025-09-23T15:31:11.999+09:00  INFO 12490 --- [nio-8080-exec-9] p6spy                                      : #1663914671999 | took 1ms | statement | connection 48| url: jdbc:h2:mem:testdb
    select v1_0.date_time_slot, v1_0.participant_id from vote v1_0 join participant p1_0 on p1_0.id=v1_0.participant_id where p1_0.room_id=7;

2025-09-23T15:31:12.005+09:00  INFO 12490 --- [nio-8080-exec-9] c.e.c.logging.ControllerLoggingAspect    : [RES] layer=controller | method=RoomController.getDateTimeSlotStatisticBySession | duration=13ms | result=CustomApiResponse(code=200, success=true, message=null, data=DateTimeSlotStatisticResponse[participantCount=1, statistic=[DateTimeSlotVotesResponse[dateTimeSlot=2025-09-25T01:00, participantNames=[유저1){: style="width: 80%; display: block; margin: 0 auto;" }){: style="width: 80%; display: block; margin: 0 auto;" })

...

시간대별 분석

  • Writer: [nio-8080-exec-2]
  • Reader: [nio-8080-exec-9]
  • 시간대별 동작
    • .967 (Writer): [SSE][PUBLISH] ... event=vote-changed
      • DB 변경사항이 커밋되기 전에 데이터가 변경되었다는 SSE 메시지를 먼저 전송한다.
    • .971 (Writer): insert into vote ...
      • Writer는 갱신할 정보를 DB에 INSERT 한다. 이 작업은 아직 커밋되지 않은 트랜잭션 내에서 일어난다.
    • .986 (Writer): commit
      • Writer의 쓰기 트랜잭션이 커밋된다.
    • .992 (Reader): [REQ] ... method=GET ...
      • SSE 메시지를 수신한 클라이언트가 갱신된 데이터를 얻기 위해 GET 요청을 보낸다. Writer의 커밋 이후 6ms 뒤이다.
    • .999 (Reader): select ... from vote ...
      • Reader가 DB에서 데이터를 조회한다. 다행히 이 시점(.999)은 Writer의 커밋(.986)보다 13ms 늦었기 때문에, Writer의 INSERT로 인한 변경 사항을 볼 수 있다.
    • .005 (Reader): [RES] ... participantCount=1
      • Reader는 갱신 정보가 포함된, 변경 후 데이터를 클라이언트에게 정상적으로 최종 응답한다. 이로 인해 경쟁 조건지만 우연히 데이터 불일치가 발생하지 않는다.

성공 결과 분석

Reader의 SELECT(.999)가 Writer의 COMMIT(.986)보다 약 13ms 늦게 실행되었다. 아주 짧은 시간차를 두고 Writer의 커밋이 먼저 완료되어 Reader는 최신 데이터를 읽을 수 있었다. 하지만 이는 예측 불가능한 외부 요인에 따라 언제든 실패할 수 있는 ‘운’에 기댄 코드일 뿐 근본적으로 성공한 것이 아니었다.

트랜잭션을 걸었는데 왜 경쟁상태가 발생했을까?

왜 @Transactional 메서드 안의 SSE 메세지 전송이 트랜잭션 완료(커밋)된 후 이루어지지 않았을까? 이를 이해하려면 Spring이 트랜잭션을 어떻게 처리하는지, AOP 프록시, ThreadLocal, 그리고 TransactionSynchronizationManager를 통해 어떻게 동작하는지 알아야 한다.

Spring Transaction과 AOP

해결 사례: 경쟁 조건 방지로 데이터 일치

이후 로그를 통해 커밋 이후 데이터를 올바르게 GET 요청하는 방식으로 경쟁 조건 문제를 방지했음을 확인했다.

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

2025-09-23T16:35:34.113+09:00  INFO 13727 --- [nio-8080-exec-1] c.e.c.logging.ControllerLoggingAspect    : [REQ] layer=controller | method=RoomController.updateParticipantVotes | httpMethod=PUT | uri=/api/v1/rooms/0N1E65GRDZHA1/votes/participants | args=[0N1E65GRDZHA1, ParticipantVotesUpdateRequest[participantName=유저1, dateTimeSlots=[2025-09-25T01:00, 2025-09-25T00:30){: style="width: 80%; display: block; margin: 0 auto;" }]

2025-09-23T16:35:34.176+09:00  INFO 13727 --- [nio-8080-exec-1] p6spy                                      : #1663918534176 | took 3ms | statement | connection 16| url: jdbc:h2:mem:testdb
    insert into vote (date_time_slot, participant_id) values ('2025-09-25T00:30:00.000+0900', 3);

2025-09-23T16:35:34.181+09:00  INFO 13727 --- [nio-8080-exec-1] p6spy                                      : #1663918534181 | took 3ms | statement | connection 16| url: jdbc:h2:mem:testdb
    insert into vote (date_time_slot, participant_id) values ('2025-09-25T01:00:00.000+0900', 3);

2025-09-23T16:35:34.185+09:00  INFO 13727 --- [nio-8080-exec-1] p6spy                                      : #1663918534185 | took 2ms | commit | connection 16| url: jdbc:h2:mem:testdb

2025-09-23T16:35:34.187+09:00  INFO 13727 --- [nio-8080-exec-1] c.e.r.a.service.RoomApplicationService   : [SSE] Sent SSE [vote-changed] after commit. roomSession=0N1E65GRDZHA1

2025-09-23T16:35:34.194+09:00  INFO 13727 --- [nio-8080-exec-2] com.estime.common.logging.ApiLogFilter   : [REQ] layer=filter | ip=192.168.3.88 | method=GET | uri=/api/v1/rooms/0N1E65GRDZHA1/statistics/date-time-slots | ua=Mozilla/5.0 ...

2025-09-23T16:35:34.206+09:00  INFO 13727 --- [nio-8080-exec-2] p6spy                                      : #1663918534206 | took 1ms | statement | connection 17| url: jdbc:h2:mem:testdb
    select v1_0.date_time_slot, v1_0.participant_id from vote v1_0 where v1_0.participant_id in (3);

2025-09-23T16:35:34.214+09:00  INFO 13727 --- [nio-8080-exec-2] c.e.c.logging.ControllerLoggingAspect    : [RES] layer=controller | method=RoomController.getDateTimeSlotStatisticBySession | duration=20ms | result=CustomApiResponse(code=200, success=true, message=null, data=DateTimeSlotStatisticResponse[participantCount=1, statistic=[DateTimeSlotVotesResponse[dateTimeSlot=2025-09-25T00:30, participantNames=[유저1){: style="width: 80%; display: block; margin: 0 auto;" }, DateTimeSlotVotesResponse[dateTimeSlot=2025-09-25T01:00, participantNames=[유저1){: style="width: 80%; display: block; margin: 0 auto;" }){: style="width: 80%; display: block; margin: 0 auto;" })

시간대별 분석

  • Writer: [nio-8080-exec-1]
  • Reader: [nio-8080-exec-2]
  • 시간대별 동작
    • .176 (Writer): insert into vote ...
      • Writer는 갱신할 정보를 DB에 INSERT 한다. 이 작업은 아직 커밋되지 않은 트랜잭션 내에서 일어난다.
    • .185 (Writer): commit
      • Writer의 쓰기 트랜잭션이 커밋된다.
    • .187 (Writer): [SSE][PUBLISH] ... event=vote-changed
      • DB 변경사항이 커밋된 후, 데이터가 변경되었다는 SSE 이벤트를 먼저 발행한다.
    • .194 (Reader): [REQ] ... method=GET ...
      • SSE 메시지를 수신한 클라이언트가 갱신된 데이터를 얻기 위해 GET 요청을 보낸다.
    • .206 (Reader): select ... from vote ...
      • Reader가 DB에서 데이터를 조회한다. 이 시점에서 이미 커밋되었기 때문에 Writer의 INSERT로 인한 변경 사항을 볼 수 있다.
    • .214 (Reader): [RES] ... participantCount=1
      • Reader는 갱신 정보가 포함된, 변경 후 데이터를 클라이언트에게 정상적으로 최종 응답한다.

결론

선언적 프로그래밍과 AOP

Spring은 개발자가 비즈니스 로직에 집중하도록 기술적인 처리는 프레임워크에 위임하는 선언적 프로그래밍 모델을 지향한다. @Transactional 어노테이션이 바로 그 대표적인 예이다.

개발자는 단순히 메서드에 @Transactional을 붙여 “이 작업은 트랜잭션 내에서 실행되어야 한다”고 선언하기만 하면된다. 그러면 Spring의 AOP 기능이 동작한다. AOP는 애플리케이션의 핵심 비즈니스 로직(Core Concern)에서 트랜잭션, 로깅, 보안과 같은 횡단 관심사(Cross-cutting Concern)를 분리해낸다.

실행 시점에 Spring은 해당 객체 대신 AOP 프록시 객체를 생성한다. 이 프록시는 대상 메서드를 감싸서 호출 전후에 트랜잭션 시작, 커밋, 롤백과 같은 부가 기능을 비즈니스 로직 코드의 수정 없이 그대로 주입한다.

관심사의 분리(SoC)

이러한 프록시 기반 AOP 방식은 관심사의 분리(Separation of Concerns, SoC)라는 설계 원칙을 극대화한다.

  • 비즈니스 로직: 오직 자신의 책임인 ‘무엇을 할 것인가’에만 집중한다. (사용자를 등록한다, 주문을 처리한다)
  • 트랜잭션 처리: ‘어떻게 처리할 것인가’의 기술적인 부분은 전적으로 Spring 프레임워크가 담당한다.

만약 프록시가 없다면 개발자는 모든 비즈니스 로직 메서드마다 try-catch-finally 블록을 사용하여 트랜잭션 코드를 직접 작성해야 한다. 이는 코드 중복 발생시키고 비즈니스 로직을 오염시키며 유지보수를 어렵게 만든다. Spring은 AOP를 통해 이러한 문제를 해결하고 객체지향 설계의 순수성을 유지한다.

동기화 문제 및 해결

트랜잭션의 범위는 데이터베이스 커넥션에 한정된다. 따라서 트랜잭션의 생명주기와 외부 시스템 연동(메시지 발행, API 호출 등)의 생명주기를 동기화하는 것이 중요하다.

  • TransactionSynchronizationManager와 ThreadLocal은 이 동기화 문제를 해결하기 위한 기술적 구현체이다.
  • ThreadLocal: 웹 환경에서는 하나의 사용자 요청이 하나의 스레드에 의해 처리된다. ThreadLocal은 이 스레드 내에서 트랜잭션의 컨텍스트(Context)를 전파하는 역할을 한다. 즉 트랜잭션을 시작할 때 사용된 데이터베이스 커넥션을 ThreadLocal에 바인딩하여, 동일 스레드에서 실행되는 어떤 코드(서비스, 리포지토리 등)라도 동일한 커넥션에 접근할 수 있도록 보장한다. 이는 자원의 일관성과 격리 수준을 유지하는 데 필수적이다.
  • TransactionSynchronizationManager: 트랜잭션의 상태 변화에 따른 콜백(Callback)을 등록하고 실행하는 중앙 관리자이다. “트랜잭션이 성공적으로 커밋된 후에만 특정 로직을 실행하라”와 같은 정교한 제어가 가능하게 한다. 이를 통해 개발자는 데이터가 DB에 완전히 반영되었음을 보장받는 시점에 메시지를 발행하는 등, 데이터 정합성을 해치지 않는 안전한 코드를 작성할 수 있다.
Troubleshooting
sse transaction thread aop concurrency
This post is licensed under CC BY 4.0 by the author.