Journal (P3/3): Crash recovery; chỉnh gì, đừng chỉnh gì

Ở phần trước: j: true chờ journal xuống đĩa, và nhiều client ghi cùng lúc chia nhau một lần sync (group commit). Checkpoint ghi page đã sửa xuống file dữ liệu, sau đó các file journal cũ mới được xoá.

• Cần đọc trước: Checkpoint và j: true
• Dẫn tới: WiredTiger MVCC. Với bài này, phần Journal & Checkpoint khép lại tại đây.

Crash recovery: khởi động lại sau khi mongod chết

[tài liệu] Manual mô tả recovery thành ba bước:

1. Tìm trong các file dữ liệu định danh của checkpoint cuối cùng;
2. Tìm trong journal record khớp với định danh đó;
3. Áp dụng lại (replay) các thao tác trong journal kể từ checkpoint đó.

Tài liệu WiredTiger nói chính xác hơn: mỗi record journal có một LSN (log sequence number): số chỉ vị trí của nó, gồm số file và offset trong file (file WiredTigerLog.0000000002, byte thứ 384 thì là 2,384); recovery replay "mọi thao tác kể từ LSN của checkpoint gần nhất". Nếu lần trước mongod shutdown bình thường thì tài liệu nói recovery thấy không cần replay.

[quan sát] Đây là các dòng log thật sau lần docker kill đầu tiên của Lab 4 (trial w1-a: 16 client ghi w: 1, kill sau 6 giây; reclog-w1-a.txt, reclog-full-w1-a.txt, rút gọn bớt phần định danh):

W STORAGE  "Detected unclean shutdown - Lock file is not empty"  {"lockFile":"/data/db/mongod.lock"}
W STORAGE  "Recovering data from the last clean checkpoint."
I WTRECOV  "Recovering log 2 through 3"
I WTRECOV  "Main recovery loop: starting at 2,384 to 3,256"
I WTRECOV  "recovery log replay has successfully finished and ran for 223 milliseconds"
I WTRECOV  "recovery rollback to stable has successfully finished and ran for 0 milliseconds"
I WTRECOV  "recovery checkpoint has successfully finished and ran for 34 milliseconds"
I WTRECOV  "recovery was completed successfully and took 258ms, including 223ms for the log replay,
            0ms for the rollback to stable, and 34ms for the checkpoint."

Đọc từng dòng: mongod.lock còn nội dung nghĩa là lần trước không shutdown bình thường. Recovery bắt đầu từ LSN 2,384 (file journal 2, offset 384, nơi checkpoint cuối đánh dấu) tới 3,256 (gần đầu file journal 3), replay mất 223 ms, rồi làm một checkpoint mới để chốt (34 ms). "Rollback to stable" ở standalone mất 0 ms; nó liên quan tới timestamp, thuộc bài WiredTiger MVCC và bài Elections, Failover & Majority. Sau một lần shutdown bình thường (docker stop) hai dòng cảnh báo đầu không xuất hiện và log báo "Startup from clean shutdown?": true (reclog-full-stop-a.txt).

[quan sát] Nhưng ngay cả sau docker stop (WiredTiger đóng bình thường, e2d-shutdown-log.txt), log recovery vẫn có Main recovery loop: starting at 42,9400576 to 43,256 và "log replay" 384 ms. Tài liệu nói shutdown bình thường thì không cần replay; tôi không giải thích được. [suy luận] "Log replay" có lẽ gồm một phần chi phí cố định (đọc journal): trong 25 lần recovery sau kill, ngắn nhất cũng 166 ms. Tôi không kiểm chứng.

Lab 4: kill mongod, rồi đếm

Kill mongod đang chịu tải, khởi động lại, đếm lệnh ghi nào còn.

