본문으로 건너뛰기

SIGKILL로 확인한 커밋과 롤백

첫 번째 실험에서는 BOOKED → CANCELLED를 COMMIT한 뒤 mysqld를 종료했습니다. 두 번째 실험에서는 CANCELLED → REFUNDING을 COMMIT하지 않은 상태로 종료했습니다.

실험 환경

항목
MySQL8.4.10
Container Imagemysql:8.4
저장 공간Docker named volume
Buffer Pool128MiB
innodb_flush_log_at_trx_commit1
innodb_log_writer_threads1
종료 방식SIGKILL
종료 코드137

테이블은 다음처럼 만들었습니다.

sql
CREATE TABLE reservations (
id BIGINT NOT NULL PRIMARY KEY,
status VARCHAR(20) NOT NULL,
notes BLOB NOT NULL
) ENGINE=InnoDB;

INSERT INTO reservations (id, status, notes)
VALUES (1, 'BOOKED', REPEAT('B', 7000));

LSN 변화를 관찰하기 위해 status와 함께 7,000바이트의 notes도 바꿨습니다.

기록한 값

각 시점에 다음 전역 상태값을 기록했습니다.

  • Innodb_redo_log_current_lsn
  • Innodb_redo_log_flushed_to_disk_lsn
  • Innodb_redo_log_checkpoint_lsn

LSN은 트랜잭션이나 행의 번호가 아니라 서버 전체 Redo Stream의 위치입니다. Server Status Variables도 Current LSN, Flushed-to-disk LSN과 Checkpoint LSN을 구분합니다.

따라서 실험 전후 LSN 차이를 id=1 한 행이 만든 Redo 크기로 해석할 수 없습니다. 같은 시간에 발생한 InnoDB 내부 작업도 전역 LSN을 전진시킬 수 있습니다.

실험 A: COMMIT한 CANCELLED

먼저 id=1CANCELLED로 바꾸고 COMMIT했습니다.

sql
START TRANSACTION;

UPDATE reservations
SET status = 'CANCELLED',
notes = REPEAT('C', 7000)
WHERE id = 1;

COMMIT;

변경 전과 COMMIT 뒤에 관찰한 값입니다.

시점Current LSNFlushed-to-disk LSNCheckpoint LSN상태
변경 전29,593,26329,593,26329,523,001BOOKED
COMMIT 뒤29,610,30429,610,30429,523,001CANCELLED

Current LSN과 Flushed-to-disk LSN은 17,041 증가했고, 관찰 시점에는 두 값이 같았습니다. Checkpoint LSN은 그대로였습니다.

innodb_flush_log_at_trx_commit=1이면 COMMIT에서 Redo write와 durable flush를 기다립니다. 저장 계층이 flush 요청을 정상적으로 처리한다는 전제입니다.

Checkpoint가 전진하지 않은 상태에서도 COMMIT은 끝났습니다. 이는 Data Page Flush가 COMMIT 완료 조건이 아니라는 설명과 맞습니다. 하지만 이 표만으로 id=1의 Data Page가 아직 Flush되지 않았다고 증명할 수는 없습니다. Page Cleaner가 종료 전에 해당 Page를 저장했을 가능성도 있습니다.

첫 번째 SIGKILL 뒤 Redo Recovery

COMMIT 뒤 Container에 SIGKILL을 보냈고 같은 named volume으로 다시 시작했습니다. 재시작 로그에는 다음 내용이 남았습니다.

text
Database was not shutdown normally!
Starting crash recovery.
Doing recovery: scanned up to log sequence number 29610314
Applying a batch of 73 redo log records ...
Apply batch completed!

재시작 뒤 행을 조회한 결과입니다.

text
id status note_marker
1 CANCELLED C

여기서 73은 행이나 개별 Redo Record 수가 아닙니다. MySQL 8.4.10 소스상 해당 Recovery Batch에 등록된 Page address entry 수입니다. 출력 코드recv_sys->n_addrs를 사용합니다. 이 로그만으로 id=1의 Redo가 실제 적용됐다고 볼 수는 없습니다.

실험 B: COMMIT하지 않은 REFUNDING

