Phần trước đo được rằng 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ể. Bài này đo cái mà người ta thật sự dùng: bốn thư viện log của Python, cộng print làm mốc so sánh, và bốn mức để xem một lời gọi bị lọc bỏ có thật sự miễn phí hay không.

Chi phí ghi một dòng log

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.

Cách ghi µs mỗi dòng So với print
print() ra tệp 0,18 1×
structlog (JSON) 3,96 22×
logging chuẩn 4,51 25×
logging + JSON 4,56 25×
loguru 6,98 39×

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:

Cấu hình µs mỗi dòng Chênh
print() đối chiếu 0,21 —
logging, formatter chỉ có %(message)s 3,64 +3,43
thêm %(levelname)s 3,72 +0,08
thêm %(asctime)s 4,48 +0,76

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

Lời gọi ns
lg.debug(...) 57,9 bị lọc bỏ
lg.info(...) 58,0 bị lọc bỏ
lg.warning(...) 4 758,6 được ghi
lg.error(...) 4 760,6 được ghi

Điều đáng nhớ

Nói lại theo cách khác, vì cả ba kết quả đều ngược với 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ỏ:

Cách viết ns
lg.debug("req=%d", i) 59,2
lg.debug(f"req={i}") 92,9 (+57%)
if lg.isEnabledFor(...) rồi mới dựng 32,5

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 Python với khoảng hai chục thuộc tính, trong đó có cả việc dò ngược ngăn xếp để lấy tên tệp và số dòng. Sau đó bản ghi đi lên cây logger, qua bộ lọc, rồi 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 đủ. Đó là những thứ có ích — nhưng chú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 tra mức ngay dòng đầu và trả về trước khi chạm tới bất cứ thứ gì đắt. Toàn bộ 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.

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

  • 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, hoàn toà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 nó bằng %s chứ không bằng f-string. Đây là quy tắc rẻ nhất trong bài: cùng một dòng, cùng một 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 là 6,8 µs mỗi dòng. Nếu con số đó quan trọng với bạn thì vấn đề không phải là 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.

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

Đây là Python, và ngôn ngữ chi phối kết quả. Phần trước đo fprintf trong C tốn khoảng 169 ns cho một dòng tương đương — rẻ hơn logging của Python 27 lần. Bảng trong bài này nói về cái giá của một thư viện log trong một ngôn ngữ động, không phải về cái giá của việc ghi log nói chung.

Tôi so năm cách ghi chứ không so năm bộ tính năng. loguru chậm nhất trong bảng, nhưng nó cũng là thứ duy nhất cho bạn dấu vết ngoại lệ đầy đủ và xoay tệp mà không phải cấu hình gì. So chúng bằng một con số duy nhất là bỏ qua lý do người ta chọn chúng.

Không có mạng, không có nhiều luồng, không có fsync. Ghi ra tệp đã đệm là trường hợp dễ nhất. Log đẩy qua mạng tới bộ thu gom sẽ có thêm một bậc chi phí hoàn toàn khác, và tranh chấp khoá giữa nhiều luồng sẽ làm khoảng cách giữa các thư viện đổi hẳn — đó là phép đo của một phần khác.

Một khiếm khuyết trong chính phép đo của tôi, và cách nó lộ ra. Ở lô đầu tiên, tôi gọi print trong một vòng for thuần nhưng gọi các thư viện trong một list comprehension. List comprehension tích luỹ 200 000 phần tử None, nên nó cộng thêm một khoản chi phí mà nhánh print không phải trả. Bất đối xứng đó làm tỷ lệ bị thổi lên.

Cách phát hiện: phép đo bóc tách ở bảng thứ hai dùng vòng for thuần cho cả hai phía, và nó cho logging 4,48 µs so với print 0,21 µs — tỷ lệ 21,3 lần, so với 25,1 lần ở bảng đầu. Vậy bất đối xứng có thật và nó thổi tỷ lệ lên khoảng 18%, nhưng kết luận thì không đổi: khoảng cách vẫn là hơn hai mươi lần. Tôi để cả hai con số lại thay vì lặng lẽ giữ con số đẹp hơn.

Thử 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.