Thiết kế (e2-writer.js, e2-trial.sh, e2-check.js): container mongo-jrn22-kill, cấu hình mặc định. 16 client trong container khác, mỗi client chèn tuần tự các document _id liên tiếp (một client một dải), in ra ACK <_id> mỗi khi nhận acknowledged. Sau 6 giây, docker kill (SIGKILL tới mongod), rồi docker start, chờ mongod sẵn sàng, rồi với mỗi client kiểm tra: mọi _id từ 1 tới ack cuối cùng của nó có mặt không? Ba nhóm, mỗi nhóm 5 lượt: w: 1, w: 1, j: true, và w: 1 với --journalCommitInterval 500 (container thứ hai).

("Quy ra thời gian ghi" = số document mất chia cho tốc độ ack trung bình của lượt đó, derive-e2.out. Với j: true, có 7, 1, 0, 1, 6 document có mặt mà client chưa nhận ack: lệnh ghi đã xuống journal nhưng kill tới trước khi câu trả lời về tới client; một lỗi "không biết đã ghi hay chưa", chuyện của retry ở bài Write Conflicts, Retry & Idempotency.)

Cái này chứng minh gì, và không chứng minh gì

Chứng minh (cho container bị SIGKILL, trong lab này):

• j: true giữ lời hứa: 187.405 lệnh ghi đã nhận ack, 0 mất, qua 5 lần kill. Đúng như bài Durability & Consistency hứa.
• w: 1 không có j để mất một lượng nhỏ nhưng khác 0: 891 trên 238.200, chỉ 1 trong 5 lượt không mất gì. Mỗi lượt mất bằng khoảng từ 0 tới ≈ 72 ms lệnh ghi cuối cùng. [suy luận] Khớp với việc record nằm trong bộ đệm journal của mongod tới khi bị ghi xuống OS: tài liệu WiredTiger nói một thread nền flush slot đang mở "mỗi 50 ms" để khi hệ thống rảnh bộ đệm không nằm đó mãi, và bộ đếm của lab cho 10 flush mỗi giây (100 ms); cả hai nằm trong khoảng ta thấy.

Không chứng minh:

• Đây không phải mất điện. SIGKILL xoá tiến trình nhưng page cache của hệ điều hành vẫn còn: byte mà mongod đã write() xuống OS, chưa fsync, vẫn được ghi ra đĩa. Cửa sổ đo được (tới 72 ms) chỉ là phần còn trong RAM của mongod; khi mất điện thật còn thêm phần đã ghi xuống OS mà chưa sync (chu kỳ sync mặc định 100 ms theo manual). [suy luận] Nên 72 ms là cận dưới của cửa sổ của w: 1 khi mất điện, không phải cận trên. Tôi không có cách an toàn để cắt điện máy ảo Docker mà không chạm các container khác.
• Đây không đo được commitIntervalMs: ở 500 ms, mất 674 lệnh, cửa sổ lớn nhất 38 ms, so với 891 và 72 ms ở 100 ms. 5 lượt dao động mạnh như vậy không cho thấy khác biệt nào. [suy luận] Tham số này điều khiển nhịp sync, mà SIGKILL không phân biệt đã sync hay chưa; muốn thấy tác dụng phải cắt điện thật.

Recovery mất bao lâu, theo lượng journal

e2b-trial.sh (chạy bằng e2b-all.sh và e2c-all.sh): trước mỗi lần kill, ép một checkpoint bằng fsync, rồi 16 client ghi w: 1 document khoảng 1,1 KB trong T giây, một script khác đọc log bytes written mỗi giây, rồi kill. Mọi lần T nhỏ hơn 60 giây nên không có checkpoint nào xen vào (ckN không đổi trong mọi file poll). Lượng journal ≈ 1,1 KB mỗi document đã ack. Tốc độ ghi biến thiên giữa các lượt vì host bận, nên bảng sắp theo lượng journal chứ không theo T.

[quan sát]

