Cùng một dòng log: print tốn 0,18 µs, logging tốn 4,51 µs — và 94% khoản chênh không nằm ở chỗ ai cũng nhắm vào khi tối ưu

Khi một dòng log tốn tiền, trực giác ai cũng chỉ tay vào phần nhìn thấy được: cái dấu thời gian đầu dòng, phần định dạng JSON, chuỗi được nối. Nhưng hoá ra đó là chỗ rẻ nhất. Phần đắt là thứ vô hình xảy ra trước khi một ký tự nào được định dạng — và bài này tôi đo để chỉ ra chính xác tiền đi đâu. Phần trước đo ghi một dòng log làm mỗi request đắt thêm 43%, nhưng đó là fprintf trong C, trường hợp rẻ nhất có thể. Lần này tôi đo cái người ta thật sự dùng: bốn thư viện log của Python, cộng print làm mốc, và bốn mức để xem một lời gọi bị lọc bỏ có thật sự miễn phí không.

(Các con số là thời gian trên mỗi dòng đo trong container, không phải perf counter phần cứng.)

Bảng số liệu

Python 3.12.14 trong container, ghi ra tệp đã đệm, một luồng, 200 000 dòng mỗi lô, lấy trung vị của 5 lô rồi lặp lại cả bài ba lần.

Ba lần chạy cho logging là 4,34 / 4,53 / 4,51 µs; cho loguru là 7,06 / 6,98 / 6,95 µs. Khoảng cách 25 lần giữa print và logging lớn tới mức tôi phải bóc nó ra xem tiền đi đâu:

Và bốn mức, với ngưỡng đặt ở WARNING:

Ba kết quả, đều ngược chỗ người ta hay tìm

Chi phí của logging không nằm ở định dạng thời gian. Đó là chỗ tôi đoán trước khi đo, và là chỗ hầu hết các bài tối ưu nhắm vào. Thực tế %(asctime)s chỉ tốn 0,76 µs, tức 17% tổng chi phí; còn 94% — 3,43 trong 3,64 µs — biến mất vào bộ khung: dựng đối tượng LogRecord, đi qua chuỗi logger cha con, lấy khoá, gọi qua từng handler. Formatter chỉ là công đoạn cuối và là công đoạn rẻ.

Lời gọi bị lọc bỏ thì rẻ thật. 57,9 ns so với 4 758,6 ns — chênh 82 lần. Nghĩa là để nguyên lg.debug(...) rải khắp mã nguồn trong môi trường chạy thật là quyết định an toàn. Đó là tin tốt, và nó có đúng một điều kiện.

Điều kiện đó là: đừng dùng f-string. Cùng một lời gọi bị lọc bỏ:

f-string được Python tính trước khi hàm debug được gọi, nên chuỗi vẫn được dựng đầy đủ rồi vứt đi ngay bên trong. Bạn trả tiền cho một dòng log không bao giờ tồn tại.

Vì sao

print chỉ làm hai việc: nối chuỗi và đẩy byte vào bộ đệm của tệp — 0,18 µs là sàn vật lý của việc đó trong Python. logging làm nhiều hơn hẳn, và phần lớn không phải để định dạng: mỗi lời gọi tạo một LogRecord — một đối tượng với khoảng hai chục thuộc tính, gồm cả việc dò ngược ngăn xếp để lấy tên tệp và số dòng — rồi bản ghi đi lên cây logger, qua bộ lọc, tới từng handler, mỗi handler lấy một khoá threading.RLock trước khi ghi. Đó là cái giá của việc logging có thể định tuyến một dòng tới nhiều đích, lọc theo module, và an toàn khi nhiều luồng cùng ghi. structlog nhanh hơn logging (3,96 so với 4,51 µs) không phải vì nó tối ưu hơn mà vì trong cấu hình tôi dùng nó đi thẳng qua PrintLoggerFactory và bỏ qua toàn bộ bộ khung của thư viện chuẩn — cắm structlog vào sau logging thì chi phí cộng dồn chứ không thay thế. loguru đắt nhất (6,98 µs) vì nó làm nhiều nhất cho mỗi lời gọi: bắt ngữ cảnh, hỗ trợ tô màu, chuẩn bị sẵn đường bắt ngoại lệ với dấu vết đầy đủ — những thứ có ích, nhưng được trả tiền ở mỗi dòng, kể cả dòng không cần tới chúng. Còn chuyện lời gọi bị lọc rẻ tới 82 lần: Logger.debug kiểm mức ngay dòng đầu và trả về trước khi chạm bất cứ thứ gì đắt, nên 57,9 ns kia gần như chỉ là chi phí gọi một hàm Python và một phép so sánh số nguyên.

