방 참여 API 이슈 확인 및 트러블 슈팅 [1] - 문제 확인 및 원인 정리

Tech Stack

spring boot 3.5, JPA, MySQL 9.3.0, Repeatable Read 트랜잭션 격리 정책

부하테스트 실행 결과

seongjunnoh@seongjunnohui-noteubug loadtest % k6 run room_join_load_test.js

         /\\      Grafana   /‾‾/                                                                                                                                                                                
    /\\  /  \\     |\\  __   /  /                                                                                                                                                                                 
   /  \\/    \\    | |/ /  /   ‾‾\\                                                                                                                                                                               
  /          \\   |   (  |  (‾)  |                                                                                                                                                                              
 / __________ \\  |_|\\_\\  \\_____/ 

     execution: local
        script: room_join_load_test.js
        output: -

     scenarios: (100.00%) 1 scenario, 500 max VUs, 10m5s max duration (incl. graceful stop):
              * join_once_burst: 1 iterations for each of 500 VUs (maxDuration: 10m0s, gracefulStop: 5s)

  █ THRESHOLDS 

    **rooms_join_5xx
    ✗ 'count==0' count=120

    rooms_join_latency
    ✗ 'p(95)<1000' p(95)=34517.5511**

  █ TOTAL RESULTS 

    checks_total.......................: 1000   23.435273/s
    checks_succeeded...................: 88.00% 880 out of 1000
    checks_failed......................: 12.00% 120 out of 1000

    ✓ join responded
    ✗ join 200 or expected 4xx
      ↳  76% — ✓ 380 / ✗ 120

    CUSTOM
    fail_ROOM_MEMBER_COUNT_EXCEEDED.........................................: 364    8.530439/s
    rooms_join_2xx..........................................................: 16     0.374964/s
    rooms_join_4xx..........................................................: 364    8.530439/s
    rooms_join_5xx..........................................................: 120    2.812233/s
    rooms_join_latency......................................................: avg=27936.991638 min=10569.233 med=29669.9935 max=34718.465 p(90)=33880.2578 p(95)=34517.5511

    HTTP
    http_req_duration.......................................................: avg=13.97s       min=1.28ms    med=5.46s      max=34.71s    p(90)=33.27s     p(95)=33.87s    
      { expected_response:true }............................................: avg=617.51ms     min=1.28ms    med=5.52ms     max=27.21s    p(90)=76.61ms    p(95)=229.53ms  
    http_req_failed.........................................................: 48.40% 484 out of 1000
    http_reqs...............................................................: 1000   23.435273/s

    EXECUTION
    iteration_duration......................................................: avg=33.11s       min=15.63s    med=34.81s     max=40.18s    p(90)=39.06s     p(95)=39.57s    
    iterations..............................................................: 500    11.717636/s
    vus.....................................................................: 49     min=0           max=500
    vus_max.................................................................: 500    min=500         max=500

    NETWORK
    data_received...........................................................: 525 kB 12 kB/s
    data_sent...............................................................: 220 kB 5.2 kB/s

running (00m42.7s), 000/500 VUs, 500 complete and 0 interrupted iterations
join_once_burst ✓ [======================================] 500 VUs  00m40.2s/10m0s  500/500 iters, 1 per VU
ERRO[0043] thresholds on metrics 'rooms_join_5xx, rooms_join_latency' have been crossed

콘솔 500 에러 로그 일부

시나리오 : ‘per-vu-iterations’ 으로 500 명의 유저가 VU와 1대1 매칭되어 거의 동시에 ‘방 참여 api’ 를 호출 (방 모집인원 10명 제한, HOST 1명만 방 멤버로 존재하는 상황)
5xx 에러 0건을 목표로 하였으나, 120건 발생
- 서버가 500건 요청 중 120건을 정상처리 하지 못한 상황
- 200 OK : 16건 → 방 참여 OK 응답을 받은 사람이 16명 (DB에 room_participants 레코드 개수도 HOST 제외 16개)
- 400 Error : 364건 → 모두 fail_ROOM_MEMBER_COUNT_EXCEEDED 상황
p(95) < 1000 을 목표로 하였으나, 현재 p(95) 는 34초 수준
- p(95) < 1000 : ‘전체 요청 중 95%가 1초 이내에 완료되어야 한다’ 라는 의미

⇒ 우선 5xx error 발생 원인을 찾아서 이를 해결해야한다

⇒ 로그를 보았을때 deadlock 발생으로 인해 5xx error가 발생한 듯 하다

<aside> 💡

[Deadlock found when trying to get lock; try restarting transaction] [update rooms set book_id=?,category=?,description=?,end_date=?,is_public=?,member_count=?,modified_at=?,password=?,recruit_count=?,room_percentage=?,room_status=?,start_date=?,status=?,title=? where room_id=?]; SQL [update rooms set book_id=?,category=?,description=?,end_date=?,is_public=?,member_count=?,modified_at=?,password=?,recruit_count=?,room_percentage=?,room_status=?,start_date=?,status=?,title=? where room_id=?]

</aside>

부하테스트 과정에서 발견된 데드락 상황의 원인 정리

실제 부하테스트 결과로 발생한 mysql 서버의 error log 를 확인해보면 아래와 같다

아래와 같이 사전에 error log 에 데드락 관련 로그들이 print 되도록 설정하였음

SET PERSIST innodb_print_all_deadlocks = ON;
SET PERSIST innodb_status_output = ON;
SET PERSIST innodb_status_output_locks = ON;

SET PERSIST log_error_verbosity = 3;

‘tail -f [로컬 mysql 서버에서의 error log 파일 경로]’ 명령어를 통해서 확인한 로그 전문

------------------------
LATEST DETECTED DEADLOCK
------------------------
2025-10-28 17:15:56 0x16c4cf000
*** (1) TRANSACTION:
TRANSACTION 9481465, ACTIVE 1 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 9 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 2
MySQL thread id 229, OS thread handle 6130446336, query id 21616 localhost 127.0.0.1 root updating
update rooms set book_id=1,category='LITERATURE',description='인기 작가 김희용의 독서 모임방입니다.',end_date='2025-11-21',is_public=1,member_count=10,modified_at='2025-10-28 17:15:55.783038',password=null,recruit_count=10,room_percentage=0.0,room_status='RECRUITING',start_date='2025-11-10',status='ACTIVE',title='김희용의 문학 모임' where room_id=12345

*** (1) HOLDS THE LOCK(S):  // -> T1이 PRIMARY 인덱스의 특정 레코드(room_id=12345 레코드) 에 s-lock hold 중
RECORD LOCKS space id 4932 page no 4 n bits 72 index PRIMARY of table `thip`.`rooms` trx id 9481465 lock mode S locks rec but not gap
Record lock, heap no 5 PHYSICAL RECORD: n_fields 18; compact format; info bits 64
 0: len 8; hex 8000000000003039; asc       09;;
 1: len 6; hex 00000090acee; asc       ;;
 2: len 7; hex 02000002290da7; asc     )  ;;
 3: len 8; hex 99b7ed7e47000000; asc    ~G   ;;
 4: len 8; hex 99b7f913f70605c5; asc         ;;
 5: len 1; hex 01; asc  ;;
 6: len 1; hex 03; asc  ;;
 7: len 30; hex ec9db8eab8b020ec9e91eab08020eab980ed9dacec9aa9ec9d9820eb8f85; asc                               ; (total 53 bytes);
 8: len 3; hex 8fd375; asc   u;;
 9: len 1; hex 01; asc  ;;
 10: len 4; hex 8000000a; asc     ;;
 11: SQL NULL;
 12: len 4; hex 8000000a; asc     ;;
 13: len 8; hex 0000000000000000; asc         ;;
 14: len 3; hex 8fd36a; asc   j;;
 15: len 26; hex eab980ed9dacec9aa9ec9d9820ebacb8ed959920ebaaa8ec9e84; asc                           ;;
 16: len 8; hex 8000000000000001; asc         ;;
 17: len 10; hex 52454352554954494e47; asc RECRUITING;;

