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

안녕하세요, BlueByte입니다. 평소 밀리초 만에 끝나던 UPDATE 가 1분 가까이 멈춰 있다가 ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction 으로 실패합니다. 망가진 것은 없습니다. 다른 트랜잭션이 우리 문장이 필요로 하는 행 잠금을 쥐고 있고, InnoDB 는 설정된 시간만큼 정확히 기다린 뒤 포기한 것입니다. 오늘은 이 메시지와 변형들, 그 잠금이 아직 남아 있는 이유, 블로커가 사라지기 전에 지목하는 법, 원인별 해결, 그리고 재시도 전에 무엇이 롤백됐는지까지 하나씩 짚어보겠습니다.

1205 가 보고하는 것과 드라이버가 바꾸는 모양

클라이언트에서는 한 줄입니다.

mysql> UPDATE orders SET status = 'paid' WHERE id = 4711;
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

MySQL 에러 레퍼런스는 이것을 error number 1205, symbol ER_LOCK_WAIT_TIMEOUT, SQLSTATE HY000, message Lock wait timeout exceeded; try restarting transaction 으로 싣고 있습니다. 드라이버는 이 문구를 바꾸지 않고 감싸기만 하므로, 같은 실패가 PDO 에서는 SQLSTATE[HY000]: General error: 1205 Lock wait timeout exceeded 로, ORM 에서는 커넥션 풀 스택 트레이스 안에 묻혀서 도착합니다. 어떤 래퍼를 거쳐도 살아남는 것은 두 가지, 숫자 1205 와 SQLSTATE HY000 입니다. 데드락은 1213 과 SQLSTATE 40001 이라는 다른 짝을 달고 오고, 둘은 서로 다른 대응을 요구합니다. 이 영역의 혼동은 대부분 여기서 시작합니다.

문장이 포기하는 순간에도 행 잠금이 남아 있는 이유

InnoDB 는 트랜잭션이 행을 건드릴 때 잠금을 잡고 COMMIT 또는 ROLLBACK 에서 풉니다. 기다림이 만료됐다는 것은 다른 트랜잭션이 둘 중 어느 쪽에도 닿지 못했다는 뜻입니다.

• 세션이 트랜잭션을 열어 둔 채 놀고 있는 경우입니다. 명시적인 START TRANSACTION, 또는 클라이언트나 프레임워크가 꺼 둔 autocommit 뒤에 화면 하나, 네트워크 왕복 한 번, 자리를 비운 사람 하나가 끼어 있습니다.
• 긴 문장은 실행 내내 잠금을 붙들고 있습니다. 수백만 행짜리 UPDATE, 범위가 넓은 SELECT ... FOR UPDATE, 트랜잭션 하나로 감싼 임포트가 그렇습니다.
• 쓸 만한 인덱스가 없는 UPDATE ... WHERE 나 SELECT ... FOR UPDATE 는 조건에 맞은 행이 아니라 스캔한 행을 잠급니다. 작아 보이는 문장이 넓은 구간을 묶어 두는 이유입니다.
• 두 작업이 같은 행을 다른 순서로 건드리면서, 한쪽이 타임아웃을 넘길 만큼 다른 쪽 뒤에 줄을 서기도 합니다.

시계 역할을 하는 값은 초 단위의 innodb_lock_wait_timeout 입니다. 매뉴얼의 속성 표는 Default Value 50, Minimum Value 1, Maximum Value 1073741824, Scope Both, Dynamic Yes 로 적고 있습니다. 50초를 기다리는 것은 멈춘 것이 아니라 기본 동작입니다.

sys.innodb_lock_waits 로 막고 있는 세션을 지목하기

기다리는 중에 물어보셔야 합니다. 이 행은 누군가 대기하는 동안에만 존재합니다.

SELECT waiting_pid, waiting_query, wait_age, blocking_pid,
       blocking_query, sql_kill_blocking_connection
FROM sys.innodb_lock_waits\G

*************************** 1. row ***************************
                 waiting_pid: 812
               waiting_query: UPDATE orders SET status = 'paid' WHERE id = 4711
                    wait_age: 00:00:41
                blocking_pid: 774
              blocking_query: NULL
