MySQL Lock Deadlock (1) 기본편

해리포터에 모두가 두려워하는 존재 볼드모트가 있다면, 데이터베이스 세계에서는 Deadlock이 있습니다. 원인은 다양한데, Deadlock은 100%확률로 발생하지도 않지만, 발생하고 나서는 원인을 찾기도 어렵습니다. 

 

실제로 Deadlock이 발생하는 증상을 재현시켜 보겠습니다.

 

 

먼저 테스트를 위한 테이터를 입력합니다.

CREATE TABLE users (
    id INTEGER AUTO_INCREMENT PRIMARY KEY,
    username VARCHAR(255) UNIQUE NOT NULL,
    created_at TIMESTAMP DEFAULT NOW()
)Engine=InnoDB CHARSET=utf8;

INSERT INTO users (username, created_at) VALUES 
('Kenton_Kirlin', '2017-02-16 18:22:10.846'), ('Andre_Purdy85', '2017-04-02 17:11:21.417'), 
('Harley_Lind18', '2017-02-21 11:12:32.574'), ('Arely_Bogan63', '2016-08-13 01:28:43.085');

 

 

 

생성한 users 테이블에 대해서 터미널을 2개 열고 각각 쿼리를 실행합니다.

트랜잭션 1	트랜잭션 2
START TRANSACTION;
	START TRANSACTION;
SELECT * FROM users WHERE id = 1 FOR UPDATE;
	SELECT * FROM users WHERE id=3 FOR UPDATE;
SELECT * FROM users WHERE id = 3 FOR UPDATE;
	SELECT * FROM users WHERE id = 1 FOR UPDATE;

 

위에서 부터 순서대로,

(1) 트랜잭션 1에서 id = 1에 대해서 X lock을 겁니다.

(2) 트랜잭션 2에서 id = 3에 대해서 X lock을 겁니다.

(3) 트랜잭션 1에서 id = 3에 대해서 X lock을 거는데, 트랜잭션 2에서 이미 X lock을 건 상태이기 때문에, blocking됩니다.

(4) 트랜잭션 2에서 id = 1에 대해서 X lock을 겁니다.

이렇게 되면 lock이 루프로 걸리는 상황이 되면서 Deadlock이 발생하게 됩니다.

 

 

(3) 에서 innodb_lock_wait_timeout 파라미터의 설정된 시간(디폴트 50초)동안 blocking됩니다. 이 시간 후에는 에러가 발생하게 됩니다.

ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

 

(4) 에서 Deadlock이 발생하는 상황이 되면, innoDB엔진이 innodb_deadlock_detect설정(디폴트 true)에 따라서 아래처럼 Deadlock을 감지해서 에러로 리턴해줍니다.

ERROR 1213 (40001): Deadlock found when trying to get lock; try restarting transaction

 

 

 

위의 예는 Deadlock을 이해하기 위한 이론적인 샘플입니다. 하지만, 실제 어플리케이션의 코드는 복잡해서 어느 쿼리가 Deadlock을 발생시키는지 바로 추적하는 것은 매우 힘든 일입니다.

 

 

그래서 MySQL의 lock관련 상태 정보를 얻을 수 있는 방법이 필요합니다. 아래 명령으로 상세한 상태 정보를 볼 수 있습니다.

show engine innodb status;

 

아래 내용은 위의 출력내용중에 Deadlock에 관련된 내용만 출력한 내용입니다.

