픽의 태그 수정 시 터지는 동시성 문제

[sangwonsheep]

MySQL Log

MySQL Log 설정

# general log 설정 확인
show variables like 'general_log%';

# general log 설정 켜기
set global general_log='ON';

# 로그 파일 위치 변경
set global general_log_file='/var/lib/mysql/general_log.log';

참고 링크

# 동시에 트랜잭션 시작
2024-12-04T09:58:05.322809Z	 3516 Query	SET autocommit=0
2024-12-04T09:58:05.322809Z	 3517 Query	SET autocommit=0

# 동시에 Pick 조회
2024-12-04T09:58:05.323578Z	 3517 Query	select p1_0.id,p1_0.created_at,p1_0.link_id,p1_0.parent_folder_id,p1_0.tag_order,p1_0.title,p1_0.updated_at,p1_0.user_id from pick p1_0 where p1_0.id=104
2024-12-04T09:58:05.323578Z	 3516 Query	select p1_0.id,p1_0.created_at,p1_0.link_id,p1_0.parent_folder_id,p1_0.tag_order,p1_0.title,p1_0.updated_at,p1_0.user_id from pick p1_0 where p1_0.id=104

# 동시에 Tag 조회
2024-12-04T09:58:05.326315Z	 3517 Query	select t1_0.id,t1_0.color_number,t1_0.name,t1_0.user_id from tag t1_0 where t1_0.id in (7,8,9,10,11)
2024-12-04T09:58:05.326315Z	 3516 Query	select t1_0.id,t1_0.color_number,t1_0.name,t1_0.user_id from tag t1_0 where t1_0.id in (7,8,9,10)

# 동시에 Pick 조회 - select for update(비관적 락)
2024-12-04T09:58:05.328577Z	 3517 Query	select p1_0.id,p1_0.created_at,p1_0.link_id,p1_0.parent_folder_id,p1_0.tag_order,p1_0.title,p1_0.updated_at,p1_0.user_id from pick p1_0 where p1_0.id=104 for update
2024-12-04T09:58:05.328577Z	 3516 Query	select p1_0.id,p1_0.created_at,p1_0.link_id,p1_0.parent_folder_id,p1_0.tag_order,p1_0.title,p1_0.updated_at,p1_0.user_id from pick p1_0 where p1_0.id=104 for update

# 트랜잭션 3517이 먼저 실행
# PickTag에 insert하는 부분
# tagIdList : [7, 8, 9, 10, 11]
# 7, 8, 9는 이미 DB에 있으므로 10, 11 insert
2024-12-04T09:58:05.331068Z	 3517 Query	insert into pick_tag (pick_id,tag_id) values (104,10)
2024-12-04T09:58:05.333046Z	 3517 Query	insert into pick_tag (pick_id,tag_id) values (104,11)

# 이후 트랜잭션 3517 실행
2024-12-04T09:58:05.334959Z	 3517 Query	select l1_0.id,l1_0.description,l1_0.image_url,l1_0.invalidated_at_at,l1_0.title,l1_0.url from link l1_0 where l1_0.id=104
2024-12-04T09:58:05.337155Z	 3517 Query	update pick set link_id=104,parent_folder_id=23,tag_order='7 8 9 10 11',title='GitHub',updated_at='2024-12-04 18:58:05.336236',user_id=1 where id=104
2024-12-04T09:58:05.338293Z	 3517 Query	commit
2024-12-04T09:58:05.348285Z	 3517 Query	SET autocommit=1

# 트랜잭션 3516이 이미 DB에 존재하는 10을 다시 insert
2024-12-04T09:58:05.350489Z	 3516 Query	insert into pick_tag (pick_id,tag_id) values (104,10)

# 이미 존재하는 row이므로 예외가 발생하여 rollback
2024-12-04T09:58:05.362478Z	 3516 Query	rollback

Application Log

