InnoDB 교착 로그 읽기: LATEST DETECTED DEADLOCK
회원 프로필에 관심 태그를 저장하는 API가 있었다. 저장 버튼을 누르면 그 회원의 태그를 전부 지우고 새로 고른 태그를 다시 넣는 단순한 구조였다. 예전 태그와 새 태그를 비교하는 코드를 짜기 귀찮아서 고른 방식이다. 그러다 가입 이벤트가 열린 날, 에러 알림 채널에 Deadlock found when trying to get lock이 줄줄이 올라왔다.
같은 행을 두고 다툰 것도 아닌데 교착이라니 납득이 가지 않았다. 신규 가입자는 저마다 다른 회원이고, 각자 자기 태그만 지우고 넣는다. 겹칠 데가 없어 보였다. 손에 쥔 단서는 SHOW ENGINE INNODB STATUS 결과에 있는 LATEST DETECTED DEADLOCK 구역 하나뿐이었다.
그 전까지는 이 구역에서 쿼리 두 줄만 훑고 창을 닫곤 했다. 그날 처음으로 끝까지 한 줄씩 읽었다. 아래는 그때 원인을 찾아간 순서 그대로다. 기준은 MySQL 8.0이다.
로그부터 확보한다
SHOW ENGINE INNODB STATUS\G결과에서 LATEST DETECTED DEADLOCK 구역을 찾는다. 이 구역에는 가장 최근에 난 교착 하나만 남는다. 그날 알림을 보고 몇 분 뒤에 명령을 쳤더니 이미 다른 교착이 그 자리를 덮어쓴 뒤였다. 같은 패턴이 계속 나던 중이라 다행이었지, 한 번뿐인 교착이었다면 흔적도 못 찾았을 것이다. 그 뒤로는 서버마다 아래 설정을 켜 둔다. 교착이 날 때마다 전부 에러 로그에 기록된다.
SET GLOBAL innodb_print_all_deadlocks = ON;버전 차이도 있다. 5.7을 쓰던 시절에는 (1)번 트랜잭션이 이미 쥐고 있던 잠금이 로그에 나오지 않았다. 그래서 반쪽짜리 로그를 들고 추측을 해야 했다. 8.0에서는 두 트랜잭션 모두 HOLDS THE LOCK(S) 구역이 따로 붙는다.
뼈대는 트랜잭션 두 개와 네 구역
그날 받은 로그를 간추리면 이렇다. 스레드 번호처럼 원인과 상관없는 줄은 줄였다.
*** (1) TRANSACTION:
TRANSACTION 91822, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1128, 2 row lock(s)
INSERT INTO user_tags (user_id, tag) VALUES (150, 'camping')
*** (1) HOLDS THE LOCK(S):
RECORD LOCKS space id 41 page no 5 n bits 80 index uk_user_tag of table `shop`.`user_tags` trx id 91822 lock_mode X locks gap before rec
Record lock, heap no 3 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
0: len 8; hex 80000000000000c8; asc ;;
1: len 4; hex 676f6c66; asc golf;;
2: len 8; hex 8000000000000002; asc ;;
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 41 page no 5 n bits 80 index uk_user_tag of table `shop`.`user_tags` trx id 91822 lock_mode X locks gap before rec insert intention waiting
Record lock, heap no 3 PHYSICAL RECORD: n_fields 3; compact format; info bits 0
0: len 8; hex 80000000000000c8; asc ;;
1: len 4; hex 676f6c66; asc golf;;
2: len 8; hex 8000000000000002; asc ;;
*** (2) TRANSACTION:
TRANSACTION 91823, ACTIVE 0 sec inserting
INSERT INTO user_tags (user_id, tag) VALUES (160, 'running')
*** (2) HOLDS THE LOCK(S):
... index uk_user_tag ... trx id 91823 lock_mode X locks gap before rec
(같은 레코드: 200, 'golf', 2)
*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
... index uk_user_tag ... trx id 91823 lock_mode X locks gap before rec insert intention waiting
(같은 레코드: 200, 'golf', 2)
*** WE ROLL BACK TRANSACTION (2)트랜잭션마다 머리말, 쥔 잠금, 기다리는 잠금 순서로 나오고, 맨 끝에 희생자가 적힌다. 머리말의 ACTIVE 0 sec는 트랜잭션이 열린 지 얼마나 됐는지를 보여 준다. 0초라면 긴 배치가 아니라 짧은 요청끼리 부딪쳤다는 뜻이다. LOCK WAIT는 잠금을 기다리는 상태라는 표시다.
가장 조심해야 할 점은 쿼리 줄이다. 여기 찍히는 문장은 교착이 감지된 순간 실행 중이던 문장 하나뿐이다. 같은 트랜잭션에서 앞서 실행한 문장은 나오지 않는다. 이걸 몰라서 처음엔 INSERT 두 개만 보고 한참 헤맸다. 희생자는 InnoDB가 고른다. 문서에 따르면 삽입, 수정, 삭제한 행 수가 적은 쪽, 즉 작은 트랜잭션을 되돌리려 한다.
lock_mode 뒤에 붙는 말
잠금 줄의 핵심은 lock_mode 다음에 오는 꼬리말이다. 표기와 뜻을 표로 옮겨 둔다.
| 표기 | 잠그는 범위 |
|---|---|
lock_mode X | 꼬리말이 없으면 next-key 락. 레코드와 그 앞 간격을 함께 잠근다 |
lock_mode X locks rec but not gap | 레코드 하나만. 간격은 건드리지 않는다 |
lock_mode X locks gap before rec | 레코드 앞 간격만. 레코드 자체는 잠그지 않는다 |
... gap before rec insert intention | 그 간격에 행을 넣겠다는 삽입 의도 락 |
lock mode S ... | 공유 잠금. 나머지 꼬리말은 X와 같은 방식으로 읽는다 |
끝에 붙은 waiting | 아직 얻지 못하고 기다리는 중 |
처음엔 꼬리말 없는 lock_mode X를 레코드 잠금으로 읽었다. 반대다. 아무 말도 없는 쪽이 가장 넓게 잠근다. 레코드 칸에 supremum이 보이면 인덱스 맨 끝 너머의 간격, 즉 가장 큰 값 뒤쪽이 잠겼다는 뜻이다.
갭 락은 성질이 독특하다. 오로지 남이 그 간격에 행을 넣지 못하게 막는 용도라서 갭 락끼리는 충돌하지 않는다. 두 트랜잭션이 같은 간격에 X 갭 락을 동시에 쥘 수 있다. 반면 삽입 의도 락은 남이 쥔 갭 락과 충돌한다. 삽입 의도 락끼리는 넣는 자리가 다르면 서로 기다리지 않는다.
레코드 줄에서 값 꺼내기
index uk_user_tag를 보면 어느 인덱스에서 잠금이 걸렸는지 알 수 있다. 테이블 정의를 열어 보니 (user_id, tag) 유니크 인덱스였다. 보조 인덱스 레코드는 인덱스 컬럼 뒤에 기본 키가 붙어 있어서 필드가 세 개다. 0번은 user_id, 1번은 tag, 2번은 id다.
hex 80000000000000c8은 BIGINT 값이다. InnoDB는 정렬을 위해 부호 비트를 뒤집어 저장하므로 맨 앞의 8을 0으로 돌려 읽으면 0xc8, 곧 200이다. 1번 필드는 asc 칸에 글자가 그대로 보인다. 결국 레코드는 (200, 'golf', 2)다.
여기서 before rec의 뜻을 잘못 읽기 쉽다. 잠긴 건 200번 회원의 행이 아니라 그 앞의 빈 간격이다. 바로 앞 레코드가 (100, 'book')이었으니 user_id 100과 200 사이, 태그가 아직 없는 신규 회원들이 모두 들어갈 자리다. 150번과 160번 회원이 같은 간격에 모여 있었던 것이다.
로그에 없는 문장을 찾아서
이제 거꾸로 따라간다. 두 트랜잭션은 같은 간격에 갭 락을 쥐고 있고, 각자 그 간격에 넣으려다 상대의 갭 락에 막혔다. 그림으로 그리면 원이 닫힌다. 남은 질문은 하나다. INSERT 전에 누가 갭 락을 걸었을까.
INSERT는 스스로 갭 락을 걸지 않는다. 간격을 잠그는 건 잠금 읽기나 UPDATE, DELETE처럼 인덱스를 검색하는 문장이다. 특히 검색 결과가 비었을 때 REPEATABLE READ에서는 찾은 자리 앞의 간격을 잠근다. 그래서 같은 트랜잭션 안에서 user_tags를 건드리는 코드를 찾아봤고, 곧바로 나왔다. 저장 함수 첫 줄의 DELETE FROM user_tags WHERE user_id = ?였다. 신규 회원이라 지울 태그가 없었고, 그 빈 검색이 간격을 잠갔다. 귀찮아서 고른 지우고 다시 넣기가 범인이었다는 걸 알고 꽤 허탈했다.
복원한 순서를 로컬에서 세션 두 개로 재현해 보았다.
CREATE TABLE user_tags (
id BIGINT AUTO_INCREMENT PRIMARY KEY,
user_id BIGINT NOT NULL,
tag VARCHAR(30) NOT NULL,
UNIQUE KEY uk_user_tag (user_id, tag)
) ENGINE=InnoDB;
INSERT INTO user_tags (user_id, tag) VALUES (100, 'book'), (200, 'golf');
-- 세션 A
START TRANSACTION;
DELETE FROM user_tags WHERE user_id = 150; -- (100)~(200) 간격에 갭 락
-- 세션 B
START TRANSACTION;
DELETE FROM user_tags WHERE user_id = 160; -- 같은 간격에 갭 락, 충돌 없음
-- 세션 A
INSERT INTO user_tags (user_id, tag) VALUES (150, 'camping'); -- B의 갭 락에 막혀 대기
-- 세션 B
INSERT INTO user_tags (user_id, tag) VALUES (160, 'running'); -- ERROR 1213 (40001): Deadlock found행이 너무 적으면 옵티마이저가 인덱스 대신 전체 스캔을 고를 수 있다. 그러면 잠금 양상이 달라지니 EXPLAIN으로 DELETE가 uk_user_tag를 타는지 먼저 확인한다. 재현한 뒤 받은 로그가 운영 로그와 같은 꼴로 나왔을 때 비로소 안심했다.
지금 로그를 읽는 순서
고친 방법은 단순하다. 지우기 전에 잠금 없는 SELECT로 기존 태그를 읽고, 행이 있을 때만 기본 키로 지운다. 존재하는 행을 기본 키 등호로 지우면 rec but not gap, 즉 레코드 하나만 잠근다. 빈 간격을 잠글 일이 사라지자 교착 알림도 멈췄다. 이 트랜잭션만 READ COMMITTED로 돌리는 방법도 따져 봤다. 그 격리 수준에서는 검색과 인덱스 스캔에 갭 락을 쓰지 않는다. 다만 다른 쿼리의 읽기 결과까지 달라질 수 있어서 이번에는 쓰지 않았다. 1213 에러가 나면 트랜잭션을 한 번 다시 시도하는 코드는 그대로 남겨 두었다. 교착은 줄일 수 있어도 완전히 없애기는 어렵기 때문이다.
요즘 교착 로그를 열면 순서가 정해져 있다. 쿼리 줄은 맨 마지막에 본다. 먼저 waiting이 붙은 줄의 꼬리말을 읽고, 인덱스 이름과 hex 값으로 어느 간격인지 짚는다. 그 다음 쥔 잠금을 보고, 그 잠금을 건 문장이 무엇일지 코드에서 찾는다. 로그에 찍힌 문장은 사건의 마지막 장면일 뿐이고, 원인은 대개 그 앞 장면에 있다. 그날 이후로 쿼리 두 줄만 보고 창을 닫는 버릇은 버렸다.