PostgreSQL은 사고 상황에서 데이터 무결성을 보장하기 위해 WAL(Write-Ahead Logging)을 작성합니다.

트랜잭션 처리 중 시스템이 내려간 상황을 상상해봅시다. 트랜잭션을 커밋했어도 데이터가 버퍼에만 쓰이고 아직 디스크에는 쓰이지 않았을 수 있습니다. 이런 상황에서 시스템이 내려가면 변경사항을 잃어버립니다. PostgreSQL은 변경사항을 쓰기 전에 항상 로그를 작성합니다. 이를 이용하면 앞서 말한 상황이 일어났을 때 로그를 보고 아직 쓰이지 않은 변경사항을 재실행(redo)하여 사고를 복구하고 데이터 무결성을 유지할 수 있습니다.

이 글에서는 Docker를 사용해서 트랜잭션 커밋 전후 시점의 스냅샷 이미지를 만든 후 data 파일은 커밋 전, log 파일은 커밋 후 시점에서 임의로 가져와서 failure 상황의 디스크 이미지를 가장한 후 복구가 잘 수행되는지 확인해볼 것입니다.

실습에 사용하는 파일들:

• init.sql
• Dockerfile.base
• Dockerfile.crashed

우선 Dockerfile.base를 사용해서 dbslab-base 라는 이름으로 PostgreSQL 서버 이미지를 만듭니다.

user@host:~$ docker build -f Dockerfile.base -t dbslab-base

해당 이미지에는 다음 디렉토리를 데이터, WAL 디렉토리로 사용하도록 설정되어 있습니다.

• 데이터 디렉토리: /var/lib/pg-data
• WAL 디렉토리: /var/lib/pg-wal

또한 article 테이블과 1, 2번 행이 포함되어 있습니다.

앞서 만든 이미지를 가지고 dbslab 이라는 이름으로 서버 컨테이너를 실행시킵니다.

user@host:~$ docker run -d --name dbslab dbslab-base

이제 docker exec 명령을 통해 컨테이너에서 명령을 실행시키거나 쉘에 접속할 수 있습니다.

user@host:~$ docker exec -it dbslab /bin/ash  # ash 쉘 접속

user@host:~$ docker exec -it dbslab psql -U postgres  # psql 쉘 접속

article 테이블과 2개의 article이 이미 만들어져 있습니다.

SELECT * FROM article;

 id |          title           |         created_at
----+--------------------------+----------------------------
  1 | hello                    | 2022-12-01 10:09:17.608912
  2 | initialized!             | 2022-12-01 10:09:17.609587
(2 rows)

다음과 같이 두 article을 삽입하는 하나의 트랜잭션을 수행할 것입니다.

1. Transaction begin
2. INSERT 3rd-article
-------- (A) --------
3. INSERT 4th-article
4. Transaction commit
-------- (B) --------

이번 실습에서는 로그는 모두 stable storage에 쓰였지만 데이터가 모두 output되지 않은 채 시스템이 내려간 상황을 모사할 것입니다. 정확히는 3rd-article은 output 됐지만 4th-article은 output 되지 않은 상황인 (A) 시점에 시스템이 내려간 상황입니다.

우선 앞서 실행한 데이터베이스에 접속하고 트랜잭션을 수행합니다.

user@host:~$ docker exec -it dbslab psql -U postgres

BEGIN;

-- 3rd article을 생성하되 아직 커밋하지 않습니다.
INSERT INTO article (id, title, created_at) VALUES (
  3, concat('3rd article - txid = ', txid_current()), now()
);

-- 추후 WAL 분석을 위해 현재 트랜잭션 ID를 기억해둡니다.
SELECT txid_current();

-- 주의: 아직 psql 세션을 종료하지 마세요!

 txid_current
--------------
          739
(1 row)

다른 창에서 현재 컨테이너의 상태를 dbslab-before-commit 이라는 이름의 이미지로 만듭니다. 이 이미지는 (A) 시점의 스냅샷일 것입니다.

user@host:~$ docker commit dbslab dbslab-before-commit

다시 psql 세션으로 돌아와서 4th-article을 쓰고 트랜잭션을 마칩니다.

-- continue psql sesison

INSERT INTO article (id, title, created_at) VALUES (
  4, concat('4th article - txid = ', txid_current()), now()
);

COMMIT;

이제 psql 세션은 닫아도 됩니다.

pg 서버 컨테이너에 접속해서 WAL이 잘 기록됐는지 확인해봅니다. WAL은 /var/lib/pg-wal/ 디렉토리에 있습니다. pg-waldump 명령과 앞서 확인한 트랜잭션 ID를 사용해서 WAL 기록을 확인합니다. (아래 --xid=739 부분을 자신이 확인한 트랜잭션 ID로 바꿔주세요.)