• Từ gần 0 tới 430 MiB journal, recovery mất từ 0,2 đến 3,4 giây; với 237 đến 427 MiB, replay mất 1,0 đến 2,2 giây. Xu hướng tăng theo lượng journal nhưng nhiễu: lượt T = 20 s đầu (59,9 MiB) mất 3,25 giây, hơn cả hai lượt 154 và 182 MiB. Tôi không biết nguyên nhân; đừng vẽ đường thẳng qua bảng này.
• [suy luận] Ý nghĩa thực hành nằm ở cái trần: vì checkpoint cứ 60 giây một lần, lượng journal cần replay bị chặn bởi lượng ghi trong một chu kỳ. Ở tải của lab (3 đến 10 MiB/giây, volume Docker), đó là vài trăm MiB và vài giây; ghi nặng hơn thì trần cao hơn.

Journal không phải oplog

[tài liệu] Oplog là một collection (local.oplog.rs) của replica set, chứa thao tác ở mức MongoDB để secondary áp dụng lại; nó không có ở standalone (lab này không có oplog). Journal là file của WiredTiger, chỉ mongod đó đọc, và chỉ khi recovery; nó giúp một node sống sót qua crash. Một node replica set có cả hai và chúng không thay nhau. j: true hỏi về journal của node; w: "majority" hỏi về việc dữ liệu đã tới đa số node; majority commit point dịch chuyển ra sao khi failover là chuyện của bài Elections, Failover & Majority, còn oplog là của bài Replica Set & Oplog.

So với PostgreSQL

[tài liệu] PostgreSQL dùng WAL (write-ahead log): thay đổi của file dữ liệu chỉ được ghi sau khi các record WAL mô tả chúng đã flush xuống nơi lưu trữ bền; khi crash, server làm lại (REDO) những gì chưa vào page dữ liệu. Về ý tưởng, đây là cùng cách làm với journal và checkpoint của WiredTiger. Khác nhau nằm ở các núm vặn, theo trang cấu hình WAL của PostgreSQL:

• checkpoint_timeout mặc định 5 phút, max_wal_size mặc định 1 GB (giới hạn mềm có thể kích hoạt checkpoint sớm); MongoDB là 60 giây. Tài liệu PostgreSQL nói tăng chúng làm recovery lâu hơn, đúng đánh đổi ta đo ở trên.
• full_page_writes (mặc định on): lần sửa đầu tiên của một page sau checkpoint, WAL ghi cả page, phòng page bị ghi dở khi crash. Journal chỉ ghi thao tác; [suy luận] WiredTiger không cần vậy vì nó không ghi đè block cũ.
• synchronous_commit (mặc định on) chờ WAL flush; off thì giao dịch có thể mất tới khoảng ba lần wal_writer_delay (mặc định 200 ms) nhưng theo tài liệu không làm hỏng cơ sở dữ liệu. Bắt cặp thô cho dễ nhớ: w: 1 giống off, j: true giống on; [hình dung], tôi không khẳng định tương đương vì w của MongoDB còn nói về số node.

Chỉnh gì, và đừng chỉnh gì

• storage.journal.commitIntervalMs (1 đến 500, mặc định 100): chỉ đổi cửa sổ của lệnh ghi không có j: true; manual nói giá trị thấp làm journal bền hơn, đổi bằng hiệu năng đĩa. Lab không đo được tác dụng thật của nó (Lab 4), nên đừng chỉnh mà không có số đo trên phần cứng của bạn. Cần "không mất khi mất điện" thì dùng j: true (hoặc majority, vốn ngầm có j: true), không dùng interval nhỏ.
• storage.syncPeriodSecs (60): manual dặn không đặt ở production; về 0 thì journal lớn tới hết đĩa.
• Đĩa: manual gợi ý cân nhắc tách dữ liệu, journal và log lên thiết bị riêng. Chia log sync time duration cho log sync operations: nếu trung bình lên hàng ms thì j: true của bạn đang chờ đĩa.

Những lỗi thường gặp

