커밋이 완료되었다고 정말 디스크에 적혔을까? (2) 강제 kill에 의한 로그

이전 글에서 synchronous_commit 설정을 통해 데이터 안전과 쓰기 성능 사이의 트레이드오프를 확인해 보았습니다. 이론적으로 커밋된 데이터는 WAL(Write-Ahead Log) 덕분에 안전하게 보장된다고 배웠습니다.

하지만 문득 이런 의문이 들었습니다.

"이론적으로 복구된다는 건 알겠는데, 실제로 데이터가 막 쏟아지고 있는 찰나에 서버 전원이 나가버려도 정말 데이터가 하나도 안 날아가고 다 복구될까?" 이 궁금증을 해결하기 위해, 직접 PostgreSQL 컨테이너의 프로세스를 강제로 Kill하는 실험을 진행했습니다.

synchronous_commit의 정확한 작동 방식

트랜잭션 처리 과정

1. 데이터 변경 발생 (INSERT, UPDATE 등)

• 메모리에 데이터 기록
• 데이터를 WAL 버퍼(메모리)에 기록

2. COMMIT 실행 - 여기서 차이 발생!

• synchronous_commit = on (기본값)
  • WAL 버퍼(메모리)
  • → WAL 파일(디스크)에 물리적으로 기록(fsync) 대기
  • → 디스크 기록 완료 확인
  • → "커밋 성공" 응답 반환
• synchronous_commit = off
  • WAL 버퍼(메모리)에만 기록
  • → 바로 "커밋 성공" 응답 반환
  • → 실제 디스크 기록은 백그라운드의 별도 프로세스가 나중에 처리

3. 만약 이 시점에 docker kill 당하면?

• on: WAL 파일(디스크)에 이미 있음 → 복구 가능 
• off: WAL 버퍼(메모리)만 있던 데이터 → 증발 

---

실험 환경 및 설정

테스트 환경

• PostgreSQL 13.22 (Docker)
• 플랫폼: Docker on macOS (aarch64)
• 설정: synchronous_commit = on (안전 최우선 모드)

테스트용 테이블 생성

CREATE TABLE crash_test (
    id SERIAL PRIMARY KEY,
    created_at TIMESTAMP DEFAULT NOW()
);

데이터 삽입 프로시저

CREATE OR REPLACE PROCEDURE insert_commit_loop()
LANGUAGE plpgsql
AS $$
BEGIN
    FOR i IN 1..100000 LOOP
        INSERT INTO crash_test DEFAULT VALUES;
        COMMIT;  -- 핵심! 한 건 넣을 때마다 바로바로 커밋
    END LOOP;
END;
$$;

실험 진행: docker kill

1. 1단계: 프로시저 실행 CALL insert_commit_loop();
2. 2단계: 진행 중 강제 종료 docker kill postgres-container
   • docker stop은 DB에 정리할 시간을 주지만, docker kill은 프로세스를 즉시 kill합니다.
   • (전원을 뽑는 것과 동일한 상황을 재현하기위해 kill을 사용했습니다)
3. 3단계: 컨테이너 재시작 docker start postgres-container
4. 결과: 26,319건 복구 SELECT count(*) FROM crash_test; 

프로시저가 100,000번 루프를 다 돌기 전에 강제로 종료되었으므로, 실제로는 약 26,000번째 INSERT를 처리하던 중 전원이 나간 셈입니다. 하지만 단 한 건도 유실되지 않고 모두 복구되었습니다.

왜 유실이 없었을까? synchronous_commit = on 설정 덕분입니다.

• 26,319번째까지: WAL 디스크 기록 완료 → 커밋 성공 응답
• 26,320번째부터: WAL 디스크 기록 진행 중 → 응답 못 보낸 상태에서 kill

사실 이 데이터들 중 상당수는 아직 실제 데이터 파일에는 적히지 않고 메모리에만 있었을 가능성이 큽니다. DB는 성능을 위해 데이터 파일 업데이트를 미루기 때문입니다. 그런데도 완벽하게 복구된 이유는 바로 디스크에 안전하게 기록된 WAL 덕분입니다.

---

로그로 읽는 DB의 복원 과정

다음은 재부팅 시 출력된 PostgreSQL의 로그입니다.

# 강제 종료 직후: 모든 클라이언트 연결이 비명을 지름 
2026-02-22 20:06:14.553 KST [36] FATAL: terminating connection due to unexpected postmaster exit 
2026-02-22 20:06:14.553 KST [47] FATAL: terminating connection due to unexpected postmaster exit

# 재시작: 기존 데이터베이스 디렉토리 발견, 초기화 스킵 
PostgreSQL Database directory appears to contain a database; Skipping initialization

# 부팅 시작 
2026-02-22 20:06:18.723 KST [1] LOG: starting PostgreSQL 13.22 (Debian 13.22-1.pgdg13+1) 
2026-02-22 20:06:18.723 KST [1] LOG: listening on IPv4 address "0.0.0.0", port 5432