*** (1) WAITING FOR THIS LOCK TO BE GRANTED:  // -> T1이 같은 레코드에 대해 x-lock 획득 대기 중
RECORD LOCKS space id 4932 page no 4 n bits 72 index PRIMARY of table `thip`.`rooms` trx id 9481465 lock_mode X locks rec but not gap waiting
Record lock, heap no 5 PHYSICAL RECORD: n_fields 18; compact format; info bits 64
 0: len 8; hex 8000000000003039; asc       09;;
 1: len 6; hex 00000090acee; asc       ;;
 2: len 7; hex 02000002290da7; asc     )  ;;
 3: len 8; hex 99b7ed7e47000000; asc    ~G   ;;
 4: len 8; hex 99b7f913f70605c5; asc         ;;
 5: len 1; hex 01; asc  ;;
 6: len 1; hex 03; asc  ;;
 7: len 30; hex ec9db8eab8b020ec9e91eab08020eab980ed9dacec9aa9ec9d9820eb8f85; asc                               ; (total 53 bytes);
 8: len 3; hex 8fd375; asc   u;;
 9: len 1; hex 01; asc  ;;
 10: len 4; hex 8000000a; asc     ;;
 11: SQL NULL;
 12: len 4; hex 8000000a; asc     ;;
 13: len 8; hex 0000000000000000; asc         ;;
 14: len 3; hex 8fd36a; asc   j;;
 15: len 26; hex eab980ed9dacec9aa9ec9d9820ebacb8ed959920ebaaa8ec9e84; asc                           ;;
 16: len 8; hex 8000000000000001; asc         ;;
 17: len 10; hex 52454352554954494e47; asc RECRUITING;;

