jest 테스트 도중 만난 트랜잭션 데드락

테스트 코드를 돌리던 중 데드락을 발견했다.

데드락 해결하기

결론적으로 큰 문제는 아니었다. jest 자체가 worker를 이용해서 테스트 코드를 병렬적으로 실행하기 때문에 unique key가 걸린 user 테이블에 레코드 락이 걸려서 데드락이 발생하는 것이었다.

jest-config.json파일의 maxWorkers를 조정하여 병렬적으로 테스트 하지 않도록 일단 수정해놓았다.

{
  "preset": "ts-jest",
  "testEnvironment": "node",
  "moduleFileExtensions": ["ts", "js"],
  "transform": {
    "^.+\\.(ts)$": ["ts-jest", {
      "babel": true,
      "tsconfig": "tsconfig.json"
    }]
  },
  "testMatch": ["<rootDir>/test/**/*.(test|spec).(ts)"],
  "maxWorkers": 1
}

이렇게 수정하고 나니 더는 데드락이 발견되지 않았다.

더 알아보기

사실 트랜잭션 데드락을 직접 목격한 것이 처음이라 정확히 어떤 경우로 데드락이 걸렸는지 궁금해져서 로그를 열어보기로 했다.

mysql에서 트랜잭션 로그가 출력되도록 설정하기

mysql의 설정을 바꾸기 위해선 my.cnf 파일을 수정해주어야 한다. 근데 my.cnf 파일은 고정된 경로에 있는 my.cnf 파일을 읽어서 설정정보를 초기화 하는 것이 아니다.

특정 경로에 있는 my.cnf 파일 중 우선순위가 높은 설정 정보를 읽는다.

mysql --help

이 명령어를 통해 내 mysql의 my.cnf 우선순위를 찾을 수 있는데

이 순서로 조회되는 것을 볼 수 있고 우선순위 3번째는 설치한 mysql 경로에 따라 달라질 수 있는 것 같다.

1. /etc/my.cnf
2. /etc/mysql/my.cnf
3. /opt/homebrew/etc/my.cnf ~/.my.cnf

이 호스트에는 3순위에 my.cnf 파일을 수정했다.

이렇게 전역옵션으로 innodb_print_all_deadlocks를 참으로 설정했다. 이를 통해 mysql 로그에 데드락이 걸리면 데드락에 대한 로그를 출력시켜준다.

[mysqld]
innodb_print_all_deadlocks = 1

트랜잭션 로그 보기

jest-config.json을 다시 롤백하고 트랜젝션 데드락을 유발하고 로그를 까보았다.

트랜잭션 데드락에 대한 본문의 내용은 이러하다.

TRANSACTION 34728, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1128, 2 row lock(s), undo log entries 1
MySQL thread id 92, OS thread handle 6193836032, query id 2776 localhost 127.0.0.1 root update
insert into user(name, password) values('test1', '1234')
RECORD LOCKS space id 25 page no 5 n bits 80 index name of table `mydb`.`user` trx id 34728 lock mode S
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

RECORD LOCKS space id 25 page no 5 n bits 80 index name of table `mydb`.`user` trx id 34728 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

TRANSACTION 34729, ACTIVE 0 sec inserting
mysql tables in use 1, locked 1
LOCK WAIT 4 lock struct(s), heap size 1128, 2 row lock(s), undo log entries 1
MySQL thread id 93, OS thread handle 6191607808, query id 2777 localhost 127.0.0.1 root update
insert into user(name, password) values('test1', '1234')
RECORD LOCKS space id 25 page no 5 n bits 80 index name of table `mydb`.`user` trx id 34729 lock mode S
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

RECORD LOCKS space id 25 page no 5 n bits 80 index name of table `mydb`.`user` trx id 34729 lock_mode X insert intention waiting
Record lock, heap no 1 PHYSICAL RECORD: n_fields 1; compact format; info bits 0
 0: len 8; hex 73757072656d756d; asc supremum;;

트랜잭션 로그 분석하기

일단 두 개의 insert문을 위한 RECORD lock을 S 즉 Shared 모드로 걸었고

두 개의 트랜잭션이 각각 exclusive 모드 락으로 변경하기 위해 대기중인것으로 볼 수 있다.

다만 innoDB 엔진은 레코드 락을 걸 때 index에 락을 건다고 공부했다. 이때 락을 걸고 싶은 칼럼에 대한 인덱스 즉 name에 대한 인덱스가 없을 땐 pk에 대한 인덱스에 락을 건다.

하지만 user 테이블은 pk가 bigint에 auto_increment 인 상태이다 보니 pk가 아직 없는데 어떻게 락을 거는건지 궁금했다

insert 쿼리가 lock을 걸기전에 auto_increament 값이 할당이 되어 그 id 레코드에 락이 걸린다는 뜻인데

결국 두 번째 트랜잭션도 Insert 쿼리가 실행되서 auto_increment 값을 할당 받으면 그 값은 첫 번째 insert 쿼리의 pk 값과 다르니까 인덱스를 잠글 수 없는 것 아닐까 라는 생각이 들었다.

결론적으로 락 이런 경우 락 엘리베이션이 일어나서 레코드 락, 페이지 락, 테이블 락 순으로 락 수준이 올라갈 수 있다고 한다.

InnoDB가 레코드 락을 얻으려 시도할 때 해당 레코드가 속한 페이지에 대해 다른 쿼리가 많거나, 경쟁 조건이 발생하면 페이지 레벨으로 락 엘리베이션을 한다고 한다.