user@host:~$ docker exec -it dbslab /bin/ash

root@container:~ # cd /var/lib/pg-wal/
root@container:/var/lib/pg-wal # pg_waldump 000000010000000000000001 --xid=739
rmgr: Heap        len (rec/tot):     54/   258, tx:        739, lsn: 0/01560D08, prev 0/01560CD0, desc: INSERT off 3 flags 0x00, blkref #0: rel 1663/5/16384 blk 0 FPW
rmgr: Btree       len (rec/tot):     53/   153, tx:        739, lsn: 0/01560E10, prev 0/01560D08, desc: INSERT_LEAF off 3, blkref #0: rel 1663/5/16387 blk 1 FPW
rmgr: Heap        len (rec/tot):     95/    95, tx:        739, lsn: 0/01560EE8, prev 0/01560EB0, desc: INSERT off 4 flags 0x00, blkref #0: rel 1663/5/16384 blk 0
rmgr: Btree       len (rec/tot):     64/    64, tx:        739, lsn: 0/01560F48, prev 0/01560EE8, desc: INSERT_LEAF off 4, blkref #0: rel 1663/5/16387 blk 1
rmgr: Transaction len (rec/tot):     34/    34, tx:        739, lsn: 0/01560F88, prev 0/01560F48, desc: COMMIT 2022-12-01 10:13:39.516558 UTC
pg_waldump: error: error in WAL record at 0/1561098: invalid record length at 0/15610D0: wanted 24, got 0

마지막에서 두 번째 줄에 COMMIT이 기록되어 있는 것을 확인합니다.

이제 커밋 후 시점(B)의 이미지를 만듭니다.

user@host:~$ docker commit dbslab dbslab-after-commit

이미지를 만들 때 사용한 컨테이너는 더이상 필요하지 않으니 지워도 됩니다.

user@host:~$ docker container stop dbslab
user@host:~$ docker container rm dbslab

앞서 (A) 시점의 상태를 dbslab-before-commit 이미지로, (B) 시점의 상태를 dbslab-after-commit 이미지로 만들어두었습니다. Dockerfile.crashed를 확인해보면 dbslab-before-commit를 베이스로 하되, dbslab-after-commit 이미지에서 WAL 디렉토리만 복사해오도록 되어있습니다. 이러면 4th-article 삽입 및 커밋 작업의 로그는 쓰였지만 데이터는 output되지 않은 상황과 일치하게 됩니다.

docker build 명령을 사용해서 이미지를 빌드하고 dbslab-crashed라고 이름붙이겠습니다.

user@host:~$ docker build -f Dockerfile.crashed -t dbslab-crashed

WAL에 트랜잭션 커밋까지 로그가 남아 있으므로 4th-article 쓰기 작업부터 트랜잭션 커밋에 까지 redo를 수행할 것을 예상할 수 있습니다.

다음 명령으로 서버를 실행시킵니다. 복구 작업이 수행됩니다.

user@host:~$ docker run -d --name dbslab-recovery dbslab-crashed

docker logs 명령어로 컨테이너 로그를 확인해봅니다. 비정상 종료로 복구를 시작한다는 내용과 redo를 수행한다는 내용의 로그를 확인할 수 있습니다.

user@host:~$ docker logs dbslab-recovery

(...생략)
2022-12-01 10:21:50.552 UTC [23] LOG:  database system was interrupted; last known up at 2022-12-01 10:09:17 UTC
2022-12-01 10:21:50.918 UTC [23] LOG:  database system was not properly shut down; automatic recovery in progress
2022-12-01 10:21:50.920 UTC [23] LOG:  redo starts at 0/1521C50
2022-12-01 10:21:50.923 UTC [23] LOG:  invalid record length at 0/15610D0: wanted 24, got 0
2022-12-01 10:21:50.923 UTC [23] LOG:  redo done at 0/1561098 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 0.00 s
(...생략)

DB에 접속해서 article 테이블도 확인해봅니다.

user@host:~$ docker exec -it dbslab-recovery psql -U postgres

SELECT * FROM article;

 id |          title           |         created_at
----+--------------------------+----------------------------
  1 | hello                    | 2022-12-01 10:09:17.608912
  2 | initialized!             | 2022-12-01 10:09:17.609587
  3 | 3rd article - txid = 739 | 2022-12-01 10:11:49.136474
  4 | 4th article - txid = 739 | 2022-12-01 10:11:49.136474
(4 rows)

(WAL 디렉토리를 제외하고는) dbslab-before-commit 이미지를 사용했으므로 적어도 4th article은 쓰이지 않은 상황이었을텐데 WAL을 통해 복구가 이루어졌음을 확인할 수 있습니다.