Ra thực tế thì quy đổi ra ngân sách trước khi tranh luận: một dịch vụ 1 000 request mỗi giây ghi một dòng mỗi request tốn 4,5 ms CPU mỗi giây — 0,45% một nhân, không đáng bàn; cũng dịch vụ đó ở 50 000 request mỗi giây thì tốn 22,5% một nhân, và lúc đó nó là một mục trong hoá đơn. Cứ để lg.debug trong mã nhưng viết bằng %s chứ đừng f-string — đây là quy tắc rẻ nhất trong bài: cùng một dòng, cùng kết quả, tiết kiệm 57%. Bọc isEnabledFor chỉ khi việc dựng thông điệp thật sự đắt (chuỗi hoá một cấu trúc, đếm phần tử, gọi repr của một đối tượng lớn); với một chuỗi vài chục ký tự thì đọc khó hơn mà tiết kiệm không đáng. Đừng chọn thư viện log theo tốc độ — khoảng cách rộng nhất trong bảng chỉ là 6,8 µs mỗi dòng, và nếu con số đó quan trọng với bạn thì vấn đề không phải thư viện mà là bạn đang ghi quá nhiều dòng; ngược lại, nếu đang ghi hàng trăm nghìn dòng mỗi giây thì hãy nhìn lại chính lượng log đó, và nhớ con số của phần trước: 59 byte mỗi dòng, tức 51 GB mỗi ngày ở mức 10 000 dòng mỗi giây.

Mẫu số chung

Cái phát hiện đắt nhất ở đây — f-string bắt bạn dựng sẵn một chuỗi rồi vứt đi — không riêng gì Python: nó là một sai lầm về thời điểm tính toán, trả tiền dựng thứ mà người nhận có thể chẳng cần.

Trong thế giới Java, đây đúng là lý do SLF4J có cú pháp log.debug("req={} status={}", id, code) với dấu {} thay vì log.debug("req=" + id + " status=" + code): dạng nối chuỗi luôn dựng chuỗi trước khi gọi, kể cả khi DEBUG tắt, còn dạng {} truyền nguyên liệu vào và chỉ ghép khi thật sự ghi — chính là "đừng dùng f-string" của Java. Với thông điệp đắt thì bọc if (log.isDebugEnabled()), đúng vai isEnabledFor.

Trong Go, slog phân biệt slog.Info("msg", "key", val) (truyền cặp key-value, hoãn định dạng) với việc tự fmt.Sprintf rồi truyền vào — cái sau dựng chuỗi ngay. Và với trường thật sự đắt, slog có LogAttrs cùng ý tưởng "chỉ tính khi handler quyết định ghi" — cùng nguyên tắc hoãn tính.

Còn ở cơ sở dữ liệu, cùng khuôn hiện ra ở prepared statement: bạn truyền tham số (WHERE id = ?) chứ không ghép sẵn cả câu SQL thành chuỗi, để engine cache kế hoạch và không phải parse-lại mỗi lần; ghép chuỗi eager vừa tốn công dựng vừa mất cache (và mở đường injection). Ở tầng ứng dụng thì đây là lazy loading — đừng SELECT và dựng cả đồ thị đối tượng khi có thể chẳng ai đọc tới nhánh đó.

Mẫu số chung: chi phí ẩn lớn nhất thường là dựng sẵn háo hức một thứ mà người nhận có quyền vứt đi — nên hãy truyền nguyên liệu (tham số, placeholder, khoá-giá-trị) và để nơi quyết định cuối cùng tự dựng khi nó chắc chắn cần. Vì thế câu hỏi đúng khi một lời gọi "trông rẻ" lặp lại triệu lần không phải "nó làm gì" mà là "nó có dựng sẵn gì trước khi biết kết quả có được dùng không" — và nếu có, bạn đang trả tiền cho những thứ không bao giờ tồn tại.

Muốn tự thấy khoản tiền trả cho dòng-log-không-tồn-tại, chạy trong ba mươi giây:

docker run --rm python:3.12-slim python - <<'EOF'
import logging, time, statistics
lg = logging.getLogger("x"); lg.setLevel(logging.WARNING)   # DEBUG bi loc bo
N = 200_000
def do(fn):
    lots = []
    for _ in range(5):
        t0 = time.perf_counter_ns()
        fn(N)
        lots.append((time.perf_counter_ns() - t0) / N)
    return statistics.median(lots)

a = do(lambda n: [lg.debug("req=%d status=200", i) for i in range(n)])
b = do(lambda n: [lg.debug(f"req={i} status=200")  for i in range(n)])
print("lg.debug(\"...%%d\", i)  %6.1f ns" % a)
print("lg.debug(f\"...{i}\")    %6.1f ns   (+%.0f%%)" % (b, (b/a-1)*100))
EOF

Hai dòng ghi ra cùng một thứ, và cả hai đều bị lọc bỏ nên không dòng log nào được sinh ra. Khoảng cách giữa chúng là số tiền bạn trả cho những dòng log không tồn tại.