Log là trụ cột rẻ nhất trong ba trụ cột quan sát — đó là điều ai cũng nói. Bài này đo xem "rẻ" là bao nhiêu, trên bốn cách ghi và bốn mức.
Một dòng log được ghi thật
Cùng nội dung — một mức, một số yêu cầu, một thông điệp — ghi ra /dev/null để loại bỏ hoàn toàn ổ đĩa:
| Cách ghi | ns mỗi dòng | So với nhanh nhất |
|---|---|---|
Python: f-string rồi write thẳng |
84 | 1× |
Go: fmt.Fprintf thẳng |
225 | 2,7× |
Go: log.Printf (thư viện chuẩn) |
313 | 3,7× |
Node: template string rồi write |
344 | 4,1× |
Node: JSON.stringify rồi write |
518 | 6,2× |
Go: slog JSON |
548 | 6,5× |
Go: slog Text |
582 | 6,9× |
Python: json.dumps rồi write |
850 | 10,1× |
Python: logging.info |
4.467 | 53× |
Thư viện log của Python đắt gấp 53 lần
Dòng cuối là điều bất ngờ nhất. Cùng một dòng log, cùng ghi ra cùng một chỗ: 84 ns nếu tự làm, 4.467 ns nếu qua logging.
Phần chênh không phải định dạng chuỗi. Ba mươi tám phần trước tôi đã đo trong C rằng định dạng gần như miễn phí; ở đây cũng vậy — f-string một mình tốn 84 ns.
Phần chênh là bộ máy của chính thư viện: tạo một đối tượng LogRecord, duyệt cây logger tìm handler, chạy qua các bộ lọc, gọi formatter, khoá và mở khoá.
Điều đó không có nghĩa logging sai. Nó đổi 4,4 µs lấy những thứ mà 84 ns không có: cấu hình theo từng module, nhiều đích ghi, xoay vòng tệp, ngữ cảnh dùng chung. Nhưng nếu dịch vụ của bạn ghi 50 dòng cho mỗi yêu cầu, đó là 223 µs mỗi yêu cầu chỉ để đi qua thư viện.
Kiểm chứng nhanh trong hệ thống của bạn: nhân số dòng log mỗi yêu cầu với con số của ngôn ngữ bạn dùng, rồi so với ngân sách thời gian của một yêu cầu.
Go và Node rẻ hơn Python 8 lần
slog JSON của Go: 548 ns. JSON.stringify của Node: 518 ns. json.dumps + logging của Python: 4.467 ns.
Cả ba làm cùng một việc. Khác biệt nằm ở chỗ slog được thiết kế sau khi mọi người đã học được bài học về chi phí — nó tránh cấp phát, dùng kiểu tĩnh, và không dựng đối tượng trung gian cho mỗi dòng.
Đây cũng là lý do các thư viện log "thế hệ mới" của Go (zerolog, zap) tồn tại: chúng đẩy con số này xuống thấp hơn nữa bằng cách bỏ hẳn việc dựng chuỗi.
slog JSON nhanh hơn slog Text
548 ns so với 582 ns. JSON nhanh hơn văn bản, ngược với trực giác.
Tôi chạy lại ba lần và khoảng cách giữ nguyên chiều. Lý do nằm ở cách hai handler được cài đặt: bộ xử lý JSON của slog có đường đi nhanh cho các kiểu thường gặp và ghi thẳng byte, trong khi bộ xử lý Text phải xử lý việc trích dẫn và thoát ký tự theo quy tắc phức tạp hơn.
Bài học chung: "JSON chậm hơn văn bản" là giả định, không phải sự thật. Nó đúng ở Python (850 so với 84 ns) và Node (518 so với 344 ns), sai ở Go. Cách duy nhất để biết là đo trong chính môi trường của mình.
Bốn mức: khi log bị tắt
| Cách viết | Go | Node | Python |
|---|---|---|---|
| Có kiểm tra mức trước khi dùng đối số | 3 ns | 6 ns | 47 ns |
| Truyền đối số rời, để thư viện tự bỏ qua | 12 ns | 6 ns | 74 ns |
| Nối chuỗi ngay tại chỗ gọi | 63 ns (5,3×) | 14 ns (2,3×) | 104 ns (1,4×) |
Ba điều rút ra.
Log bị tắt rẻ ở mọi ngôn ngữ — vài chục nano giây. So với 548 ns của một dòng được ghi thật, đó là 4%. Nghĩa là để mức DEBUG trong mã nguồn gần như không tốn gì, miễn là nó không được bật.
Nối chuỗi tại chỗ gọi làm hỏng điều đó, và mức độ khác nhau theo ngôn ngữ: Go 5,3 lần, Node 2,3 lần, Python 1,4 lần. Con số Go lớn nhất vì đường đi khi bị tắt của nó rẻ nhất — 12 ns, nên 51 ns thêm vào là rất nhiều theo tỷ lệ.
Kiểm tra mức tường minh vẫn có ích, kể cả khi thư viện tự kiểm tra: 3 so với 12 ns ở Go, 47 so với 74 ns ở Python. Nhưng khoảng cách nhỏ tới mức chỉ đáng làm trong vòng lặp rất nóng.
Một khuyến nghị bị số liệu bác bỏ
Lời khuyên kinh điển cho Python là dùng %s lazy thay vì f-string:
logger.info("xong yeu cau %s", i) # duoc khuyen
logger.info(f"xong yeu cau {i}") # bi che
Khi log bật:
%s lazy : 4.467 ns
f-string : 4.257 ns
f-string nhanh hơn. Bộ máy của logging lấn át hoàn toàn phần định dạng, và khi log được ghi thật thì %s vẫn phải chạy — chỉ là chạy bên trong thư viện thay vì ở chỗ gọi.
Lời khuyên đó chỉ đúng cho trường hợp log tắt: 74 so với 104 ns. Một khoảng 30 ns.
Tôi nêu chuyện này không phải để bảo bạn ngừng dùng %s — nó vẫn đúng, và nó còn giúp các công cụ gom log theo mẫu. Chỉ là lý do "vì nhanh hơn" không đứng vững với số liệu, và biết đúng lý do thì áp dụng đúng chỗ.
Chỗ tôi không đo được
Tôi đo thư viện chuẩn của ba ngôn ngữ, không đo zerolog, zap, structlog hay pino. Chúng đều tuyên bố nhanh hơn đáng kể, và so sánh công bằng cần dựng cùng một cấu hình handler — việc đó xứng đáng một bài riêng.
Tôi cũng ghi ra /dev/null, nên không có chi phí ổ đĩa nào trong bảng. Trong sản phẩm, log đi qua tệp, qua stdout của container, rồi qua bộ thu thập — và phần đó thường lớn hơn mọi con số ở đây. Bài sau sẽ đo phần đó.
Thử ba mươi giây
Đo thư viện log của chính bạn:
import logging, time, os
N = 100000
dev = open(os.devnull, "w")
lg = logging.getLogger("x"); lg.setLevel(logging.INFO)
lg.addHandler(logging.StreamHandler(dev))
def q(name, f):
f(0)
t = time.perf_counter_ns()
for i in range(N): f(i)
print(f"{name:<34} {(time.perf_counter_ns()-t)/N:8.0f} ns")
q("logging.info (bat)", lambda i: lg.info("xong %s", i))
q("write thang", lambda i: dev.write(f"INFO req={i}\n"))
lg.setLevel(logging.WARNING)
q("logging.debug (tat)", lambda i: lg.debug("xong %s", i))
Lấy dòng đầu nhân với số dòng log mà dịch vụ ghi cho mỗi yêu cầu. Nếu kết quả vượt 1% ngân sách thời gian của một yêu cầu, bạn có một khoản tiết kiệm dễ lấy — và nó nằm ở việc ghi ít dòng hơn, không phải ở việc chọn thư viện khác.
Phần sau: log có cấu trúc — đo chi phí so với log văn bản.
