MySQL Lock 상황 문제 해결
최근 중국어 공부에 집중하느라 개발 관련해서는 느슨하게 지내고 있었는데 장애 처리 상황이 발생하여 해결했던 내용을 공유합니다.
장애 상황
외부에서 받은 데이터를 DB로 업로드 하는 프로그램이 있는데 평소에 잘 실행되던 프로그램이 특정 파일에 대해서만 저장이 되지 않는 문제가 발생하였습니다. 이 프로그램은 Spring Boot로 만들어진 프로그램으로 에러 메시지는 다음과 같은 에러 메시지가 나타납니다.
Lock wait timeout exceeded; try restarting transaction
이런 상황이 되면 많은 개발자의 반응은 "조금 전까지 잘 돌아가던 프로그램이었어요! 왜 안돌아가는지 모르겠어요?" 일 것입니다. 그리고 timeout이 발생했으니 DB 서버 성능에 문제가 있는 것이 아닌가 하는 의심도 하게 됩니다. 물론 에러 메시지의 처음이 Lock으로 시작하니 DB 서버의 성능 문제는 아닐테고, 트렌젝션 Lock 관련 문제일 가능성이 높을 것입니다.
문제 해결 과정
일단 해당 메시지로 구글링을 해보니 대략 lock timeout 시간을 늘려주라는 것과 LOCK 테이블에 lock이 존재하는지 확인해보라는 두가지 해결 방법이 대부분이었는데 lock timeout을 늘려주는 것은 해결 방법이 아닌 것으로 판단해서 LOCK 테이블에 어떤 lock이 존재하는지 확인해보았습니다.
첫 질의 결과는 다음과 같이 아무것도 나타나지 않았습니다
1 2 3 4 5mysql> use information_schema; mysql> select * from INNODB_LOCKS; Empty set (0.00 sec) mysql> select * from INNODB_LOCK_WAITS; Empty set (0.00 sec)
다음으로 확인해본 사항은 실제 문제가 발생한 프로그램이 실행중인 경우에는 lock이 어떻게 생성되는지 확인을 하기 위해 프로그램을 실행하고 동일한 테이블을 확인해 보았습니다. 아래 결과와 같이 INNODB_LOCKS에 두개의 LOCK이 있고, INNODB_LOCK_WAITS 테이블에는 하나가 있습니다.
1 2 3 4 5 6 7mysql> select * from INNODB_LOCKS; +---------------------------+-------------+-----------+-----------+----------------+-----------+------------+-----------+----------+--------------------------+ | lock_id | lock_trx_id | lock_mode | lock_type | lock_table | lock_index| lock_space | lock_page | lock_rec | lock_data | +---------------------------+-------------+-----------+-----------+----------------+-----------+------------+-----------+----------+--------------------------+ | 4803511645:5119:10714:654 | 4803511645 | X | RECORD | `test`.`order` | order_ix1 | 5119 | 10714 | 654 | 'OR', '10', NULL, 569897 | | 4798336359:5119:10714:654 | 4798336359 | X | RECORD | `test`.`order` | order_ix1 | 5119 | 10714 | 654 | 'OR', '10', NULL, 569897 | +---------------------------+-------------+-----------+-----------+----------------+-----------+------------+-----------+----------+--------------------------+
1 2 3 4 5 6mysql> select * from INNODB_LOCK_WAITS; +-------------------+---------------------------+-----------------+---------------------------+-------------------+-----------------+ | requesting_trx_id | requested_lock_id | blocking_trx_id | blocking_lock_id | requesting_thd_id | blocking_thd_id | +-------------------+---------------------------+-----------------+---------------------------+-------------------+-----------------+ | 4803511645 | 4803511645:5119:10714:654 | 4798336359 | 4798336359:5119:10714:654 | 185111677 | 168670720 | +-------------------+---------------------------+-----------------+---------------------------+-------------------+-----------------+
이 상태의 의미를 해석하면 다음과 같습니다.
- INNODB_LOCK_WAITS에 있는 4803511645 트렌젝션은 4798336359(blocking_trx_id) 트렌젝션 때문에 Lock 이 잡혔고 이 Lock이 해제되기를 기다리고 있는 상황
- 4798336359 트렌젝션은 다른 LOCK을 기다리지 않고 자기 자신이 LOCK을 잡은 상태에서 처리가 완료되기를 기다리고 있는 상태
여기까지 상태를 확인한 프로그램이 동작이 완료되기를 기다린 후(물론 동일하게 Lock Timeout 에러는 발생) 다시 위 두 테이블을 확인해보면 모든 LOCK이 없어졌습니다. 이 상태로 유추를 해보면
프로그램 중에 어떤 형태로 멀티 쓰레드가 동작하고, 각 쓰레드에서 동일한 레코드에 대해 수정 처리를 하지만 하나가 Commit이나 Rollback을 하지 않는다.
같이 생각할 수 있습니다.
하지만 해당 프로그램을 아무리 살펴보아도 멀티 쓰레드로 동작하지 않고 Spring Boot에 JPA 기반으로 개발되어 있기 때문에 개발자가 트렌젝션을 관리하지도 않고 있는 코드였습니다. 다시 한번 문제가 발생한 프로그램을 실행하고 위의 두개 LOCK 테이블을 확인해보는 중에 다음과 같은 이상한 점을 발견했습니다.
1 2 3 4 5 6 7mysql> select * from INNODB_LOCKS; +---------------------------+-------------+-----------+-----------+-----------------+-----------+------------+-----------+----------+--------------------------+ | lock_id | lock_trx_id | lock_mode | lock_type | lock_table | lock_index| lock_space | lock_page | lock_rec | lock_data | +---------------------------+-------------+-----------+-----------+-----------------+-----------+------------+-----------+----------+--------------------------+ | 5903511900:5119:10714:654 | 5903511900 | X | RECORD | `test`.`oreder` | order_ix1 | 5119 | 10714 | 654 | 'OR', '10', NULL, 569897 | | 4798336359:5119:10714:654 | 4798336359 | X | RECORD | `test`.`orsxer` | order_ix1 | 5119 | 10714 | 654 | 'OR', '10', NULL, 569897 | +---------------------------+-------------+-----------+-----------+-----------------+-----------+------------+-----------+----------+--------------------------+
여전히 두개의 LOCK이 나타나지만 하나는 이전에 봤던 LOCK과 다른 ID를 가지고 있지만, 하나는 이전의 LOCK과 동일한 ID(4798336359)를 가지고 있는 것을 확인할 수 있습니다. 이 의미는 하나는 실행시킨 프로그램에 의해서 생성된 LOCK 이지만 동일한 ID를 가지고 있는 LOCK은 이 프로그램과 상관없이 다른 프로그램이 LOCK을 잡고 있다는 것을 예상할 수 있었습니다.
여기서 MySQL의 Lock 관련 테이블이 어떤 용도로 사용하는지 확인을 해 보았습니다.
- MySQL 매뉴얼 페이지: InnoDB INFORMATION_SCHEMA Transaction and Locking Information
- INNODB_TRX:
- Provides information about every transaction currently executing inside InnoDB, including the transaction state (for example, whether it is running or waiting for a lock), when the transaction started, and the particular SQL statement the transaction is executing.
- 검색 결과로 나타나는 많은 페이지에서는 이 테이블에 대한 언급이 없었습니다. 이 테이블이 가장 중요한 테이블이라고 볼 수 있습니다.
- 오랜 시간 동안 Commit 되지 않은 트렌젝션을 보려면 이 테이블을 보면 확인 가능합니다.
- INNODB_LOCKS:
- The INNODB_LOCKS table provides information about each lock that an InnoDB transaction has requested but not yet acquired, and each lock that a transaction holds that is blocking another transaction.
- 핵심 키워드는 "not yet acquired" 와 "blocking another transaction" 입니다. 이 두개가 아닌 LOCK은 이 테이블에 나타나지 않습니다. 즉 위에 상황에서 문제가 발생한 프로그램이 종료되었을 때에는 이 테이블에는 아무런 레코드가 존재하지 않게 됩니다.
- https://dev.mysql.com/doc/refman/5.6/en/innodb-locks-table.html
- INNODB_LOCK_WAITS:
- This table indicates which transactions are waiting for a given lock, or for which lock a given transaction is waiting.
- 이 테이블은 아직 LOCK을 얻지 못하고 기다리고 있는 트렌젝션을 관리합니다.
그래서 처음에 확인한 INNODB_LOCKS, INNODB_LOCK_WAITS 테이블이 아닌 INNODB_TRX 테이블을 확인해 보았습니다.
1 2 3 4 5 6 7 8mysql> select * from INNODB_TRX; +-----------------+-----------+---------------------+-----------------------+------------------+------------+---------------------+ | trx_id | trx_state | trx_started | trx_requested_lock_id | trx_wait_started | trx_weight | trx_mysql_thread_id | +-----------------+-----------+---------------------+-----------------------+------------------+------------+---------------------+ | 4798336359 | RUNNING | 2018-11-09 12:43:53 | NULL | NULL | 4 | 184601385 | | 4799666638 | RUNNING | 2018-11-09 12:40:17 | NULL | NULL | 5 | 100997123 | | 421494077679720 | RUNNING | 2018-11-09 19:23:32 | NULL | NULL | 0 | 167903301 | +-----------------+-----------+---------------------+-----------------------+------------------+------------+---------------------+
이 테이블은 문제가 발생한 프로그램 실행 여부와 상관없이 해당 LOCK(4798336359)이 계속 존재하는 것을 볼 수 있습니다. 즉, 다른 프로그램에 의해 해당 LOCK이 발생을 하였고, 이 LOCK으로 인해 정상적으로 수행되어야 하는 프로그램에 문제가 발생한 것이었습니다.
문제를 알았으니 해결 방법은 간단합니다. INNODB_TRX 테이블에서 알려준 thread_id가 무엇인지 확인하고 해당 프로그램에서 발생시킨 트렌젝션을 종료시키거나 강제로 종료하면 됩니다. 필자의 경우 MySQL 명령을 이용하여 강제로 중지 시켰습니다.
1 2 3 4 5 6 7 8mysql> show processlist; +-----------+------------------+---------------------+------------------------+---------+--------+-------+------------------+ | Id | User | Host | db | Command | Time | State | Info | +-----------+------------------+---------------------+------------------------+---------+--------+-------+------------------+ | 184601385 | test | 10.26.205.20:36040 | test | Sleep | 653 | | NULL | | 33627939 | test | 10.26.205.20:36962 | test | Sleep | 50 | | NULL | +-----------+------------------+---------------------+------------------------+---------+--------+-------+------------------+ mysql> kill 184601385;
MySQL 관련 문제 발생 시 show processlist 명령도 많이 사용하는 명령 중의 하나인데 위와 같은 LOCK 상황에서는 Sleep 상태로 나타나서 이것만 보면 DB 서버쪽에서는 문제없는 것으로 오해할 가능성도 있을 것 같습니다. 실제로 필자도 처음에는 그렇게 슬쩍 넘어 갔습니다.