이번 시간에는 UPDATE 하나를 따라가며 MySQL의 Binlog, redo log, undo log가 각각 언제 쓰이고 누가 읽는지를 직접 확인하며 배워가는 시간입니다.
예를 들어서 계좌 잔액을 100에서 150으로 바꾸는 UPDATE를 하나 실행한다고 해볼게요. SQL은 한 줄이지만, MySQL은 이 변경을 적어도 세 군데에 기록해요. Binlog, redo log, undo log예요.
셋 다 "변경을 적어 둔 로그"라서 헷갈리기 쉬워요. 그런데 각 로그를 읽는 쪽과 읽는 시점이 모두 달라요.
실습 준비
이 글의 명령은 모두 실습 코드의 mysql-binlog-redo-undo/ 디렉터리에서 실행합니다.
compose.yaml:log-error-verbosity를 3으로 올린 MySQL 8.4setup.sql: 계좌 두 개를 만드는 SQL
그 밖의 파일은 데이터·보조 스크립트입니다.
Docker로 MySQL 8.4를 띄울게요. 복구 과정의 메시지까지 Error log에 남도록 log-error-verbosity를 3으로 올려 두었어요. compose.yaml은 이렇습니다.
services:
mysql:
image: mysql:8.4
command: --log-error-verbosity=3
environment:
MYSQL_ROOT_PASSWORD: root
ports:
- "3381:3306"
setup.sql은 bank 데이터베이스에 accounts(id, owner, balance) 테이블을 만들고 kim, lee 계좌를 잔액 100으로 넣어요.
자주 쓰는 명령은 셸 함수로 만들어 둘게요. lsn은 redo log의 위치를, pos는 Binlog의 현재 위치를 보여 줘요. MYSQL_PWD 환경 변수로 비밀번호를 넘기는 방식은 실습에서만 써 주세요.
아래 블록은 파일로 만들지 말고 실습 디렉터리에서 연 터미널에 그대로 붙여 넣어 주세요. 이후 명령은 모두 이 터미널에서 실행하고, 터미널을 새로 열면 다시 붙여 넣으시면 됩니다.
docker compose up -d
sql() { docker compose exec -T -e MYSQL_PWD=root mysql mysql -uroot "$@"; }
lsn() { sql -e "SHOW ENGINE INNODB STATUS\G" | grep -E "Log sequence number|Log flushed up to|Last checkpoint at"; }
pos() { sql -e "SHOW BINARY LOG STATUS\G" | grep -E "File|Position"; }
sql < setup.sql
실습 1: UPDATE 하나를 따라가 봅니다
UPDATE 전의 redo log 위치와 Binlog 위치를 먼저 확인해 볼게요.
lsn; pos
Log sequence number 29674439
Log flushed up to 29674439
Last checkpoint at 29674439
File: binlog.000002
Position: 888
각 항목은 이런 뜻이에요.
Log sequence number: 지금까지 만든 redo log의 끝 위치(LSN)입니다. redo log가 쌓이면 늘어나요.Log flushed up to: 디스크에 flush까지 끝난 redo log의 위치입니다.Last checkpoint at: 이 위치까지의 변경은 데이터 파일에도 기록됐다는 표시입니다. 크래시 복구는 여기서부터 시작해요.File,Position: Binlog에 다음 이벤트를 쓸 파일과 위치입니다.
이제 잔액을 150으로 바꾸고, 커밋하기 전에 20초를 기다리는 트랜잭션을 백그라운드로 실행해 볼게요. 그사이 다른 세션에서 상태를 봅니다.
sql -e "BEGIN; UPDATE bank.accounts SET balance = 150 WHERE id = 1; DO SLEEP(20); COMMIT;" &
sleep 2
sql -t -e "SELECT trx_id, trx_state, trx_rows_modified FROM information_schema.INNODB_TRX"
lsn; pos
+--------+-----------+-------------------+
| trx_id | trx_state | trx_rows_modified |
+--------+-----------+-------------------+
| 1815 | RUNNING | 1 |
+--------+-----------+-------------------+
Log sequence number 29675268
Log flushed up to 29675268
Last checkpoint at 29675268
File: binlog.000002
Position: 888
여기서 눈여겨볼 건 LSN이에요. 아직 커밋하지 않았는데도 LSN은 29674439에서 29675268로 늘었어요. InnoDB는 페이지를 바꾸는 순간 redo log를 만들기 때문이에요.
INNODB_TRX의 trx_rows_modified가 1이니 이 트랜잭션은 행 하나를 바꿨고, 바꾸기 전 값 100은 undo log에 남아 있어요.
반면 Binlog 위치는 888 그대로예요. 왜 그럴까요? Binlog에는 커밋할 때 한꺼번에 기록되기 때문이에요.
트랜잭션이 커밋된 뒤 다시 확인해 볼게요.
wait
lsn; pos
Log sequence number 29675583
Log flushed up to 29675583
Last checkpoint at 29675583
File: binlog.000002
Position: 1203
커밋하자 Binlog 위치가 888에서 1203으로 움직였어요. 그 사이에 무엇이 기록됐는지 볼게요.
sql -t -e "SHOW BINLOG EVENTS IN 'binlog.000002' FROM 888"
+---------------+------+----------------+-----------+-------------+--------------------------------------+
| Log_name | Pos | Event_type | Server_id | End_log_pos | Info |
+---------------+------+----------------+-----------+-------------+--------------------------------------+
| binlog.000002 | 888 | Anonymous_Gtid | 1 | 967 | SET @@SESSION.GTID_NEXT= 'ANONYMOUS' |
| binlog.000002 | 967 | Query | 1 | 1047 | BEGIN |
| binlog.000002 | 1047 | Table_map | 1 | 1110 | table_id: 85 (bank.accounts) |
| binlog.000002 | 1110 | Update_rows | 1 | 1172 | table_id: 85 flags: STMT_END_F |
| binlog.000002 | 1172 | Xid | 1 | 1203 | COMMIT /* xid=27 */ |
+---------------+------+----------------+-----------+-------------+--------------------------------------+
트랜잭션 하나가 BEGIN, 대상 테이블 정보(Table_map), 바뀐 행(Update_rows), 커밋(Xid) 이벤트로 기록됐어요. 기본 형식인 ROW 형식에서는 SQL 문장이 아니라 바뀐 행의 값이 남아요.
마지막 Xid 이벤트의 번호는 기억해 두세요. 뒤에서 볼 크래시 복구에서 Binlog와 InnoDB를 맞춰 보는 데 쓰여요.
실습 2: Undo log로 과거 버전을 읽습니다
undo log는 ROLLBACK에만 쓰이지 않아요. InnoDB의 기본 격리 수준인 REPEATABLE READ에서는 트랜잭션이 처음 읽은 시점의 스냅숏을 끝까지 봐요.
그사이 다른 트랜잭션이 행을 바꾸고 커밋하면 어떻게 될까요? InnoDB는 undo log를 따라가 스냅숏 시점의 값을 만들어 돌려줘요.
undo log가 얼마나 쌓였는지는 SHOW ENGINE INNODB STATUS의 History list length로 볼 수 있어요. 커밋된 트랜잭션의 undo log 가운데 아직 정리(purge)되지 않은 것의 개수예요.
hll() { sql -e "SHOW ENGINE INNODB STATUS\G" | grep "History list length"; }
hll
History list length 9
세션 두 개로 실험해 볼게요. 세션 A는 잔액을 한 번 읽고 8초 뒤에 다시 읽어요. 그사이 세션 B는 1번 계좌를 200으로 바꾸고, 2번 계좌를 100번 UPDATE합니다. B의 문장은 모두 자동 커밋돼요.
sql -t -e "BEGIN; SELECT balance AS first_read FROM bank.accounts WHERE id = 1; DO SLEEP(8); SELECT balance AS second_read FROM bank.accounts WHERE id = 1; COMMIT;" > mvcc_a.txt &
sleep 1
sql -e "UPDATE bank.accounts SET balance = 200 WHERE id = 1"
seq 1 100 | sed 's/.*/UPDATE bank.accounts SET balance = balance + 1 WHERE id = 2;/' | sql
sql -t -e "SELECT id, balance FROM bank.accounts"
hll
+----+---------+
| id | balance |
+----+---------+
| 1 | 200 |
| 2 | 200 |
+----+---------+
History list length 102
B가 커밋했으니 새 세션에서는 1번 계좌가 200으로 보여요. 그리고 History list length는 9에서 102로 늘었어요.
왜 늘었을까요? A의 스냅숏이 열려 있는 동안에는 A가 과거 버전을 읽을 수도 있으니, InnoDB는 그 뒤에 생긴 undo log를 지우지 못하기 때문이에요.
A가 끝난 뒤 A의 결과를 볼게요.
wait
cat mvcc_a.txt
+------------+
| first_read |
+------------+
| 150 |
+------------+
+-------------+
| second_read |
+-------------+
| 150 |
+-------------+
B가 커밋한 뒤에 읽은 second_read도 150이에요. A는 자기 스냅숏 시점의 값을 undo log에서 읽은 거죠.
A가 끝나고 잠시 기다리면 purge가 undo log를 정리해 값이 0이 됩니다.
hll
History list length 0
그러니 몇 시간씩 열려 있는 트랜잭션이 있으면 이 값이 계속 커지고 undo 테이블스페이스도 함께 커져요. History list length가 줄지 않는다면 오래 열린 트랜잭션부터 찾아보세요.
커밋할 때 디스크에 먼저 쓰는 것
실습 1에서 LSN은 늘었지만, 그때 데이터 파일의 페이지가 바로 바뀐 것은 아니에요. InnoDB는 UPDATE를 메모리의 버퍼 풀에 있는 페이지에서 처리해요.
바뀐 페이지를 커밋할 때마다 데이터 파일에 쓰지 않고, 나중에 page cleaner 스레드가 모아서 써요. 그 대신 커밋할 때는 redo log를 먼저 디스크에 씁니다. 데이터 파일보다 로그를 먼저 쓰는 이 방식을 WAL(Write-Ahead Logging)이라고 해요.
그런데 로그가 두 개라면 한쪽에만 쓰고 서버가 꺼질 수도 있겠죠. redo log에만 남으면 이 서버에는 변경이 있는데 Replica에는 없고, Binlog에만 남으면 그 반대가 돼요.
MySQL은 이를 막으려고 Binlog와 InnoDB 사이에 내부 XA라고 부르는 2단계 커밋을 써요.
- InnoDB가 트랜잭션을 prepare 상태로 만들고, redo log를 디스크에 flush합니다.
- Server 계층이 트랜잭션을 Binlog에 쓰고 sync합니다.
- InnoDB가 트랜잭션을 커밋 상태로 바꿉니다.
크래시 뒤 재시작할 때 InnoDB에 prepare 상태로 남은 트랜잭션이 있으면, MySQL은 Binlog를 읽어 그 트랜잭션의 XID가 있는지 봐요. Binlog에 있으면 커밋하고, 없으면 롤백해요. 앞에서 본 Xid 이벤트의 번호가 이때 쓰이는 거예요.
실습 3: Redo log로 크래시 뒤 다시 적용합니다
이제 서버를 강제로 죽여 볼게요. 한 세션은 2번 계좌를 999로 바꾼 뒤 커밋하지 않고 기다려요. 다른 세션은 1번 계좌를 300으로 바꾸고 바로 커밋한 뒤 redo log 위치를 봅니다.
sql -e "BEGIN; UPDATE bank.accounts SET balance = 999 WHERE id = 2; DO SLEEP(60);" &
sleep 1
sql -e "UPDATE bank.accounts SET balance = 300 WHERE id = 1; SHOW ENGINE INNODB STATUS\G" | grep -E "Log sequence number|Log flushed up to|Last checkpoint at"
Log sequence number 29793328
Log flushed up to 29793191
Last checkpoint at 29790234
이번에는 세 값이 달라요. Log flushed up to(29793191)까지의 redo log는 디스크에 있지만, 데이터 파일에는 Last checkpoint at(29790234)까지만 반영됐어요.
LSN 숫자는 그때까지 쌓인 redo log 양에 따라 달라지니, 세 값의 크기 관계만 보시면 돼요.
이 상태에서 컨테이너에 SIGKILL을 보내 MySQL을 바로 죽이고, 다시 시작해 볼게요.
docker kill "$(docker compose ps -q mysql)"
docker compose start
다시 시작하면서 남긴 기록 중 복구와 관련된 줄만 볼게요.
docker compose logs --no-log-prefix mysql | sed -n '/not shutdown normally/,$p' | grep -E "shutdown normally|crash recovery|redo log records|Apply batch|Resurrected|to undo|Rollback of trx|using binlog"
2026-09-30T03:52:30.527951Z 1 [Note] [MY-012551] [InnoDB] Database was not shutdown normally!
2026-09-30T03:52:30.527958Z 1 [Note] [MY-012552] [InnoDB] Starting crash recovery.
2026-09-30T03:52:30.635020Z 1 [Note] [MY-012532] [InnoDB] Applying a batch of 12 redo log records ...
2026-09-30T03:52:31.232818Z 1 [Note] [MY-012535] [InnoDB] Apply batch completed!
2026-09-30T03:52:31.462088Z 1 [Note] [MY-014023] [InnoDB] Resurrected 1 transactions doing updates.
2026-09-30T03:52:31.462155Z 1 [Note] [MY-013023] [InnoDB] 1 transaction(s) which must be rolled back or cleaned up in total 1 row operations to undo
2026-09-30T03:52:32.086157Z 0 [Note] [MY-010855] [Server] Recovering after a crash using binlog
2026-09-30T03:52:32.086806Z 0 [System] [MY-010229] [Server] Starting XA crash recovery...
2026-09-30T03:52:32.116775Z 0 [System] [MY-010232] [Server] XA crash recovery finished.
2026-09-30T03:52:32.129034Z 0 [Note] [MY-013011] [InnoDB] Rolling back trx with id 2027, 1 rows to undo
2026-09-30T03:52:32.136199Z 0 [Note] [MY-013012] [InnoDB] Rollback of trx with id 2027 completed
복구는 redo, Binlog, undo 순서로 진행됐어요. 한 줄씩 보면 이렇습니다.
Starting crash recovery,Applying a batch of 12 redo log records,Apply batch completed: 정상 종료가 아니었으니 checkpoint부터 redo log를 읽어, 데이터 파일에 아직 반영되지 않은 redo 기록 12건을 다시 적용했어요. 이 수는 서버를 죽인 순간 page cleaner가 어디까지 썼는지에 따라 달라지고, 0건일 수도 있어요.Resurrected 1 transactions doing updates: 커밋하지 않은 트랜잭션 하나를 찾았어요. undo log도 redo log로 보호되기 때문에, redo를 다시 적용하고 나면 커밋되지 않은 트랜잭션과 그 undo log가 그대로 살아나요.Recovering after a crash using binlog,XA crash recovery: prepare 상태로 남은 트랜잭션이 있는지 Binlog와 맞춰 봅니다.Rolling back trx with id 2027, 1 rows to undo,Rollback of trx with id 2027 completed: 커밋하지 않은 트랜잭션을 undo log로 되돌렸어요.
여기서는 데이터를 확인해 볼게요.
sql -t -e "SELECT * FROM bank.accounts"
+----+-------+---------+
| id | owner | balance |
+----+-------+---------+
| 1 | kim | 300 |
| 2 | lee | 200 |
+----+-------+---------+
커밋한 300은 redo log로 다시 적용되어 남았고, 커밋하지 않은 999는 undo log로 되돌아가 2번 계좌는 200 그대로예요.
정리
범위: MySQL 8.4(mysql:8.4 이미지) 기본 설정(innodb_flush_log_at_trx_commit=1, sync_binlog=1), 계좌 2개짜리 테이블, 서버는 docker kill로 강제 종료.
- 커밋 전 UPDATE에서 LSN은 29674439에서 29675268로 늘었지만 Binlog 위치는 888 그대로였고, 커밋하자 Binlog가 1203으로 움직이며
BEGIN,Table_map,Update_rows,Xid이벤트가 남았어요. - 스냅숏을 연 세션은 다른 세션이 200으로 바꾸고 커밋한 뒤에도 150을 읽었고, 그동안
History list length는 9에서 102로 늘었다가 그 세션이 끝나자 0이 됐어요.History list length가 줄지 않으면 오래 열린 트랜잭션을INNODB_TRX에서 찾아보세요. - 커밋 직후
Log flushed up to는 29793191,Last checkpoint at은 29790234였고, 이 상태에서 SIGKILL 뒤 재시작하자 redo 기록 12건을 다시 적용하고 Binlog로 XA 복구를 확인한 뒤 커밋하지 않은 트랜잭션 하나를 undo로 되돌렸어요. 무엇을 복구했는지 보려면log-error-verbosity를 3으로 두고 Error log를 확인하세요. - 크래시 뒤 1번 계좌는 커밋한 300으로 남았고, 2번 계좌는 커밋하지 않은 999가 아니라 200이었어요.