내가 지금 회사에서 개발한 것 중에는 사용자에게 보이는 알림과 작품, 시스템에 대한 알림 설정을 관리하는 Notification API가 있고 댓글과 작품의 Rating, Like를 관리하는 Community API가 있다. 그런데 이 두 서비스에서 빈도는 낮지만, 간혹 CannotAcquireLockException이 발생하여 원인을 찾아보려고 했던 과정과 사례를 적어본다.
CannotAcquireLockException
문서에는 이름과 같이 lock을 얻지 못해 발생하는 예외이다. 또한 stack trace의 메시지와1 검색한 결과로 보건대 Notification API에서는 알림을 읽은 시간을 기록하는 Confirm API와 댓글을 Like 하는 Comment Like API에서 발생했고 deadlock과 관련되어 보였다.
Deadlock
DB는 트랜잭션을 안전하게 수행하기 위해 lock을 사용한다. 그런데 트랜잭션들이 서로 필요한 lock을 가지고 있어 진행할 수 없는 상태가 되는 것이 deadlock이다. MySQL 문서에 있는 예제를 보면 어떻게 deadlock이 발생하는지 보여준다.
클라이언트 A에서 share mode로 select하여 lock를 얻는다. share mode는 트랜잭션이 끝날 때까지 값이 변경되지 않도록 한다.
mysql> CREATE TABLE t (i INT) ENGINE = InnoDB;
Query OK, 0 rows affected (1.07 sec)
mysql> INSERT INTO t (i) VALUES(1);
Query OK, 1 row affected (0.09 sec)
mysql> START TRANSACTION;
Query OK, 0 rows affected (0.00 sec)
mysql> SELECT * FROM t WHERE i = 1 FOR SHARE;
+------+
| i |
+------+
| 1 |
+------+그리고, 클라이언트 B에서 트랜잭션을 시작하고 row를 삭제한다.
mysql> START TRANSACTION;
Query OK, 0 rows affected (0.00 sec)
mysql> DELETE FROM t WHERE i = 1;삭제 작업은 x lock을2 필요로 합니다. 그리고 s lock이 있는 동안은 x lock을 획들 할 수 없다. A가 s lock을 가지고 있고 B의 요청은 queue로 전달된다. 끝으로, A가 row를 삭제하려고 한다.
mysql> DELETE FROM t WHERE i = 1;
ERROR 1213 (40001): Deadlock found when trying to get lock;
try restarting transactiondeadlock은 이때 발생한다. A는 삭제 작업을 하기 위해 x lock이 필요하지만, B가 x lock에 대한 요청을 기다리고 있고 A가 lock을 해제하기를 기다리고 있기 때문이다. 결과적으로 InnoDB는 클라이언트 중 하나의 lock을 해제하고 에러를 발생시킨다.
Confirm API
Confirm API는 알림을 읽은 시간을 기록하는 API이다. 30일 이내의 최대 50 건의 알림을 가져와서 읽지 않은 알림만 현재 시각으로 갱신하는 로직이다. (SimpleJpaRepository의 saveAll()을 사용한다.)결국, SELECT와 UPDATE하는 로직인데 UPDATE 할 때는 x lock이 필요하겠지만 위의 예제처럼 SELECT할 때 share mode를 쓰거나 하지 않아 s lock이 필요하지 않다. 그렇다면 왜 발생한 걸까?
SHOW ENGINE INNODB STATUS 명령어의 LATEST DETECTED DEADLOCK 항목에 아래의 내용이 있었다.
------------------------
LATEST DETECTED DEADLOCK
------------------------
2020-05-30 08:47:32 2b246ec44700
*** (1) TRANSACTION:
TRANSACTION 828466999, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 376, 2 row lock(s), undo log entries 1
MySQL thread id 18147477, OS thread handle 0x2b1effe82700, query id 1061155561
update notification set contents='Kelas Rahasia Sang Permaisuri \"gukguk item tsundere sedang guguk putih masochist 🤭🤣
\"', created='2020-05-30 08:44:15', icon_uri='icon/notification/x2/comment.jpg.webp', landing_uri='idn.kakaopage://comment/3311/151580/791309', push_id='LIKE_COMMENT-791309-1590828254', title='\'athyy dan 58orang lainya\' telah menyukai komentar kamu.', type_code='LIKE_COMMENT', user_id='idnub265f96b23bb86', viewed='2020-05-30 08:47:32.551' where id=199064878
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 13 page no 6567228 n bits 48 index `PRIMARY` of table `page-notification`.`notification` trx id 828466999 lock_mode X locks rec but not gap waiting
Record lock, heap no 48 PHYSICAL RECORD: n_fields 12; compact format; info bits 0
*** (2) TRANSACTION:
TRANSACTION 828466998, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 376, 2 row lock(s), undo log entries 1
MySQL thread id 18147633, OS thread handle 0x2b1eff2c5700, query id 1061155560
update notification set contents='Adonis "masih gagal paham😐😶😶"', created='2020-05-30 08:25:53.0', icon_uri='icon/notification/x2/comment.jpg.webp', landing_uri='idn.kakaopage://comment/2267/24187/1213101', push_id='REPLY_TO_COMMENT-1213101-1590827152', title='byun baekhyun meninggalkan jawaban di komentarmu.', type_code='REPLY_TO_COMMENT', user_id='idnub265f96b23bb86', viewed='2020-05-30 08:47:32.551' where id=199063150
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 13 page no 6567228 n bits 48 index `PRIMARY` of table `page-notification`.`notification` trx id 828466998 lock_mode X locks rec but not gap
Record lock, heap no 48 PHYSICAL RECORD: n_fields 12; compact format; info bits 0
[bitmap0 of 16 bytes in hex: 00 00 00 00 00 00 01 00 00 00 00 00 00 00 00 00 ]
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 13 page no 6567189 n bits 52 index `PRIMARY` of table `page-notification`.`notification` trx id 828466998 lock_mode X locks rec but not gap waiting
Record lock, heap no 52 PHYSICAL RECORD: n_fields 12; compact format; info bits 0이 내용으로 알 수 있는 사실은 다음과 같다.
TRANSACTION 1은 id가 199064878인 row를 UPDATE 한다.TRANSACTION 2는 id가 199063150인 row를 UPDATE 한다.TRANSACTION 1은 UPDATE하는 record에 대한 x lock이 필요하여 기다리고 있다.TRANSACTION 2는 UPDATE하는 record에 대한 x lock이 필요하여 기다리고 있다.TRANSACTION 2는TRANSACTION 1이 기다리고 있는 record의 x lock을 가지고 있다.
이 과정대로 쿼리를 수행하면 재현이 가능하다.
테이블을 생성.
CREATE TABLE `deadlock` (
`id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
`val` int(11) DEFAULT NULL,
PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;위와 같이 데이터를 입력.
+-------------+
| id | val |
+------+------+
| 1 | 1 |
+------+------+
| 2 | 2 |
+------+------+첫 번째 클라이언트에서 id가 1인 record의 x lock 획득.
# Client A
START TRANSACTION;
UPDATE deadlock SET val = 101 where id = 1;두 번째 클라이언트에서 id가 2인 record의 x lock 획득. 그리고 id가 1인 record의 x lock을 얻기 위해 대기.
# Client B
START TRANSACTION;
UPDATE deadlock SET val = 101 where id = 2;
UPDATE deadlock SET val = 101 where id = 1;다시 첫 번째 클라이언트에서 id가 2인 record의 x lock 획득 시도. 여기서 deadlock발생.
# Client A
UPDATE deadlock SET val = 101 where id = 2;재현 방법은 어렵지 않은데 위의 과정처럼 하나의 트랜잭션에서 2개 이상의 UPDATE명령을 실행해야 발생한다. 하지만 나는 트랜잭션을 사용한 적이 없었는데 deadlock이 발생한 것이 의아했다. 그러다가 saveAll() 코드를 확인해 보았는데 여기에 트랜잭션 어노테이션이 사용되고 있었다.
@Transactional
@Override
public <S extends T> List<S> saveAll(Iterable<S> entities) {
...
}이제는 deadlock이 발생했을 때의 상황을 알 것도 같다.
- 짦은 시간 안에
Confirm API가 동시에 호출되어 - 읽은 시간을 업데이트하기 위해 알림 목록을
saveAll()로 업데이트할 때 - 같은 알림목록을 대상으로 하여도 업데이트가 수행되는 순서는 보장되지 않기 때문에
- 서로 다른 트랜잭션에서 lock을 필요로하는 상황으로 deadlock 발생한 것이다.
Comment Like API
Comment Like API는 댓글의 좋아요 버튼을 누를 때를 호출되는 API이다. comment, comment_like 2개의 테이블을 사용한다. comment_like에는 사용자가 댓글에 좋아요 설정 또는 취소한 상태를 comment에는 댓글과 좋아요 숫자를 필드로 가지고 있다. 아래는 2개의 테이블을 간략화한 스키마이다.
CREATE TABLE `comment` (
`id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
`comment` varchar(500) NOT NULL DEFAULT '',
`like_count` int(11) unsigned NOT NULL DEFAULT '0',
PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;
CREATE TABLE `comment_like` (
`id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
`comment_id` bigint(20) unsigned NOT NULL,
`is_like` tinyint(1) NOT NULL DEFAULT '1',
PRIMARY KEY (`id`),
CONSTRAINT `fk_commentLike_commentId` FOREIGN KEY (`comment_id`) REFERENCES `comment` (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;이것도 SHOW ENGINE INNODB STATUS로 deadlock 정보를 찾아보았다.
------------------------
LATEST DETECTED DEADLOCK
------------------------
2020-06-10 17:16:42 2b221d246700
*** (1) TRANSACTION:
TRANSACTION 1124624957, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 376, 2 row lock(s), undo log entries 1
MySQL thread id 5148115, OS thread handle 0x2b1c5c38a700, query id 1602285300 update comment set like_count=like_count+1, updated='2020-06-10 17:16:42.991' where id=1105292
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 8 page no 22700 n bits 36 index `PRIMARY` of table `page-community`.`comment` trx id 1124624957 lock_mode X locks rec but not gap waiting
Record lock, heap no 36 PHYSICAL RECORD: n_fields 15; compact format; info bits 0
*** (2) TRANSACTION:
TRANSACTION 1124624956, ACTIVE 0 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 5 lock struct(s), heap size 376, 2 row lock(s), undo log entries 1
MySQL thread id 5148104, OS thread handle 0x2b1cada44700, query id 1602285299 update comment set like_count=like_count+1, updated='2020-06-10 17:16:42.988' where id=1105292
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 8 page no 22700 n bits 36 index `PRIMARY` of table `page-community`.`comment` trx id 1124624956 lock mode S locks rec but not gap
Record lock, heap no 36 PHYSICAL RECORD: n_fields 15; compact format; info bits 0
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 8 page no 22700 n bits 36 index `PRIMARY` of table `page-community`.`comment` trx id 1124624956 lock_mode X locks rec but not gap waiting
Record lock, heap no 36 PHYSICAL RECORD: n_fields 15; compact format; info bits 0Confirm API와 유사하지만 두 개의 트랜잭션이 하나의 row를 업데이트하고, 두 번째 트랜잭션이 x가 아닌 S lock을 가지고 있는 것이 눈에 띈다. 이 로직에서도 명시적으로 lock을 선언한 부분이 없는데 왜 deadlock이 발생한 것일까?
InnoDB에서 lock을 설정하는 경우를 나열해놓은 문서에서 Foreign Key 조건에서 s lock을 설정한다고 나와있다.
FOREIGN KEY가 테이블에 정의되어 있다면 제약조건을 확인해야 할 모든 insert, update, delete는 제약조건을 참조하고 있는 record에 shared lock을 설정한다. 또한, InnoDB는 제약조건이 실패하는 경우에도 lock을 설정한다.
이 내용대로 추론해보면 아래의 과정으로 재현할 수 있다.
CREATE TABLE `deadlock_child` (
`id` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
`deadlock_id` bigint(20) unsigned NOT NULL,
`val` int(11) NOT NULL,
PRIMARY KEY (`id`),
KEY `fk_deadlock_id` (`deadlock_id`),
CONSTRAINT `fk_deadlock_id` FOREIGN KEY (`deadlock_id`) REFERENCES `deadlock` (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4;deadlock 테이블을 참조하는 deadlock_child 테이블 생성.
# Client A
START TRANSACTION;
INSERT INTO `deadlock_child` (`deadlock_id`, `val`) VALUES (1, 101);첫 번째 클라이언트에서 자식 테이블에 insert하여 deadlock 테이블의 id가 1인 record의 s lock 획득.
# Client B
START TRANSACTION;
INSERT INTO `deadlock_child` (`deadlock_id`, `val`) VALUES (1, 101);두 번째 클라이언트에서 동일하게 deadlock 테이블의 id가 1인 record의 s lock 획득.
# Client A
UPDATE deadlock SET val = 101 where id = 1;첫 번째 클라이언트에서 x lock 획득을 위해 대기.
# Client B
UPDATE deadlock SET val = 101 where id = 1;두 번째 클라이언트도 x lock이 필요. 여기서 deadlock 발생.
이것도 짧은 시간 안에 같은 API가 동시에 요청되어 발생한 문제라고 여겨진다.
해결은 어떻게 하나?
이것 또한 MySQL 문서에서 deadlock를 어떻게 최소화할 수 있는지 알려준다. 기본적으로는 deadlock이 발생할 때는 재시도 하라고 하고 있으며 트랜잭션을 짧게 설정하라고 하고 있다. Confirm API의 경우에는 하나의 트랜잭션에서 수행되는 쿼리가 최대 50개가 될 수 있기 때문에 UPDATE ... WHERE IN 으로 변경하려고 한다. (2개의 row만 업데이트하는 경우에도 deadlock이 발생하기도 했다.)
Comment Like API는 부모 테이블을 먼저 업데이트하면 deadlock이 발생하지 않는다. 쿼리에 필요한 lock을 미리 획득하기 때문인데 순서를 변경하여도 로직에는 영향을 주지 않기 때문에 순서를 바꿔도 무방하다.
-
Deadlock found when trying to get lock; try restarting transaction
↩ -
https://jeong-pro.tistory.com/94
↩