------------------------
LATEST DETECTED DEADLOCK
------------------------
2021-09-28 03:13:39 0x2b8808bc4700
*** (1) TRANSACTION:
TRANSACTION 14169, ACTIVE 274 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 3 lock struct(s), heap size 1136, 4 row lock(s)
MySQL thread id 8, OS thread handle 47863275464448, query id 6820 192.168.127.186 admin statistics
SELECT * FROM users WHERE id = 3 FOR UPDATE
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 102 page no 3 n bits 72 index PRIMARY of table `test_db_210926`.`users` trx id 14169 lock_mode X locks rec but not gap waiting
Record lock, heap no 4 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
 0: len 4; hex 80000003; asc     ;;
 1: len 6; hex 000000003754; asc     7T;;
 2: len 7; hex b0000002d90128; asc       (;;
 3: len 13; hex 4861726c65795f4c696e643138; asc Harley_Lind18;;
 4: len 4; hex 58ac20a1; asc X   ;;

*** (2) TRANSACTION:
TRANSACTION 14170, ACTIVE 264 sec starting index read
mysql tables in use 1, locked 1
3 lock struct(s), heap size 1136, 2 row lock(s)
MySQL thread id 3, OS thread handle 47863262103296, query id 6821 1192.168.127.186 admin statistics
SELECT * FROM users WHERE id=1 FOR UPDATE
*** (2) HOLDS THE LOCK(S):
RECORD LOCKS space id 102 page no 3 n bits 72 index PRIMARY of table `test_db_210926`.`users` trx id 14170 lock_mode X locks rec but not gap
Record lock, heap no 4 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
 0: len 4; hex 80000003; asc     ;;
 1: len 6; hex 000000003754; asc     7T;;
 2: len 7; hex b0000002d90128; asc       (;;
 3: len 13; hex 4861726c65795f4c696e643138; asc Harley_Lind18;;
 4: len 4; hex 58ac20a1; asc X   ;;

*** (2) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 102 page no 3 n bits 72 index PRIMARY of table `test_db_210926`.`users` trx id 14170 lock_mode X locks rec but not gap waiting
Record lock, heap no 2 PHYSICAL RECORD: n_fields 5; compact format; info bits 0
 0: len 4; hex 80000001; asc     ;;
 1: len 6; hex 000000003754; asc     7T;;
 2: len 7; hex b0000002d90110; asc        ;;
 3: len 13; hex 4b656e746f6e5f4b69726c696e; asc Kenton_Kirlin;;
 4: len 4; hex 58a5edd3; asc X   ;;

*** WE ROLL BACK TRANSACTION (2)

 

 

위에서 4번째행의 16진수 정보는 thread ID를 의미합니다.

2021-09-28 03:13:39 0x2b8808bc4700

혹시, MySQL의 버그로 의심된다면, 이 정보 heap dump를 버그로 리포트할 수 도 있을 거 같습니다.

 

 

 

트랜잭션 1 에서 id = 3 대상으로 한  X lock을 획득하기 위해서 blocking되어 있는 내용의 로그도 보입니다.

SELECT * FROM users WHERE id = 3 FOR UPDATE
*** (1) WAITING FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 102 page no 3 n bits 72 index PRIMARY of table `test_db_210926`.`users` trx id 14169 lock_mode X locks rec but not gap waiting

 

 

마지막에 WE ROLL BACK TRANSACTION 메세지와 함께 rollback이 됩니다.

*** WE ROLL BACK TRANSACTION (2)

 

이 로그를 Deadlock 로그라고 하는데, 이 로그에서 어플리케이션의 코드를 추적하기 위해서는 Deadlock이 발생한 쿼리를 찾아야 합니다. 이 예에서는 트랜잭션1 의 경우는 SELECT * FROM users WHERE id = 3 FOR UPDATE 이고, 트랜잭션 2의 경우는 SELECT * FROM users WHERE id=1 FOR UPDATE 입니다. 이 쿼리 정보를 가지고 문제가 되었던 어플리케이션의 소스를 확인하는 단서로 이용할 수 있을 것입니다.

 

 

이렇게 문제가 발생한 Deadlock에 대해서 정보를 수집하는 내용을 살펴 보았습니다.

그런데, 아래 2개 파라미터로 일이 커지게 전에 문제를 해결 하는 방법을 MySQL은 제공합니다.

 

innodb_lock_wait_timeout 파라미터로 Deadlock에 의해서 blocking되는 시간을 지정할 수 있습니다. 

innodb_deadlock_detect 파라미터를 설정하면, 자동으로 Deadlock을 감지해서 rollback해줍니다.

 

파라미터명	디폴트 값	비고
innodb_lock_wait_timeout	50	초
innodb_deadlock_detect	on	true/false

 

 

이렇게 간단한 예로 Deadlock이 발생하는 경우를 살펴 보았습니다.