Failover (P2/3): Majority commit point và rollback

Ở phần trước: primary biến mất thì một secondary được bầu làm primary nếu có đa số phiếu và optime cao nhất trong số các member nó thấy. Primary bị cô lập vẫn nhận w: 1 khoảng 10 giây trước khi step down. Những lệnh ghi đó đi đâu?

• Cần đọc trước: Failover: heartbeat, term và một cuộc bầu cử
• Dẫn tới: Failover: ứng dụng nhìn thấy gì

Môi trường lab: như phần trước: MongoDB 8.3.11 trong Docker (mongo:8), replica set 3 node mongo-fo26-a/-b/-c (1 CPU, 1 GB RAM, WiredTiger cache 0,25 GB), Node.js driver 7.7.0, host Docker Desktop đang bận nên mọi thời gian là cận dưới. Script và output thô nằm trong lab26/ kèm INDEX.md. Nhãn: [tài liệu] manual MongoDB, [quan sát] đo trong lab, [suy luận] rút ra, chưa kiểm riêng, [chi tiết cài đặt] cách server đang làm, không phải cam kết.

Hình dung trước: biên bản chỉ có hiệu lực khi đa số đã ký

Ba người trực ghi một cuốn biên bản chung. Trưởng ca viết dòng mới nhất vào sổ của mình, hai người kia chép lại. Một dòng chỉ được coi là chính thức khi có ít nhất hai người (đa số) đã chép nó. Mọi cam kết với khách ("đã ghi nhận") chỉ nên dựa vào các dòng chính thức.

Một đêm trưởng ca bị cô lập và vẫn viết thêm mười phút vào sổ riêng. Trong lúc đó hai người kia bầu trưởng ca mới và viết tiếp. Khi trưởng ca cũ quay lại, sổ của ông và sổ của nhóm khác nhau kể từ một dòng chung. Ông phải gạch bỏ mọi dòng mình viết sau dòng chung đó, cất những trang bị gạch vào một hộp để ai cần thì xem, rồi chép lại theo sổ của nhóm.

dòng chung cuối cùng         = common point
dòng đã có đa số chép lại     = majority commit point
gạch các dòng sau dòng chung  = rollback
hộp đựng các trang bị gạch    = rollback files

Đây chỉ là cách hình dung: MongoDB không "gạch" mà rollback ở mức storage engine, và có hai điểm khác nhau (common point và commit point) mà biên bản không thể hiện hết.

Ý chính

Majority commit point là vị trí mới nhất trong oplog mà đa số member đã có. Primary tính nó và mọi member đều biết nó. Lệnh ghi w: "majority" được xác nhận khi commit point đã tới lệnh đó, và read concern "majority" đọc dữ liệu tại điểm này (lời hứa của hai mức nằm ở Durability & Consistency). Phần oplog sau điểm này, nghĩa là các lệnh chỉ nằm ở primary hoặc ở thiểu số, là phần có thể bị rollback khi failover; phần trước nó thì không. Rollback là việc một node có những thay đổi mà nhóm không có: nó đưa dữ liệu về common point (điểm chung với lịch sử mới), cất các document bị gỡ vào rollback file, rồi chép tiếp theo nhóm.

Majority commit point là gì, và nằm ở đâu

[tài liệu] replSetGetStatus().optimes cho một bức tranh từ góc nhìn của node đang hỏi:

Mỗi optime có dạng { ts, t }: ts là thứ tự lệnh, t là term của primary đã ghi nó. [tài liệu] Manual nói commit point "do primary tính" và mỗi member giữ trong bộ nhớ một snapshot dữ liệu tại điểm đó để trả lời read concern "majority" (bài Isolation: read concern đã đo majority đọc cũ hơn local khi hai secondary tạm mất; ở đây ta xem điểm ấy trong rs.status()).

Vì sao một lệnh có đa số rồi thì không bị rollback? [suy luận] Đây là cách lập luận đa số giao nhau: mọi election cần đa số phiếu, và bất kỳ hai đa số nào của ba node đều chung ít nhất một node. Node chung đó đã có lệnh, nên nó không bầu cho candidate thiếu lệnh đó (kiểm tra optime ở phần trước; lab không tái hiện một lần từ chối như vậy). Vậy primary mới luôn có lệnh.

Lab 2: nhìn majority commit point nhích và đứng yên

Câu hỏi: commit point đi theo ai, và nó làm gì khi đa số mất? Tôi chạy ba bước trên primary c (e4-commit-point.out), mỗi bước in optimes và, để so, stable timestamp của WiredTiger từ serverStatus (xem mục "Stable timestamp: ai dạy gì ở đâu").