2024-12-04 18:58:05.329  INFO 1 --- [io-8080-exec-10] t.a.infrastructure.pick.PickDataHandler  : ---------- (1) [7, 8, 9]
2024-12-04 18:58:05.329  INFO 1 --- [io-8080-exec-10] t.a.infrastructure.pick.PickDataHandler  : ---------- (2) [7, 8, 9]
2024-12-04 18:58:05.329  INFO 1 --- [io-8080-exec-10] t.a.infrastructure.pick.PickDataHandler  : ---------- (2) [7, 8, 9]
2024-12-04 18:58:05.330  INFO 1 --- [io-8080-exec-10] t.a.infrastructure.pick.PickDataHandler  : ---------- (2) [7, 8, 9]
2024-12-04 18:58:05.330  INFO 1 --- [io-8080-exec-10] t.a.infrastructure.pick.PickDataHandler  : ---------- (2) [7, 8, 9]
2024-12-04 18:58:05.331  INFO 1 --- [io-8080-exec-10] p6spy                                    :
    insert
    into
        pick_tag
        (pick_id, tag_id)
    values
        (104, 10)
2024-12-04 18:58:05.332  INFO 1 --- [io-8080-exec-10] t.a.infrastructure.pick.PickDataHandler  : ---------- (2) [7, 8, 9]
2024-12-04 18:58:05.333  INFO 1 --- [io-8080-exec-10] p6spy                                    :
    insert
    into
        pick_tag
        (pick_id, tag_id)
    values
        (104, 11)
2024-12-04 18:58:05.334  INFO 1 --- [io-8080-exec-10] t.a.infrastructure.pick.PickDataHandler  : ---------- (3) [7, 8, 9]
2024-12-04 18:58:05.334  INFO 1 --- [io-8080-exec-10] t.a.infrastructure.pick.PickDataHandler  : ---------- (4) [7, 8, 9, 10, 11]
2024-12-04 18:58:05.335  INFO 1 --- [io-8080-exec-10] p6spy                                    :
    select
        l1_0.id,
        l1_0.description,
        l1_0.image_url,
        l1_0.invalidated_at_at,
        l1_0.title,
        l1_0.url
    from
        link l1_0
    where
        l1_0.id=104
2024-12-04 18:58:05.337  INFO 1 --- [io-8080-exec-10] p6spy                                    :
    update
        pick
    set
        link_id=104,
        parent_folder_id=23,
        tag_order='7 8 9 10 11',
        title='GitHub',
        updated_at='2024-12-04T18:58:05.336+0900',
        user_id=1
    where
        id=104
2024-12-04 18:58:05.347  INFO 1 --- [io-8080-exec-10] p6spy                                    :

위에 로그를 살펴보면, PickTag에 7, 8, 9, 10, 11 값이 insert 되었음.
Pick에 있는 tag_order의 경우도 '7 8 9 10 11'로 update 되었음.

---

2024-12-04 18:58:05.347  INFO 1 --- [nio-8080-exec-8] p6spy                                    :
    select
        p1_0.id,
        p1_0.created_at,
        p1_0.link_id,
        p1_0.parent_folder_id,
        p1_0.tag_order,
        p1_0.title,
        p1_0.updated_at,
        p1_0.user_id
    from
        pick p1_0
    where
        p1_0.id=104 for update
2024-12-04 18:58:05.348  INFO 1 --- [nio-8080-exec-8] t.a.infrastructure.pick.PickDataHandler  : ---------- (1) [7, 8, 9]
2024-12-04 18:58:05.348  INFO 1 --- [nio-8080-exec-8] t.a.infrastructure.pick.PickDataHandler  : ---------- (2) [7, 8, 9]
2024-12-04 18:58:05.349  INFO 1 --- [nio-8080-exec-8] t.a.infrastructure.pick.PickDataHandler  : ---------- (2) [7, 8, 9]
2024-12-04 18:58:05.349  INFO 1 --- [nio-8080-exec-8] t.a.infrastructure.pick.PickDataHandler  : ---------- (2) [7, 8, 9]
2024-12-04 18:58:05.349  INFO 1 --- [nio-8080-exec-8] t.a.infrastructure.pick.PickDataHandler  : ---------- (2) [7, 8, 9]
2024-12-04 18:58:05.355  INFO 1 --- [nio-8080-exec-8] p6spy                                    :
    insert
    into
        pick_tag
        (pick_id, tag_id)
    values
        (104, 10)
