Sự cố làm 0,2% request chậm gấp 56 lần mà p99 đứng yên ở 0,46 µs — chỉ p99.9 mới lộ ra 21,88 µs

Có một cách rất dễ tự bịt mắt mình mà không hề biết: nhìn một con số tổng hợp và tin rằng nó kể toàn bộ câu chuyện. Giống như đánh giá độ sâu một con sông bằng độ sâu trung bình rồi lội qua — con số ấy đúng, và bạn vẫn có thể chết đuối ở khúc sâu nhất mà nó đã làm mờ đi. Bài này mở sê-ri về quan sát hệ thống bằng đúng cái bẫy đó: tôi dựng một sự 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 log, metric, trace, và đo luôn cái giá của từng lăng kính.

(Các con số là độ trễ và thời gian đo trong container, không phải perf counter phần cứng.)

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:

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. Và giá của từng lớp quan sát:

Log còn sinh ra 11,34 MB cho 200 000 request, tức 59 byte mỗi request.

Bốn điều làm 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%, và 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à lộ 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, 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 thì phần đóng góp vào trung bình chỉ khoảng 11% — đúng bằng mức mọi người quen bỏ qua. Còn về giá, ba lớp đắt khác nhau vì làm 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ớ (+13,4%), trace cần bốn mốc thay vì hai (+20,0%), còn log phải định dạng một chuỗi và đẩy nó qua tầng vào ra — công đoạn đắt nhất (+43,1%) và còn để lại 59 byte mỗi request phải lưu, chuyển đi và trả tiền.

Ra thực tế thì chọn phân vị theo tỷ lệ sự cố bạn muốn bắt, 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. Đừng bao giờ cảnh báo theo max: ba lần chạy của tôi cho max 29,29 / 27,71 / 127,33 µs (cùng chương trình, cùng 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à 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 là 51 GB mỗi ngày, trả tiền cả ở khâu lưu lẫn khâu tìm. Và 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ỏ bước nào cũng khiến bước sau thành mò mẫm.

Mẫu số chung

Cái bẫy lõi ở đây — một con số tổng hợp vứt bỏ phần đuôi thì mù trước sự kiện ở đuôi, nên phải chọn thống kê khớp với thứ mình cần thấy — không riêng gì độ trễ web, nó đúng ở mọi nơi người ta tóm tắt một phân bố thành một con số.

Trong thế giới Java, đây đúng là lý do Micrometer/Actuator khuyến khích publish histogram và các phân vị cao (percentiles = 0.95, 0.99, 0.999) hay SLO buckets, thay vì chỉ một mean — và cái bẫy quen thuộc là dashboard Grafana mặc định vẽ avg latency, đúng cái làm mờ sự cố đuôi. Ai từng gỡ một "p50 đẹp mà khách vẫn than chậm" đều học lại bài này.

Trong Go, cùng chuyện: expvar/prometheus client cho Histogram để giữ được đuôi, và cộng đồng nhắc đi nhắc lại "đừng theo dõi mean latency" — một trung bình đẹp che đúng cái 0,2% đang đau.

Còn ở cơ sở dữ liệu, pg_stat_statements mặc định cho bạn mean_exec_time — con số dễ gây ngộ nhận nhất, vì một truy vấn đôi khi chậm khủng khiếp vẫn có mean thấp; muốn thấy đuôi phải bật slow query log với ngưỡng, hoặc dùng bản mới có thống kê phân vị. Cùng nguyên tắc: trung bình của thời gian query giấu đúng những lần query đau nhất.

Mẫu số chung: mọi phép tóm tắt một phân bố thành một con số đều vứt bỏ một phần, và sự kiện hiếm-nhưng-nặng luôn sống ở phần đuôi mà trung bình và phân vị thấp cắt đi — nên con số bạn chọn để theo dõi quyết định loại sự cố bạn có thể nhìn thấy, trước cả khi bàn tới công cụ. Vì thế câu hỏi đúng khi dựng một chỉ số không phải "nó có đẹp không" mà là "sự kiện nhỏ nhất tôi cần bắt chạm bao nhiêu phần trăm lưu lượng, và con số này có nhìn xuống tới đó không" — vì một dashboard toàn màu xanh chỉ có nghĩa là chưa có gì vượt qua cái ngưỡng bạn tình cờ chọn để nhìn.

Muốn tự thấy ngưỡng đó nằm ở đâu, chạy trong 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.