첫 번째 재시작 뒤 값은 CANCELLED였습니다. 이번에는 새 Transaction을 열고 REFUNDING으로 바꾼 뒤 COMMIT하지 않았습니다.

sql
START TRANSACTION;

UPDATE reservations
SET status = 'REFUNDING',
notes = REPEAT('U', 7000)
WHERE id = 1;

SELECT status
FROM reservations
WHERE id = 1;

SELECT SLEEP(600);

강제 종료 전에는 다음 상태를 확인했습니다.

text
변경한 세션
status = REFUNDING

다른 세션
status = CANCELLED

information_schema.innodb_trx에서는 수정 중인 Transaction이 보였습니다.

text
trx_state trx_rows_modified
RUNNING 1

InnoDB Monitor에도 Undo Entry가 남았습니다.

text
---TRANSACTION 2319, ACTIVE 3 sec
2 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 1

이 시점의 전역 표본과 InnoDB Monitor 기록은 다음과 같았습니다.

text
Current LSN = 29,672,903
Flushed-to-disk LSN = 29,672,903
Checkpoint LSN = 29,672,903
Pages flushed up to = 29,672,903
Modified db pages = 0

COMMIT하지 않았는데도 Flushed-to-disk LSN이 Current LSN까지 진행했습니다. 미완료 트랜잭션의 Redo도 영속화될 수 있다는 설명과 맞습니다.

Checkpoint LSN은 Current LSN까지 전진했고, 같은 표본에서 Modified db pages는 0이었습니다. 관찰 시점에 Buffer Pool이 추적하던 Dirty Page가 없었다는 뜻이며, 미커밋 변경도 COMMIT 전에 Flush될 수 있다는 STEAL 흐름과 맞습니다. 다만 REFUNDING을 담은 개별 Page ID나 Data File의 바이트를 대조하지 않았으므로, 그 Page가 실제로 저장됐다고 이 표본만으로 단정할 수는 없습니다.

두 번째 SIGKILL 뒤 Transaction Rollback

열린 Transaction을 그대로 둔 채 다시 SIGKILL을 보냈습니다. 두 번째 재시작의 Redo Application Batch는 0이었습니다.

text
Database was not shutdown normally!
Starting crash recovery.
Doing recovery: scanned up to log sequence number 29672903
Applying a batch of 0 redo log records ...
Apply batch completed!

이어 미완료 Transaction을 복원하고 Rollback한 로그가 남았습니다.

text
Transaction ID: 2319 found for resurrecting updates
Total records resurrected: 1
Resurrected 1 transactions doing updates.
1 transaction(s) which must be rolled back or cleaned up
in total 1 row operations to undo

Starting in background the rollback of uncommitted transactions
Rolling back trx with id 2319, 1 rows to undo
Rollback of trx with id 2319 completed
Rollback of non-prepared transactions completed

재시작 뒤 결과입니다.

text
id status
1 CANCELLED

open_transactions
0

Redo Batch가 0이라는 로그는 해당 Batch에서 처리할 Page address가 없었다는 뜻입니다. 미완료 트랜잭션의 Rollback은 그 뒤 별도 단계로 진행됐습니다. 로그에는 Transaction 2319를 복원하고 백그라운드에서 한 행을 되돌린 과정이 남았습니다.

실험에서 확인한 범위

두 번 모두 InnoDB가 비정상 종료를 감지하고 Crash Recovery를 시작했습니다. 첫 재시작 뒤에는 COMMIT한 CANCELLED가 남았습니다. 두 번째 종료 전에는 미완료 Transaction과 Undo Entry가 있었고, 재시작 과정에서 한 행을 Rollback한 뒤 CANCELLED로 돌아왔습니다. 두 번째 종료 직전 표본에서는 Checkpoint LSN이 Current LSN까지 전진했고 Modified db pages가 0이었습니다.

이 실험은 mysqld Process Crash만 재현했습니다. 첫 번째 종료 직전 id=1의 Data Page가 BOOKED였는지, 첫 복구에서 특정 Redo가 실제로 적용됐는지, REFUNDING을 담은 개별 Page의 바이트가 어떻게 바뀌었는지는 확인하지 못했습니다. Docker Host와 저장 장치의 전원은 유지됐으므로 전원 장애 실험으로도 볼 수 없습니다.