sql_kill_blocking_connection: KILL 774

blocking_query 가 NULL 로 나오면 당황하기 쉽지만, 문서에 적힌 정상 동작입니다. 막고 있는 세션이 유휴 상태가 되면 이 칼럼은 NULL 을 돌려줍니다. 막다른 길이 아니라 그 자체가 답입니다. 블로커는 문장을 돌리는 중이 아니라 열린 트랜잭션 위에 앉아 있습니다. 뷰는 바로 쓸 수 있는 문장도 두 개 건네줍니다. sql_kill_blocking_query 는 막고 있는 문장을, sql_kill_blocking_connection 은 그 문장을 돌리는 세션을 끊습니다.

죽이기 전에 INNODB_TRX 로 교차 확인하기

SELECT trx_id, trx_state, trx_started, trx_mysql_thread_id, trx_rows_locked, trx_query
FROM information_schema.innodb_trx ORDER BY trx_started;

trx_state 는 잠금을 기다리는 트랜잭션에 LOCK WAIT, 기다리지 않는 트랜잭션에 RUNNING 을 보여줍니다. trx_started 와 같이 읽으세요. 20분 전에 시작했는데 trx_query 가 비어 있는 블로커는 유휴 트랜잭션 쪽이고, 몇 초 전에 시작했는데 trx_rows_locked 가 큰 블로커는 배치 쪽입니다. 잠금 단위로 더 보고 싶다면 performance_schema.data_locks 에 특정 행이나 테이블을 기다리는 잠금 큐가, performance_schema.data_lock_waits 에 어떤 보유 잠금이 어떤 요청을 막고 있는지가 들어 있습니다.

원인별 해결, 가장 싼 수부터

유휴 블로커라면 그 세션에서 COMMIT 이나 ROLLBACK 을 하게 하거나, 뷰가 만들어 준 KILL 을 실행하세요. 커넥션을 끊으면 그 트랜잭션은 롤백됩니다. 유휴 세션에는 무해하지만, 절반쯤 진행된 배치에는 비쌉니다. 그동안 한 일을 전부 되돌려야 하기 때문입니다.

KILL 774;

Query OK, 0 rows affected (0.00 sec)

인덱스가 없는 조건이라면, 매뉴얼이 잠금 경합에 대해 권하는 방법 그대로입니다. SELECT ... FOR UPDATE 와 UPDATE ... WHERE 에 쓰이는 칼럼에 인덱스를 만드는 것입니다. 실행 계획을 먼저 보고 인덱스를 추가하세요.

EXPLAIN UPDATE orders SET status = 'paid' WHERE customer_ref = 'C-91823';
ALTER TABLE orders ADD INDEX idx_orders_customer_ref (customer_ref);

트랜잭션이 길다면, 데이터를 넣거나 바꾸는 트랜잭션을 오래 열려 있지 않을 만큼 작게 유지하고 배치를 한 번에 몰지 말고 나눠 커밋하세요. 어떤 작업이 정말로 더 긴 대기를 필요로 한다면, 서버 기본값은 그대로 두고 그 세션에서만 올리면 됩니다.

SET SESSION innodb_lock_wait_timeout = 120;

재시도 로직을 쓰기 전에 읽어야 할 것

매뉴얼은 범위를 분명히 적습니다. lock wait timeout 은 InnoDB 가 현재 문장, 즉 잠금을 기다리다 타임아웃을 만난 그 문장을 롤백하게 만듭니다. 트랜잭션 전체를 롤백하려면 서버를 --innodb-rollback-on-timeout 을 켜고 시작해야 합니다. 기본 동작에서는 문장을, 그 옵션이 켜져 있으면 트랜잭션 전체를 재시도하라는 것입니다.

즉 기본값에서는 1205 이후에도 트랜잭션이 열린 채이고, 앞서 잡은 잠금을 전부 쥐고 있습니다. 같은 트랜잭션 안에서 실패한 문장만 다시 돌리는 재시도 루프는 그 잠금을 그대로 들고 다시 타임아웃을 맞는 일이 잦습니다. 지금 어느 동작인지부터 확인하세요.

SELECT @@innodb_lock_wait_timeout, @@innodb_rollback_on_timeout;