Bước A: cụm khỏe. Sau một lúc nghỉ, tôi ghi một document w: 1 rồi hỏi rs.status() ngay lập tức, rồi 300 ms sau:

ngay sau lệnh ghi:   lastCommittedOpTime 1791600451:1   appliedOpTime 1791600451:3
300 ms sau:          lastCommittedOpTime 1791600451:3   appliedOpTime 1791600451:3

[quan sát] appliedOpTime đi trước lastCommittedOpTime ngay khi lệnh ghi xong, rồi commit point tới bằng nó khi secondary báo đã có. Để biết khoảng cách thường có là bao nhiêu, tôi ghi liên tục w: 1 và đọc optimes sau mỗi lệnh: trong 6.795 cặp (ghi, đọc status), hiệu số giữa thời điểm của appliedOpTime và của lastCommittedOpTime có median 6 ms, p95 42 ms, max 338 ms; 6.696 trong 6.795 mẫu có hiệu số lớn hơn 0 (mỗi mẫu đọc ngay sau một lệnh ghi). Nghĩa là trong cụm khỏe, commit point gần như luôn chạy sau primary vài ms và lệnh w: 1 luôn có một khoảng ngắn ở "chưa đa số".

Bước B: một secondary dừng (docker pause). Primary vẫn có đủ đa số (nó và secondary còn lại): commit point tiếp tục theo kịp appliedOpTime (cùng 1791600455:5), và w: "majority" được xác nhận sau 3 ms. Có một cái bẫy mà lần chạy đầu của tôi dính (e4-commit-point-run1-chained.out): tôi dừng đúng secondary mà secondary kia đang chép oplog từ nó (chaining, mặc định cho phép), nên w: "majority" timeout dù chỉ "mất một node". Tôi bỏ lần chạy đó; lần chạy chính thức kiểm tra sync source trước và dừng secondary không ai chép từ nó.

Bước C: cả hai secondary dừng (dưới 10 giây để primary chưa step down). Tôi ghi 5 document w: 1, rồi đọc:

lastCommittedOpTime          1791600455:6      (đứng yên)
readConcernMajorityOpTime    1791600455:6      (đứng yên)
WiredTiger stable timestamp  1791600455:6      (đứng yên)
appliedOpTime                1791600464:5      (đi tiếp, 8,66 giây phía trước)
đếm bằng readConcern local    = 6807
đếm bằng readConcern majority = 6802           (thiếu đúng 5 document vừa ghi)
w:"majority", wtimeout 1500   -> WriteConcernTimeout sau 1.521 ms

[quan sát] Khi đa số mất, ba chỉ số của phần đã có đa số đứng yên còn appliedOpTime đi tiếp, và 5 lệnh w: 1 được xác nhận nhưng chưa thể đọc bằng majority. Lệnh w: "majority" timeout, nhưng nó vẫn được áp dụng trên primary (appliedOpTime lên 1791600464:6): timeout không phải thất bại (bài Durability: lab majority). 1 giây sau khi mở lại hai secondary, commit point đã bằng appliedOpTime (1791600464:6); 3 giây sau, hai cách đếm cùng ra 6.808, tức 6.807 cộng document của lệnh đã timeout.

Một chi tiết nên biết: dòng member trong rs.status() là thông tin heartbeat nên có thể chậm vài giây. [quan sát] Ở bước B, optime của hai secondary hiển thị còn thấp hơn commit point; 1 giây sau khi mở lại hai secondary, dòng member của chúng vẫn ghi 1791600455:6 dù commit point đã ở 1791600464:6. [suy luận] Commit point được tính từ thông tin cập nhật nhanh hơn heartbeat, nên đừng suy ra commit point bằng cách đọc dòng member.

Stable timestamp: ai dạy gì ở đâu

Bài WiredTiger MVCC giới thiệu bốn timestamp (read, oldest, stable, pinned) từ góc nhìn storage engine, và quan sát ở một node rằng stable timestamp trùng lastCommittedOpTime; nó chỉ dự đoán rằng với nhiều node stable timestamp không thể vượt commit point. [quan sát] Lab trên thấy điều đó ở ba node: ở cả 7 lần tôi in trạng thái (qua ba bước), stable timestamp của WiredTiger bằng đúng lastCommittedOpTime (ví dụ 1791600455:6 ở bước C), kể cả lúc appliedOpTime đã đi trước 8,66 giây. Bảy lần quan sát chưa chứng minh được "không thể vượt". [suy luận] Đó là lý do rollback có chỗ để về: WiredTiger giữ được dữ liệu tại một mốc mà đa số đã có; ở Lab 3, stableTimestamp lúc rollback trùng đúng common point.

