Sê-ri đã đo riêng từng trụ cột: log tốn gì, chỉ số tốn gì, trace tốn gì. Phần này đo thứ nằm giữa chúng — cái giá và lợi ích của việc nối chúng lại. Cụ thể: nhúng trace_id vào mỗi dòng log tốn thêm bao nhiêu, và đổi lại được gì khi có sự cố thật.

Nhúng trace_id vào log: trả gì, được gì

Bảng số liệu

Tập log mô phỏng một dịch vụ ở 1 000 yêu cầu mỗi giây, mỗi yêu cầu ghi 4 dòng log, cửa sổ điều tra 60 giây — tổng 240 000 dòng. Trong đó có đúng một yêu cầu bị lỗi, và ba dòng log khác của chính yêu cầu đó là thứ cần tìm.

Cái giá:

Dung lượng Byte mỗi dòng
Không có trace_id 28,73 MB 125,5
Có trace_id + span_id 45,89 MB 200,5
Chênh +59,8%

Quy ra ở mức 1 000 yêu cầu mỗi giây: 40,4 GB mỗi ngày thành 64,5 GB — thêm 24,1 GB.

Cái được — số dòng phải đọc để điều tra:

Cách làm Kết quả trả về
Không có trace_id, lọc theo dịch vụ và điểm cuối 48 000 dòng
Có trace_id, grep đúng mã đó 4 dòng

Giảm 12 000 lần.

Thời gian máy chạy, để đối chiếu:
grep theo dịch vụ + điểm cuối 20 ms
grep theo trace_id 14 ms

Điều đáng nhớ

Đây là một trong ít quyết định trong quan sát hệ thống mà đánh đổi hoàn toàn rõ ràng và tính được ra số. Trả 59,8% dung lượng log, nhận lại việc giảm 12 000 lần số dòng phải đọc. Hầu hết các quyết định khác trong sê-ri này đều mơ hồ hơn nhiều.

Không có trace_id thì bạn không có cách nào nhóm các dòng lại. Tìm ra dòng ERROR là dễ — một lệnh grep. Vấn đề là ba dòng còn lại của cùng yêu cầu đó không mang dấu hiệu nào để nhận ra. Chúng nằm lẫn giữa 240 000 dòng khác, và thứ duy nhất bạn lọc được là những đặc điểm chung như dịch vụ và điểm cuối — thứ mà 48 000 dòng khác cũng có.

Và điều dễ hiểu nhầm: thời gian máy chạy gần như không đổi. 20 ms so với 14 ms. Cả hai lệnh đều quét hết tệp, nên máy làm gần đúng một lượng công việc. Cái thay đổi không phải công việc của máy mà là công việc của người: đọc 4 dòng, hay lọc 48 000 dòng để tìm 3 dòng mình cần.

Đó cũng là lý do lợi ích này khó thấy trên bất kỳ bảng điều khiển nào. Nó không hiện ra thành CPU thấp hơn hay truy vấn nhanh hơn; nó hiện ra thành sự cố được xử lý xong trong mười phút thay vì hai tiếng.

Vì sao

Ba trụ cột trả lời ba câu hỏi khác nhau — phần đầu sê-ri đã đo chuyện đó. Nhưng khi điều tra thật, bạn không hỏi một câu; bạn đi từ câu này sang câu kia: chỉ số nói có vấn đề, trace nói chậm ở chặng nào, rồi bạn cần log của đúng chặng đó để biết chuyện gì đã xảy ra bên trong.

Mỗi bước chuyển đó cần một mã định danh chung. Không có nó, mỗi lần chuyển bạn phải bắc cầu bằng thời gian và điều kiện lọc — và cây cầu đó luôn rộng hơn cần thiết vì thời gian không phân biệt được yêu cầu này với yêu cầu khác xảy ra cùng lúc.

Ở 1 000 yêu cầu mỗi giây, "cùng lúc" nghĩa là 1 000 ứng viên cho mỗi giây bạn phải xem. Đó chính là nguồn gốc con số 48 000: 60 giây × 1 000 yêu cầu, chia cho 5 nhóm mà bộ lọc phân biệt được, nhân 4 dòng mỗi yêu cầu.

Còn 75 byte thêm vào mỗi dòng là trace_id 32 ký tự hex cộng span_id 16 ký tự, cộng tên hai trường và dấu ngoặc kép của JSON. Không có cách nào làm nó nhỏ hơn nhiều — mã định danh trace phải đủ dài để không trùng nhau trên toàn hệ thống.