*** (2) TRANSACTION:
TRANSACTION 9481469, ACTIVE 1 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 9 lock struct(s), heap size 1128, 4 row lock(s), undo log entries 2
MySQL thread id 135, OS thread handle 6137131008, query id 21633 localhost 127.0.0.1 root updating
update rooms set book_id=1,category='LITERATURE',description='인기 작가 김희용의 독서 모임방입니다.',end_date='2025-11-21',is_public=1,member_count=10,modified_at='2025-10-28 17:15:55.792038',password=null,recruit_count=10,room_percentage=0.0,room_status='RECRUITING',start_date='2025-11-10',status='ACTIVE',title='김희용의 문학 모임' where room_id=12345

*** (2) HOLDS THE LOCK(S):  // -> T2도 마찬가지로 PRIMARY 인덱스의 특정 레코드(room_id=12345 레코드) 에 s-lock hold 중
RECORD LOCKS space id 4932 page no 4 n bits 72 index PRIMARY of table `thip`.`rooms` trx id 9481469 lock mode S locks rec but not gap
Record lock, heap no 5 PHYSICAL RECORD: n_fields 18; compact format; info bits 64
 0: len 8; hex 8000000000003039; asc       09;;
 1: len 6; hex 00000090acee; asc       ;;
 2: len 7; hex 02000002290da7; asc     )  ;;
 3: len 8; hex 99b7ed7e47000000; asc    ~G   ;;
 4: len 8; hex 99b7f913f70605c5; asc         ;;
 5: len 1; hex 01; asc  ;;
 6: len 1; hex 03; asc  ;;
 7: len 30; hex ec9db8eab8b020ec9e91eab08020eab980ed9dacec9aa9ec9d9820eb8f85; asc                               ; (total 53 bytes);
 8: len 3; hex 8fd375; asc   u;;
 9: len 1; hex 01; asc  ;;
 10: len 4; hex 8000000a; asc     ;;
 11: SQL NULL;
 12: len 4; hex 8000000a; asc     ;;
 13: len 8; hex 0000000000000000; asc         ;;
 14: len 3; hex 8fd36a; asc   j;;
 15: len 26; hex eab980ed9dacec9aa9ec9d9820ebacb8ed959920ebaaa8ec9e84; asc                           ;;
 16: len 8; hex 8000000000000001; asc         ;;
 17: len 10; hex 52454352554954494e47; asc RECRUITING;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:  // -> T2도 마찬가지로 같은 레코드에 대해 x-lock 획득 대기 중
RECORD LOCKS space id 4932 page no 4 n bits 72 index PRIMARY of table `thip`.`rooms` trx id 9481469 lock_mode X locks rec but not gap waiting
Record lock, heap no 5 PHYSICAL RECORD: n_fields 18; compact format; info bits 64
 0: len 8; hex 8000000000003039; asc       09;;
 1: len 6; hex 00000090acee; asc       ;;
 2: len 7; hex 02000002290da7; asc     )  ;;
 3: len 8; hex 99b7ed7e47000000; asc    ~G   ;;
 4: len 8; hex 99b7f913f70605c5; asc         ;;
 5: len 1; hex 01; asc  ;;
 6: len 1; hex 03; asc  ;;
 7: len 30; hex ec9db8eab8b020ec9e91eab08020eab980ed9dacec9aa9ec9d9820eb8f85; asc                               ; (total 53 bytes);
 8: len 3; hex 8fd375; asc   u;;
 9: len 1; hex 01; asc  ;;
 10: len 4; hex 8000000a; asc     ;;
 11: SQL NULL;
 12: len 4; hex 8000000a; asc     ;;
 13: len 8; hex 0000000000000000; asc         ;;
 14: len 3; hex 8fd36a; asc   j;;
 15: len 26; hex eab980ed9dacec9aa9ec9d9820ebacb8ed959920ebaaa8ec9e84; asc                           ;;
 16: len 8; hex 8000000000000001; asc         ;;
 17: len 10; hex 52454352554954494e47; asc RECRUITING;;