2024-12-04 18:58:05.366  INFO 1 --- [nio-8080-exec-8] p6spy                                    :
2024-12-04 18:58:05.370 ERROR 1 --- [nio-8080-exec-8] t.core.exception.level.ErrorLevel        : could not execute statement [Duplicate entry '104-10' for key 'pick_tag.UC_PICK_TAG'] [insert into pick_tag (pick_id,tag_id) values (?,?)]; SQL [insert into pick_tag (pick_id,tag_id) values (?,?)]; constraint [pick_tag.UC_PICK_TAG]
org.springframework.dao.DataIntegrityViolationException: could not execute statement [Duplicate entry '104-10' for key 'pick_tag.UC_PICK_TAG'] [insert into pick_tag (pick_id,tag_id) values (?,?)]; SQL [insert into pick_tag (pick_id,tag_id) values (?,?)]; constraint [pick_tag.UC_PICK_TAG]
{"requestTime":"2024-12-04T18:58:05.321555363","method":"PATCH","requestBody":"{\"id\":104,\"tagIdOrderedList\":[7,8,9,10]}","requestURI":"/api/picks","cookies":{"techPickLogin":"true"}}

이미 PickTag 테이블에 7, 8, 9, 10, 11이 존재하므로 10을 넣지 못함.
그렇기 때문에 unique index 조건에 걸리게 되어 예외가 발생하게 됨.

그렇다면, 프론트엔드에서 요청은 어떻게 날라왔을까? 순서는 어떻게 넘어왔을까?

프론트엔드 요청

1. [7, 8] 요청

2. [7, 8, 9] 요청

3. [7, 8, 9, 10] 요청

4. [7, 8, 9, 10, 11] 요청

1 -> 2 -> 3 -> 4 순서로 요청을 진행하였음.
하지만, 실제 DB에는 3번째 4번째 요청이 동시에 진행되었음.
즉, 동시성 문제가 발생했다는 것.

결론

프론트에서 요청의 순서를 보장해서 보내줘야 할 것인가?
백엔드에서 당연히 락을 걸어서 동시성 제어를 할 것이다.
백엔드에서 픽 수정하는 부분에 대하여 비관적 락이 걸려있으나, 비관적 락은 무시되었다.

1. 비관적 락이 제대로 동작하지 않은 이유를 분석해야 한다.
2. 빠른 시간 내에 요청을 보낸 것도 아닌데 왜 동시성 문제가 터지는 것일까에 대한 분석이 필요하다.

[kimminkyeu]

찾아보니 SELECT ... FOR UPDATE 은 제대로 동작한게 맞습니다.
다른 트랜잭션의 READ를 안막고, UPDATE 만 막는게 정상적인 동작이였네요...

INNODB 공식 설명을 다시 한번 유심히 봤습니다.

https://dev.mysql.com/doc/refman/8.4/en/innodb-locks-set.html

• [출처] https://dev.mysql.com/doc/refman/8.4/en/innodb-locking-reads.html

For index records the search encounters, locks the rows and any associated index entries, the same as if you issued an UPDATE statement for those rows.
Other transactions are blocked from updating those rows,
⚠️ from doing SELECT ... FOR SHARE,
⚠️ or from reading the data in certain transaction isolation levels.
⚠️ Consistent reads ignore any locks set on the records that exist in the read view.

SELECT … FOR UPDATE 은 ...

1. ⚠️ 다른 Transaction의 SELECT … FOR UPDATE 을 막지 않는다.
2. ⚠️ 특정 ISOLATION LEVEL은 막지 않는다.
3. ⚠️ Consistent Read를 지원하는 경우 막지 않는다. = Reapeatable Read, Read Commited를 막지 않는다.

따라서 위 쿼리는 Innodb의 방식대로 잘 돌아간 게 맞네요.

근본적 문제는, 들어온 요청 순서와 쿼리 실행 순서가 달라서인 것으로 보입니다.
요청은 A B C 이렇게 왔는데
트랜잭션 시작, 쿼리 실행은 A C B 로 실행되서 터지는 것인데요

해결법은 요청 순서대로 태그 Read-Update-Commit이 동작하도록 보장하는 것 같습니다.

1. JPA Version 은 그런 관점에서 해결을 못함. 왜냐면 retry 후에 다시 시도할때 계속 터질 것이기 때문. 즉 리트라이 돌다가 터지는건 마찬가지.

2. 저희가 구현한 Named Lock으로 Read 단에서 부터 줄세우기

결국은 지금 설계에서 유일한 해결책은 네임드락 뿐이네요....

정리하면
해결법 = 쿼리가 요청 순서대로 실행되지 않기 때문에, 최초 태그 리스트 Read 쿼리 실행때부터 줄세우기 해야 함.