Mở đầu sê-ri về quan sát hệ thống, và tôi muốn bắt đầu bằng câu hỏi ít được hỏi nhất: ba trụ cột log, metric, trace khác nhau ở chỗ nào, và mỗi cái đáng bao nhiêu tiền? Nên tôi dựng một sự cố có thật — 0,2% số request đi qua một nhánh chậm — rồi soi nó bằng cả ba lăng kính, và đo luôn cái giá của từng lăng kính.
Bảng số liệu
Chương trình xử lý 200 000 request, mỗi request chia ba giai đoạn: phân tích, truy vấn, dựng kết quả. Cứ 500 request thì một request đi qua nhánh truy vấn chậm. Công việc là tính toán thật chứ không phải sleep. Container debian:12-slim, clang 14 -O2, trung vị của ba lần chạy.
Sự cố nhìn từ metric:
| Giá trị | |
|---|---|
| Trung bình | 0,45 µs |
| p50 | 0,42 µs |
| p90 | 0,42 µs |
| p99 | 0,46 µs |
| p99.9 | 21,88 µs |
| max | 29,29 µs |
Sự thật bên dưới, thứ mà chỉ tôi biết vì tôi dựng ra nó: 199 600 request bình thường mất trung bình 0,40 µs, còn 400 request chậm mất trung bình 22,47 µs — chậm gấp 56 lần.
Giá của từng lớp quan sát:
| Cấu hình | ns mỗi request | Thêm |
|---|---|---|
| Không quan sát gì | 388,9 | — |
| + metric | 440,6 | +13,4% |
| + trace 4 mốc | 467,4 | +20,0% |
| + log một dòng | 557,4 | +43,1% |
Log còn sinh ra 11,34 MB cho 200 000 request, tức 59 byte mỗi request.
Điều đáng nhớ
Nói lại theo cách khác, vì đây là chỗ khiến bảng điều khiển nói dối:
p99 hoàn toàn mù trước sự cố này. p50 là 0,42 µs, p99 là 0,46 µs — chênh 10%, đúng bằng mức nhiễu bình thường. Trong khi đó có 400 request chậm gấp 56 lần đang thực sự xảy ra. Lý do rất số học: sự cố chạm vào 0,2% số request, mà p99 chỉ nhìn tới 1% chậm nhất — 0,2% nằm gọn bên trong phần đuôi mà p99 cắt bỏ.
Trung bình còn tệ hơn. Nó nhích từ 0,40 lên 0,45 µs, tăng 12%. Không ai mở cuộc điều tra vì một chỉ số tăng 12%.
Chỉ p99.9 mới lộ ra, và nó lộ ra rất to: 21,88 µs, gấp 52 lần p50. Cùng một dữ liệu, cùng một sự cố — khác nhau ở chỗ bạn chọn con số nào để vẽ lên bảng điều khiển.
Và ba trụ cột không thay thế được nhau. Metric nói có vấn đề. Log nói request nào. Trace nói chậm ở đâu trong request. Trong phép đo này, trace cho thấy giai đoạn truy vấn chiếm 62% thời gian của một request bình thường nhưng 99% thời gian của một request chậm — đó là câu trả lời mà không phân vị nào và không dòng log nào đưa ra được.
Vì sao
Phân vị là một phép cắt, và mỗi phép cắt vứt đi phần nằm ngoài nó. p99 trả lời câu "request chậm thứ 1% là bao nhiêu", nên nó chỉ nhìn thấy sự cố khi sự cố ảnh hưởng hơn 1% lưu lượng. Sự cố ảnh hưởng 0,2% cần p99.8 trở lên mới chạm tới. Quy tắc rút ra rất đơn giản: phân vị bạn theo dõi quyết định tỷ lệ sự cố nhỏ nhất mà bạn có thể thấy.
Trung bình thì không cắt gì, nhưng nó chia đều: 400 giá trị lớn hoà tan vào 199 600 giá trị nhỏ. Với tỷ lệ 0,2% và hệ số 56 lần, phần đóng góp vào trung bình chỉ là khoảng 11% — đúng bằng mức mà mọi người quen bỏ qua.
Còn về giá: ba lớp đắt khác nhau vì chúng làm những việc khác nhau. Metric chỉ cần hai mốc thời gian và vài phép cộng vào bộ đếm trong bộ nhớ, nên +13,4%. Trace cần bốn mốc thời gian thay vì hai, nên +20,0%. Log phải định dạng một chuỗi và đẩy nó qua tầng vào ra — đó là công đoạn đắt nhất, +43,1%, và nó còn để lại 59 byte mỗi request phải lưu, chuyển đi và trả tiền.
Nghĩa là gì trong thực tế
- Chọn phân vị theo tỷ lệ sự cố bạn muốn bắt được, không theo thói quen. Muốn thấy sự cố chạm 0,1% lưu lượng thì phải có p99.9. Vẽ p99 rồi yên tâm là tự bịt mắt mình.
- Đừng bao giờ cảnh báo theo
max. Trong ba lần chạy của tôi, max là 29,29 / 27,71 / 127,33 µs — cùng một chương trình, cùng một dữ liệu. Một giá trị đơn lẻ thì nhiễu chi phối, còn phân vị thì ổn định: p99.9 cho 21,88 / 21,92 / 21,88 µs. - Metric là thứ bật liên tục, trace là thứ lấy mẫu, log là thứ phải cân nhắc. Thứ tự giá tiền — 13%, 20%, 43% — gợi ý đúng thứ tự đó. Với request 389 ns thì log một dòng gần như tốn bằng một nửa công việc thật.
- Ước lượng dung lượng log trước khi bật. 59 byte mỗi request nghe không đáng gì, nhưng ở 10 000 request mỗi giây thì đó là 51 GB mỗi ngày, và bạn sẽ trả tiền cho từng gigabyte đó ở khâu lưu trữ lẫn khâu tìm kiếm.
- Khi có báo động, đọc theo thứ tự: metric để biết có và từ lúc nào, log để lấy vài mã request cụ thể, trace để biết giai đoạn nào phình ra. Bỏ qua bước nào cũng khiến bước sau thành mò mẫm.
Chỗ tôi không kết luận được
Đây là mô hình, không phải một dịch vụ thật. Không có mạng, không có ổ đĩa, không có tranh chấp khoá. Con số 388,9 ns cho một "request" nhỏ hơn nhiều so với bất kỳ dịch vụ HTTP nào — nên các tỷ lệ phần trăm chi phí ở đây là cận trên. Với một request thật mất 5 ms, một dòng log 170 ns sẽ chỉ là 0,003%. Điều đó không làm sai kết luận về thứ tự giá, nhưng làm thay đổi hẳn mức độ nghiêm trọng.
Tôi đo chi phí ghi log ở dạng đơn giản nhất: fprintf vào một tệp đã đệm, một dòng phẳng, không khoá, một luồng. Log có cấu trúc, nhiều luồng, hay đẩy qua mạng đều đắt hơn — phần sau của sê-ri sẽ đo bốn thư viện log thật.
Một sai lầm khi đo, và cách nó lộ ra. Bản đầu tiên cho kết quả "giai đoạn truy vấn chiếm 92% thời gian của request bình thường". Con số đó không thể đúng: giai đoạn truy vấn chỉ có 300 trong tổng 500 đơn vị công việc, nên nó phải quanh 60%. Tính ngược lại thì giai đoạn 1 và 3 chỉ tốn 20 ns cho 200 đơn vị, trong khi giai đoạn 2 tốn 280 ns cho 300 đơn vị — mỗi đơn vị lệch nhau chín lần, vô lý.
Nguyên nhân: tôi gọi work(100) ở cả giai đoạn đầu và giai đoạn cuối. Hàm đó thuần tuý và cùng tham số, nên clang nhận ra hai lời gọi cho cùng một kết quả và xoá bớt một. Chữa bằng cách thêm một tham số hạt giống khác nhau cho mỗi lời gọi. Sau khi sửa, tỷ lệ về 62% — khớp với tỷ lệ công việc thật.
Bài học không phải là "cẩn thận với clang", mà là: kiểm tra tính nhất quán nội tại của bảng kết quả trước khi tin nó. Con số 92% không mâu thuẫn với thực tế nào ở bên ngoài — nó chỉ mâu thuẫn với một con số khác trong cùng bảng, và đó là tất cả những gì tôi có để phát hiện ra.
Thử ba mươi giây
python3 - <<'EOF'
import random, statistics
random.seed(7)
# 199 600 request binh thuong quanh 0,40 us; 400 request cham 22,47 us
xs = [random.gauss(0.40, 0.03) for _ in range(199_600)]
xs += [random.gauss(22.47, 1.0) for _ in range(400)]
xs.sort()
def p(q): return xs[int(q*(len(xs)-1)/100)]
print("trung binh %.2f | p50 %.2f | p90 %.2f | p99 %.2f | p99.9 %.2f | max %.2f"
% (statistics.fmean(xs), p(50), p(90), p(99), p(99.9), xs[-1]))
EOF
Chạy nó, rồi đổi 400 thành 4000 (2% thay vì 0,2%) và chạy lại. p99 sẽ nhảy từ chỗ không thấy gì lên hơn hai mươi micro giây. Ngưỡng nằm ở đúng đó, và biết nó nằm ở đâu là toàn bộ điều bài này muốn nói.