*** WE ROLL BACK TRANSACTION (2)  // -> InnoDB의 최종 조치 : T2 롤백

→ [요약] : T1 과 T2 모두 room_id = 12345 레코드에 대한 s-lock 을 유지하고 있고, 해당 레코드를 update 를 위해 서로가 가진 s-lock 해제를 기다리다가(x-lock으로의 전환을 위해) 데드락이 발생. 결국 T2 가 롤백됨.

→ [의문점] : room_id = 12345 레코드에 대한 s-lock 획득은 언제 발생한 것인가??

실제 THIP 코드로 확인

‘방 참여 api’ 에서 유효성 검증 이후의 플로우는 아래와 같음

RoomParticipant 엔티티 save

@Override
public void save(RoomParticipant roomParticipant) {
    UserJpaEntity userJpaEntity = userJpaRepository.findByUserId(roomParticipant.getUserId()).orElseThrow(
            () -> new EntityNotFoundException(USER_NOT_FOUND));

    RoomJpaEntity roomJpaEntity = roomJpaRepository.findByRoomId(roomParticipant.getRoomId()).orElseThrow(
            () -> new EntityNotFoundException(ROOM_NOT_FOUND)
    );

    roomParticipantJpaRepository.save(roomParticipantMapper.toJpaEntity(
            roomParticipant, userJpaEntity, roomJpaEntity
    ));
}

Room 엔티티 조회 → 필드값 update → save

@Override
public void update(Room room) {
    RoomJpaEntity roomJpaEntity = roomJpaRepository.findByRoomId(room.getId()).orElseThrow(
            () -> new EntityNotFoundException(ROOM_NOT_FOUND)
    );

    roomJpaRepository.save(roomJpaEntity.updateFrom(room));
}

위 코드가 트랜잭션 내에서 실행되는 과정은 아래와 같음
1. 새로 생성된 RoomParticipantJpaEntity 가 영속성 컨텍스트에 영속화 상태로 올라감(roomParticipantJpaRepository.save())
2. 이후 RoomJpaEntity 가 조회 → 필드값 업데이트 → roomJpaRepository.save() 과정으로 인해 영속성 컨텍스트 내부에서 dirty 상태로 존재
3. 트랜잭션이 끝나고, 영속성 컨텍스트가 flush 될 때,
  1. DB로 RoomParticipant 엔티티에 대한 insert 쿼리 발생
  2. DB로 Room 엔티티에 대한 update 쿼리 발생
  인 것은 확인함
  - 테스트 코드를 통해서 new 엔티티 save, dirty 엔티티 save 이후 flush 시 insert, update 쿼리가 발생하는것 확인함

s-lock 획득 시점 파악

MySQL 공식 문서에 ‘외래키 제약조건이 정의된 테이블에 insert, update, delete 쿼리가 발생할 때 해당 FK와 관련된 레코드에 대해 s-lock 을 획득한다’ 라는 언급이 있음

https://dev.mysql.com/doc/refman/9.3/en/innodb-locks-set.html#:~:text=If a FOREIGN KEY constraint is defined on a table%2C any insert%2C update%2C or delete that requires the constraint condition to be checked sets shared record-level locks on the records that it looks at to check the constraint. InnoDB also sets these locks in the case where the constraint fails

현재 THIP 에서의 room_participants 테이블의 스키마는 아래와 같다

create table room_participants
(
    room_participant_id   bigint auto_increment
        primary key,
    created_at            datetime(6)                            not null,
    modified_at           datetime(6)                            not null,
    status                enum ('ACTIVE', 'EXPIRED', 'INACTIVE') not null,
    current_page          int                                    not null,
    room_participant_role enum ('HOST', 'MEMBER')                not null,
    user_percentage       double                                 not null,
    room_id               bigint                                 null,
    user_id               bigint                                 null,
    **constraint FK4mv7x9pqx10gk4dp04uv8kcj0
        foreign key (room_id) references rooms (room_id),**
    constraint FKry0h8u0jjq3gsyc9rvvqujek3
        foreign key (user_id) references users (user_id)
);