Trả thêm 59,8% dung lượng log để giảm số dòng phải đọc khi điều tra từ 48.000 xuống 4 — một đánh đổi hiếm khi rõ ràng đến thế

Hình dung một thư viện khổng lồ nơi mọi cuốn sách bị xé rời từng trang và đổ chung vào một đống. Mọi trang vẫn còn đó — không mất chữ nào — nhưng để đọc lại một cuốn, bạn phải bới cả đống tìm những trang thuộc về nó, mà chẳng có gì đánh dấu trang nào thuộc cuốn nào. Bây giờ tưởng tượng mỗi trang được đóng thêm một con dấu mã số cuốn sách. Đống trang vẫn to y hệt, tốn thêm chút mực — nhưng giờ tìm lại một cuốn chỉ là lọc theo con dấu. trace_id trong log chính là con dấu đó, và bài này tôi đo cái giá của mực và cái được của việc tìm.

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. (Đo trên tập log mô phỏng, không cần phần cứng đặc biệt.)

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á:

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:

Giảm 12 000 lần.

Thời gian máy chạy, để đối chiếu:

Vì sao đây là đánh đổi hiếm khi rõ đến thế

Đâ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 — cái này thì hai con số nằm ngay trên bàn.

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ó. Đúng cái đống trang sách không con dấu.

Và điều dễ hiểu nhầm nhất: 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 con số 48.000

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 công việc hằng ngày

• 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.

Cùng một sức mạnh của "khoá tương quan", đổi ngăn xếp

Chuyện "gắn một mã định danh chung để nối các mẩu rời rạc của cùng một đơn vị công việc lại" không riêng gì log của microservice — nó là một mẫu tương quan lặp ở mọi tầng.

Trong thế giới Java, đây đúng là lý do MDC (Mapped Diagnostic Context) của SLF4J tồn tại: bạn đặt MDC.put("traceId", id) một lần đầu request, và mọi dòng log sau đó — dù ở tầng service, repository, hay một @Async khác (nếu ngữ cảnh được truyền qua) — tự mang theo mã đó qua pattern %X{traceId}. Spring Cloud Sleuth / Micrometer Tracing tự động hoá đúng việc này: inject trace_id/span_id vào MDC. Cái giá cũng đúng như bài này — mỗi dòng log dài thêm — và cái được cũng đúng: grep một id ra cả câu chuyện của một request.

Trong Go, không có MDC ngầm, nên mã tương quan phải đi tường minh qua context.Context và một structured logger như slog: logger.With("trace_id", id) tạo một logger con mang sẵn mã cho mọi dòng của request đó. Trần trụi hơn Java, nhưng cùng nguyên tắc, và cùng cái bẫy "quên gắn ở một nhánh code là mất tương quan ở đó".

Còn ở cơ sở dữ liệu, họ hàng gần nhất là application_name / session id trong slow query log, hay một request_id gắn vào comment SQL (/* trace_id:abc */ SELECT ...). Kỹ thuật "SQL comment tagging" này cho phép nối một truy vấn chậm trong log của DB về đúng request ứng dụng đã sinh ra nó — chính là bắc cây cầu cuối cùng từ trace sang tầng CSDL, cùng ý tưởng con dấu mã số.

Mẫu số chung: giá trị lớn nhất của một hệ quan sát không nằm ở việc thu được nhiều dữ liệu, mà ở việc có một khoá chung để nối các mẩu dữ liệu của cùng một đơn vị công việc lại — và cái khoá đó rẻ để thêm nhưng gần như bất khả để tái tạo sau khi dữ liệu đã ghi mà không có nó. Chi phí là vài chục byte mỗi dòng; cái được là biến việc "bới cả đống rơm" thành việc "lọc một con dấu". Nên câu hỏi đúng khi thiết kế logging không phải "log này có đủ thông tin không" mà là "tôi có nối được dòng log này về đúng request, trace, và người dùng đã sinh ra nó không".

Muốn tự tính cái giá cho hệ của mình, chạy thử:

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.