+----------------------------+------------------------------+
| @@innodb_lock_wait_timeout | @@innodb_rollback_on_timeout |
+----------------------------+------------------------------+
|                         50 |                            0 |
+----------------------------+------------------------------+

innodb_rollback_on_timeout 은 global 이고 dynamic 이 아니므로, 바꾸려면 SET GLOBAL 이 아니라 재시작이 필요합니다.

실제 사례: 야간 정산이 결제를 막은 밤

야간 정산 작업이 01:00 에 시작해 인덱스가 없는 customer_ref 칼럼으로 orders 를 갱신합니다. 01:02 부터 결제 쓰기가 1205 로 실패하기 시작합니다. sys.innodb_lock_waits 에는 waiting_pid: 812, wait_age: 00:00:41, blocking_pid: 774, 그리고 NULL 인 blocking_query 가 보입니다. information_schema.innodb_trx 를 보면 774 번 세션은 01:00:07 에 시작해 RUNNING 상태이고 trx_rows_locked 가 수십만입니다. 정산이 테이블 전체를 스캔하면서 스캔한 것을 그대로 잠근 것입니다. 당직자는 이것을 죽이지 않습니다. 롤백이 실행만큼 오래 걸리기 때문입니다. 작업을 끝까지 두자 01:09 에 결제가 회복됩니다. 다음 날 아침에 들어간 수정은 두 가지였습니다. customer_ref 인덱스, 그리고 5,000 행마다 커밋. 그다음 밤에는 trx_rows_locked 가 수백 수준에서 머물렀고 결제 쪽은 작업이 도는 줄도 몰랐습니다.

정말 사라졌는지 확인하고 그 상태를 유지하기

실패했던 문장을 다시 실행해 보세요. 즉시 돌아와야 합니다. 그다음 누군가 뒤에 줄 서 있지는 않은지 봅니다.

SELECT COUNT(*) AS waiters FROM sys.innodb_lock_waits;
SELECT trx_mysql_thread_id, trx_state, TIMESTAMPDIFF(SECOND, trx_started, NOW()) AS age_s
FROM information_schema.innodb_trx WHERE TIMESTAMPDIFF(SECOND, trx_started, NOW()) > 60;

첫 결과가 0 이고 두 번째 질의에 행이 없다면 건강한 상태입니다. 그 상태를 유지하는 방법은 두 번째 질의에 알람을 거는 것입니다. 1분 넘게 살아 있는 트랜잭션이 모든 1205 의 원재료입니다. 여기에 같은 테이블을 건드리는 작업들이 행을 같은 순서로 잡도록 맞춰 두면 경합 자체가 줄어듭니다.

1213·metadata lock 대기와의 차이

데드락은 줄이 아니라 고리입니다. 두 트랜잭션이 서로가 필요한 것을 쥐고 있는 상태로, InnoDB 가 이를 감지해 희생자를 골라 그 트랜잭션을 통째로 롤백하고 1213 과 SQLSTATE 40001 을 보고합니다. 이쪽은 트랜잭션 전체를 재시도하면 됩니다. 둘을 잇는 지점도 하나 있습니다. innodb_deadlock_detect 로 데드락 감지를 끄면 InnoDB 는 데드락이 생겼을 때 innodb_lock_wait_timeout 에 기대어 트랜잭션을 롤백하므로, 진짜 데드락이 1205 로 나타납니다. 비슷해 보이지만 InnoDB 행 잠금이 아예 아닌 경우도 있습니다. 열린 트랜잭션 뒤에서 멈춘 DDL 은 metadata lock 을 기다리는 것이고, 이것은 InnoDB 잠금 테이블이 아니라 performance_schema.metadata_locks 로 드러납니다.

다음에 쓰기가 1205 로 죽으면 이 순서를 거꾸로 따라가 보세요. 실제로 받은 에러 번호와 SQLSTATE 는 무엇인지, sys.innodb_lock_waits 가 누구를 블로커로 지목하는지, 그 블로커가 innodb_trx 에서 유휴인지 바쁜지를 본 뒤에야 기다릴지, 끊을지, 인덱스를 만들지 고르면 됩니다.