• Nhầm journal với oplog: chúng không đọc nhau và không thay nhau.
• "Có j: true là an toàn khi primary mất": journal bảo vệ một node chết đột ngột, không bảo vệ lệnh ghi chưa sang secondary khi failover.
• "Checkpoint 60 giây nghĩa là w: 1 mất tới 60 giây": giữa hai checkpoint thay đổi nằm trong journal. 60 giây quyết định recovery dài bao lâu, không quyết định mất bao nhiêu.
• Tin docker kill như phép thử mất điện: page cache của OS sống qua SIGKILL.
• Chỉnh commitIntervalMs hoặc syncPeriodSecs mà không đo; tưởng tắt được journal (từ 6.1 luôn bật).
• Thấy WiredTigerLog.* dài 100 MiB mà tưởng đó là lượng journal đang dùng: đó là kích thước cấp phát sẵn.
• Suy ra production từ số fsync trong Docker; và quên rằng checkpoint ghi cả page (Lab 3).

Cột mốc: Bạn đã có thể mô tả ba bước crash recovery, đọc các dòng log recovery, và nói vì sao j: true giữ lệnh ghi đã ack khi kill mongod còn w: 1 thì không. Bài này khép lại tại đây.

Hỏi & đáp

Nếu bỏ hết thuật ngữ: một cửa hàng ghi mỗi lần bán vào cuốn sổ ghi chép hằng ngày ngay lúc đó, còn sổ cái gọn gàng thì chỉ chỉnh mỗi giờ một lần. Đêm mất điện, sáng ra họ mở sổ cái tới dấu "đúng tới đây", rồi làm lại từng dòng trong sổ ghi chép sau dấu đó. Giao dịch nào đã nằm trong sổ ghi chép thì không mất; giao dịch chủ tiệm mới nhẩm trong đầu thì mất. Muốn chắc chắn, đứng đợi cho tới khi nét bút khô; làm thế thì mỗi lần bán chậm hơn, nhưng nhiều khách xếp hàng thì có thể cùng đợi một lần mực khô. Và mỗi giờ chỉnh sổ cái là việc chủ tiệm không ngồi ghi lại từng dòng mà viết lại cả trang: sửa một chữ nhỏ trong một trang dày thì tốn công cả trang.

Bài tiếp theo

Bài này nói một thay đổi sống sót qua crash thế nào, chưa nói cùng một dữ liệu tồn tại ở nhiều phiên bản cùng lúc ra sao. Ta đã thấy $inc làm một page dirty và checkpoint ghi lại nó; nhưng trong lúc đó, một transaction khác vẫn phải đọc được giá trị trước $inc, và WiredTigerHS.wt (history store) trong danh sách file ở bài WiredTiger chưa được giải thích.

WiredTiger MVCC trả lời: update chain (chuỗi các phiên bản của một document ngay trên page), timestamp, vì sao một snapshot cũ buộc server giữ lại các phiên bản cũ, và history store là nơi chúng được cất. Nó nối ba tầng lại với nhau: transaction của ứng dụng, transaction của MongoDB và transaction của WiredTiger.

Tài liệu tham khảo

• MongoDB: Journaling (journal record, 100 ms, j: true, file size, compression, always enabled since 6.1)
• MongoDB: WiredTiger Storage Engine (snapshots and checkpoints, journal, compression)
• MongoDB: Configuration File Options (storage.journal.commitIntervalMs, storage.syncPeriodSecs, storage.wiredTiger.engineConfig.journalCompressor)
• MongoDB: serverStatus (wiredTiger.log, wiredTiger.transaction)
• MongoDB: Write Concern (j option, writeConcernMajorityJournalDefault)
• MongoDB: Production Notes (journaling, separate devices)
• WiredTiger: Logging (log records, LSN, slots, internal threads, recovery)
• WiredTiger: Log File Format
• WiredTiger: Checkpoint
• PostgreSQL: Write-Ahead Logging (WAL)
• PostgreSQL: WAL Configuration (checkpoints, checkpoint_timeout, max_wal_size)
• PostgreSQL: Write Ahead Log settings (synchronous_commit, full_page_writes, wal_writer_delay, commit_delay, fsync)