# 마지막 정상 작동 시점 확인 (약 3분 26초 전) 
2026-02-22 20:06:18.732 KST [28] LOG: database system was interrupted; last known up at 2026-02-22 20:02:48 KST

# 비정상 종료 감지 → 자동 복구 시작 
2026-02-22 20:06:19.676 KST [28] LOG: database system was not properly shut down; automatic recovery in progress

# Redo 시작: LSN 23/EF2940C0 위치부터 WAL 재생 
2026-02-22 20:06:19.681 KST [28] LOG: redo starts at 23/EF2940C0

# WAL이 끊긴 지점 발견: kill 당한 순간 메모리 데이터가 증발한 증거 
# "24바이트 기대했는데 0바이트" = WAL 레코드가 쓰이다가 중간에 잘림 
2026-02-22 20:06:19.710 KST [28] LOG: invalid record length at 23/EF72FD00: wanted 24, got 0

# 유효한 마지막 WAL 레코드까지 복구 완료 (약 4.2MB 재생) 
2026-02-22 20:06:19.710 KST [28] LOG: redo done at 23/EF72FCD8

# 복구 완료 및 서비스 재개
2026-02-22 20:06:19.753 KST [1] LOG: database system is ready to accept connections

 

핵심 포인트

• 23/EF2940C0 ~ 23/EF72FCD8: WAL의 시작과 끝 위치
• 약 4.2MB의 WAL을 읽어서 26,319건의 INSERT를 재실행(Redo)
• 3분 26초치 작업을 단 1초 만에 복구 (WAL이 순차IO라 빠름)

---

번외: Checkpoint 폭풍과 WAL 크기 설정

복구 과정을 이해했으니, 이제 WAL 크기 설정의 중요성을 체험해 봅시다.

Checkpoint란?

메모리에 쌓인 변경된 데이터를 디스크의 실제 데이터 파일로 밀어내는 작업을 Checkpoint라고 합니다.

실험: WAL 공간을 극단적으로 줄이기

ALTER SYSTEM SET max_wal_size = '100MB';
ALTER SYSTEM SET min_wal_size = '20MB';
ALTER SYSTEM SET checkpoint_timeout = '30s';

CREATE TABLE checkpoint_test (
    id SERIAL PRIMARY KEY,
    data TEXT DEFAULT md5(random()::text)
);

INSERT INTO checkpoint_test
SELECT FROM generate_series(1, 1000000);  -- 100만 건

결과: DB가 비명을 지름

# WAL이 100MB를 금방 채움
2026-02-22 21:06:23.864 KST [29] LOG: checkpoints are occurring too frequently (13 seconds apart) 
2026-02-22 21:06:23.864 KST [29] HINT: Consider increasing the configuration parameter "max_wal_size".
2026-02-22 21:06:25.784 KST [29] LOG: checkpoints are occurring too frequently (2 seconds apart) 
2026-02-22 21:06:25.784 KST [29] HINT: Consider increasing the configuration parameter "max_wal_size".

 

이 로그의 의미

• 설정한 checkpoint_timeout(30초)보다 훨씬 빠르게 WAL이 100MB를 초과
• DB가 할 수 없이 체크포인트를 계속 수행 → 디스크 I/O 폭증
• INSERT 속도가 급격히 느려지고, 특정 순간 DB가 일시적으로 멈춤

max_wal_size 설정

너무 작게 설정

• 장점: 디스크 공간 절약, 장애 발생 시 복구 시간이 짧음
• 단점: Checkpoint가 빈번하게 발생하여 디스크 I/O 폭증, 대량 작업 시 성능 저하

• 너무 크게 설정
  • 장점: 대량 배치 작업 시 유리
  • 단점: 장애 복구 시간 증가, 디스크 공간이 부족할 수 있음, 한번 체크포인트 발생시 처리해야할 데이터양이 너무많음

---

결론

이번 실험을 통해 알게 된 것들을 정리하면 다음과 같습니다.

1. "커밋 성공" 응답의 의미
   • synchronous_commit = on: WAL이 디스크에 기록 완료됨. 전원 차단 시에도 100% 복구 가능.
   • synchronous_commit = off: WAL이 메모리에만 있을 수 있음. 마지막 1~2초치 데이터 유실 위험.
2. WAL의 역할
   • 데이터 파일의 랜덤 I/O 대신 순차 I/O를 사용하여 성능 향상.
   • 디스크에 안전하게 기록되어 장애 시 재실행(Redo) 보장.
3. Checkpoint와 WAL 크기의 트레이드오프
   • WAL 공간 부족 → Checkpoint 폭풍 → 전체적인 시스템 성능 저하.
   • 배치 작업 전에는 max_wal_size를 늘리고 checkpoint_timeout을 조절하는 것이 좋음.

이론만으로는 와닿지 않던 "디스크 I/O 병목"과 "데이터 안전"의 트레이드오프를, 직접 서버를 kill 해보며 체감할 수 있었습니다.