Nghĩa là gì trong thực tế

  • Nếu đang phân vân, hãy bật. 59,8% là một con số lớn nhưng nó nằm trên một khoản chi phí đã biết và dự tính được. Con số 12 000 lần thì nằm trên thời gian của con người trong lúc đang có sự cố, và đó là thứ đắt hơn nhiều.
  • Nếu dung lượng thật sự là vấn đề, hãy cắt ở chỗ khác trước. Phần trước của sê-ri đã đo: lấy mẫu, giảm số dòng log, giãn chu kỳ. Cắt trace_id là cắt đúng thứ rẻ nhất về giá trị trên mỗi byte.
  • Nhúng cả span_id, đừng chỉ nhúng trace_id. Chi phí thêm là 16 ký tự, và nó cho bạn biết dòng log thuộc về chặng nào trong trace chứ không chỉ thuộc yêu cầu nào.
  • Kiểm tra rằng nó thật sự có mặt ở mọi dòng. Phần trước đã đo hậu quả của việc mất ngữ cảnh ở một chặng: trace gãy làm hai. Với log thì hậu quả tương tự nhưng âm thầm hơn — bạn grep một trace_id và nhận về ba dòng thay vì bốn, rồi kết luận sai rằng chặng thứ tư không chạy.
  • Số 12 000 lần tỷ lệ thuận với lưu lượng. Ở 10 000 yêu cầu mỗi giây, nó thành 120 000 lần. Dịch vụ càng bận thì việc nối càng đáng.

Chỗ tôi không kết luận được

Đây là log phẳng và công cụ là grep. Hệ thống thật dùng Loki hay Elasticsearch, và cả hai đều có chỉ mục. Phần trước của sê-ri đã đo: Elasticsearch trả lời truy vấn lọc trong 2–3 ms trên 200 000 dòng. Với chỉ mục, thời gian máy của cả hai cách đều nhỏ — nhưng số dòng trả về thì không đổi, và đó mới là con số bài này nói tới. Việc có chỉ mục không giúp bạn đọc 48 000 dòng nhanh hơn.

Tỷ lệ 59,8% phụ thuộc vào dòng log của bạn dài bao nhiêu. Dòng của tôi 125,5 byte là dòng ngắn; 75 byte thêm vào là một khoản lớn tương đối. Với dòng log 500 byte có thông điệp lỗi dài và dấu vết ngăn xếp, cùng 75 byte đó chỉ là 15%. Dịch vụ ghi log càng chi tiết thì việc nối càng rẻ tương đối.

Con số 48 000 lớn hơn nó đáng ra phải thế, vì một khiếm khuyết trong dữ liệu tôi sinh ra. Tôi gán service và endpoint bằng cùng một biểu thức i % 5, nên hai trường đó tương quan hoàn toàn: dịch vụ api luôn đi kèm điểm cuối /v1/cart. Vì thế lọc theo cả hai không hẹp hơn lọc theo một, và kết quả là 60 000 / 5 × 4 = 48 000 dòng thay vì 9 600 dòng nếu hai trường độc lập.

Tôi phát hiện ra khi kiểm lại phép tính để giải thích con số trong bài: 60 × 1 000 chia 25 nhân 4 ra 9 600, không khớp với 48 000 đo được. Con số đo được thì đúng — nó là kết quả thật của lệnh grep trên tệp thật — nhưng lời giải thích đầu tiên của tôi cho nó thì sai, và nếu không kiểm lại số học thì bài này đã đưa ra một cơ chế không tồn tại.

Với dữ liệu có hai trường độc lập thật, con số sẽ là 9 600 và tỷ lệ cải thiện là 2 400 lần thay vì 12 000. Vẫn là ba bậc độ lớn, nhưng đó là con số đúng hơn để mang đi.

Tôi không đo phần nối với chỉ số. Cơ chế cho việc đó là exemplar — Prometheus gắn một trace_id mẫu vào bucket histogram, cho phép nhảy từ điểm p99 trên biểu đồ sang đúng trace đã tạo ra nó. Nó là mảnh ghép còn thiếu giữa "có vấn đề" và "vấn đề ở đâu", và tôi chưa đo chi phí của nó.

Thử ba mươi giây

docker run --rm python:3.12-slim python - <<'EOF'
import json, secrets, os
N, DONG = 60_000, 4
for co in (False, True):
    p = "/tmp/l_%s.ndjson" % co
    with open(p, "w") as f:
        for i in range(N):
            tid = secrets.token_hex(16)
            for k in range(DONG):
                r = {"level": "INFO", "service": "api", "endpoint": "/v1/cart",
                     "msg": "step %d ok" % k, "duration_ms": 12.3}
                if co: r["trace_id"] = tid; r["span_id"] = secrets.token_hex(8)
                f.write(json.dumps(r, separators=(",", ":")) + "\n")
    kb = os.path.getsize(p)
    print("%-16s %8.2f MB  %6.1f byte/dong" % ("co trace_id" if co else "khong", kb/1048576, kb/(N*DONG)))
EOF

Chạy xong, lấy hiệu hai con số rồi nhân với lưu lượng của bạn — đó là hoá đơn mỗi ngày. Rồi tự hỏi lần gần nhất một sự cố mất bao lâu để tìm ra nguyên nhân, và bao nhiêu phần trong đó là đi tìm đúng những dòng log cần đọc.