Còn ba thứ không được dạy ở đây: update chain và history store (bài WiredTiger MVCC: update chain); checkpoint ghi dữ liệu thế nào (Journal: checkpoint); và lastStableRecoveryTimestamp trong rs.status(), trường manual ghi "dùng nội bộ". [quan sát] Nó đứng ở 1791600397:1 suốt ba bước và chỉ nhảy lên 1791600464:6 sau khi hai secondary được mở lại; [suy luận] nó đi theo checkpoint chứ không theo từng lệnh.

Vì sao w: 1 có thể bị rollback

Kịch bản partition của phần trước, nhìn theo oplog:

oplog trên a (primary cũ, term 30)        oplog trên b (primary mới)
  ... 11 12 ─┬─ 13 14 15 ... (w:1, chỉ trên a)
             │
             └─ 13' (dòng mở term 31) 14' ...   (b, w:majority)
  common point = 12   →   a phải bỏ 13, 14, 15

Primary a nhận w: 1 trong lúc bị cô lập: các dòng 13, 14, 15 chỉ có trên a. Khi a nối lại, nó thấy lịch sử của nhóm khác lịch sử của nó kể từ sau dòng 12. Lịch sử đúng là lịch sử có đa số, tức của b; những dòng chỉ có trên a bị bỏ. [tài liệu] Rollback chỉ cần thiết khi primary đã nhận lệnh ghi mà secondary chưa kịp sao chép; một lệnh ghi đã kịp sang một member khác thì không bị rollback nếu member đó vẫn liên lạc được với đa số. [suy luận] Lý do là kiểm tra optime (phần trước): member đó chặn phiếu của candidate thiếu lệnh, nên primary mới phải là nó hoặc một node có lệnh. w: 1 không hứa điều đó, và đó là cái giá đã thấy ở bài Durability & Consistency.

Rollback làm những gì

[tài liệu] Manual mô tả hai thuật toán: recover to a timestamp, mặc định, đưa node về một thời điểm nhất quán rồi áp dụng lại các lệnh cho tới khi catch up với nhánh lịch sử của sync source, không giới hạn lượng dữ liệu; và rollback via refetch, chỉ khi enableMajorityReadConcern bằng false, giới hạn 300 MB. Từ MongoDB 5.0 enableMajorityReadConcern luôn là true và không đổi được, nên trên các bản hiện tại chỉ còn thuật toán đầu. Giới hạn còn lại là thời gian: rollbackTimeLimitSecs mặc định 24 giờ, đo giữa lệnh chung đầu tiên và dòng oplog cuối cùng của node bị rollback. [tài liệu] Từ 4.2, mọi thao tác của người dùng đang chạy bị kill khi node vào trạng thái ROLLBACK.

[quan sát] Log của lab (Lab 3) cho thấy thứ tự thực tế, mọi dòng ở mức I (info), thuộc component REPL hoặc ROLLBACK:

1. Starting rollback due to fetcher error (OplogStartMissing: the sync source's oplog and our oplog have diverged): hai oplog đã diverge, tức tách thành hai nhánh từ một điểm chung; node nhận ra khi dòng đầu của batch lấy từ sync source mới không nối được với dòng cuối của nó.
2. Rollback using 'recoverToStableTimestamp' method, Transition to ROLLBACK.
3. Finding common point rồi Rollback common point (một optime { ts, t }).
4. Preparing to write deleted documents to a rollback file: mỗi collection bị ảnh hưởng một file.
5. Rolling back to the stable timestamp, rồi ... completed by storage engine: WiredTiger bỏ các thay đổi sau stable timestamp. Đây là chỗ chữ "rollback to stable" ở bài Journal: crash recovery chạy 0 ms ở standalone mà giờ có việc thật.
6. Operations reverted by rollback (đếm số lệnh theo loại), Marking to truncate all oplog entries with timestamps greater than common point, Recovering from stable timestamp.
7. Rollback complete, Rollback summary, Transition to SECONDARY.

Rollback file. [tài liệu] Dữ liệu bị gỡ được ghi thành BSON ở <dbpath>/rollback/<collection UUID>/removed.<timestamp>.bson, đọc bằng bsondump; lệnh xoá document và drop collection không được ghi vào đó. Manual khuyên đọc file rồi tự quyết định xử lý, không có gì tự động đưa document trở lại. [quan sát] Ngoài file của collection, lab còn thấy một file nữa ở rollback/local.oplog.rs/ chứa các dòng oplog bị bỏ.

Lab 3: một rollback thật

Câu hỏi: bao nhiêu lệnh w: 1 đã được xác nhận bị mất, và rollback mất bao lâu? Kịch bản: primary bị cô lập vào Docker network riêng; một client Node.js chạy trong chính network đó ghi w: 1 liên tục vào nó (kết nối thẳng); sau 14,6 đến 16,2 giây một client khác ghi w: "majority" vào primary mới; hết 30 giây tôi nối mạng lại cho primary cũ. Ba lần (mẫu nhỏ), mỗi lần primary cũ là node khác (e5-rollback-t1.out đến t3.out).

(Mỗi số "revert" lớn hơn số xác nhận đúng 1: document khởi động warm-… của client.) Primary cũ nhận ghi trong khoảng 9 giây (9,0 đến 9,3) trước khi step down; sau đó mọi lệnh ghi trả NotWritablePrimary (138 đến 140 lệnh bị từ chối ở mỗi lần).

Đây là các dòng log chính của lần 1 (e5-rollback-t1.out, rút gọn; số là mili giây sau lúc cô lập):

+9913   "Stepping down from primary in response to heartbeat"
+30329  "Starting rollback due to fetcher error"  error: OplogStartMissing: the sync source's oplog
        and our oplog have diverged, going into rollback. our last optime fetched: { ts: Timestamp(1791600592, 57), t: 30 }.
        optime of first document in batch: { ts: Timestamp(1791600597, 1), t: 31 }
+30329  "Rollback using 'recoverToStableTimestamp' method"   "Transition to ROLLBACK"
+30339  "Rollback common point"  commonPointOpTime { ts: Timestamp(1791600580, 1), t: 30 }
+30460  "Rolling back to the stable timestamp"  stableTimestamp Timestamp(1791600580, 1)
+30551  "Rolling back to the stable timestamp completed by storage engine"  attempts: 0
+30564  "Operations reverted by rollback"  insert: 1281, update: 0, delete: 0
+30630  "Rollback summary"  ... "wallClockTimeDiff": 9, "rollbackCommandCounts": { "insert": 1281 },
        "rollbackDataFileDirectory": "/data/db/rollback/18d7f371-76d0-4acd-aedc-5242ebc8d6d7"
+30630  "Transition to SECONDARY"

[quan sát] Ba điều đáng chú ý. Thứ nhất, mọi lệnh w: 1 được xác nhận đều mất: 1.280, 1.132 và 1.345 lệnh mà client đã nhận acknowledged: true; sau rollback cả ba node đều có 0 document của primary cũ, và đều có đủ document w: "majority" của primary mới. Thứ hai, commonPointOpTime có t: 30 còn lệnh đầu của lịch sử mới có t: 31: hai lịch sử diverge đúng ở ranh giới term. Thứ ba, rollback chỉ là một phần nhỏ của thời gian: 91 ms cho bước storage engine, 301 ms tổng cộng; khoảng chờ giữa lệnh nối mạng và lúc rollback bắt đầu là 0,18 s, 0,52 s và 13,3 s. [suy luận] Node phải tìm lại sync source rồi mới phát hiện hai oplog đã diverge. Tôi không giải thích được vì sao lần 3 chờ 13,3 s: log mặc định không nói.

Việc hỏi replSetGetStatus mỗi 100 ms không bắt được trạng thái ROLLBACK (nó chỉ kéo dài 170 đến 301 ms), nên trạng thái này chỉ thấy trong log, không thấy bằng việc thăm dò.

Kết luận cho ứng dụng: rollback không báo cho client nào. Dữ liệu w: 1 đã xác nhận và bị rollback biến mất khỏi mọi truy vấn và chỉ còn trong một file trên đĩa của node cũ. Cách tránh là ghi bằng w: "majority" ([tài liệu] từ 5.0 đó là write concern mặc định của hầu hết các triển khai); hoặc chấp nhận mất và biết nó có thể lớn cỡ chín, mười giây ghi, như lab này.

Cột mốc: Bạn đã có thể giải thích majority commit point là gì và vì sao nó đứng yên khi đa số mất, đọc được log một lần rollback (common point, rollback to stable, rollback file), và nói vì sao w: 1 đã xác nhận vẫn mất. Phần sau nói ứng dụng nhìn thấy gì.

Hỏi & đáp