Định dạng một dòng log gần như miễn phí — fsync mỗi dòng đắt gấp 11.464 lần, và một dòng DEBUG đã tắt vẫn ngốn 62 lần chi phí

Khi một dòng log tốn tiền, trực giác ai cũng nhìn vào phần soạn chữ — nối chuỗi, định dạng, thay thư viện "zero-allocation". Nhưng đó là nhìn nhầm chỗ tiền chảy. Giống như gửi thư: viết lá thư mất vài giây, nhưng cái tốn thời gian là mỗi lần chạy ra bưu điện — và người khôn gom cả chồng thư đi một chuyến thay vì chạy ra chạy vào từng lá. Ghi log nằm trên đường đi của mọi yêu cầu, nên bài này đo mỗi dòng tốn bao nhiêu và tiền đi đâu — hoá ra gần hết nằm ở "chạy ra bưu điện", tức mỗi lần dữ liệu rời khỏi tiến trình.

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

Sáu cách ghi cùng một dòng

Hai điều rút ra ngay. Định dạng chuỗi gần như miễn phí — 0,052 µs cho một dòng có bốn trường, nên việc tối ưu định dạng log (thay printf bằng nối chuỗi thủ công, dùng thư viện "zero-allocation") nhắm vào 0,05 µs trong khi phần còn lại tốn gấp sáu tới mười nghìn lần. Cái đắt là mỗi lần ra khỏi tiến trình: bộ đệm gom nhiều dòng thành một lời gọi hệ thống, bỏ bộ đệm là trả 0,25 µs cho mỗi dòng.

stderr không có bộ đệm

Dòng thứ năm đáng chú ý vì nó là mặc định của rất nhiều thứ. Theo chuẩn C, stdout được đệm theo dòng khi ra terminal và đệm khối khi ra tệp, còn stderr không bao giờ được đệm — mỗi lần gọi là một lời gọi hệ thống. Điều đó đúng cho việc báo lỗi: khi chương trình sắp chết, bạn muốn dòng cuối cùng đã ra ngoài. Nhưng nhiều framework ghi toàn bộ log ra stderr, và khi đó mọi dòng INFO đều trả giá của một quyết định thiết kế dành cho lỗi nghiêm trọng. Trong container càng đáng chú ý: quy ước 12-factor bảo ghi log ra stdout/stderr và để nền tảng thu thập — đó là quy ước vận hành tốt, và nó có cái giá đo được ở dòng thứ năm.

fsync mỗi dòng

515,903 µs mỗi dòng. Với dịch vụ xử lý 1.000 yêu cầu mỗi giây và ghi một dòng mỗi yêu cầu, đó là hơn nửa giây CPU mỗi giây chỉ để chờ đĩa. Con số này khớp với phần 14: fsync trên ext4 đầy đủ rào chắn tốn khoảng 1.454 µs, và ở đây là 516 µs vì ghi tuần tự vào cùng một tệp nên một phần được gom. Có cấu hình log nào thật sự làm việc này không? Có — syslog với - bị bỏ trong rsyslog.conf, và một số thư viện có chế độ "durable" bật sẵn; nếu bạn không cần đảm bảo rằng dòng log cuối cùng sống sót qua mất điện, đừng bật nó.

Log DEBUG đã tắt vẫn tốn tiền

Đây là phần quan trọng nhất, vì nó là lỗi phổ biến nhất và không hiện ra trong bất kỳ hồ sơ nào một cách rõ ràng.

Dòng thứ hai chậm hơn dòng đầu 62 lần, và log vẫn đang tắt. Lý do đơn giản và ai cũng biết khi được nhắc: đối số được tính trước khi hàm được gọi — hàm ghi() kiểm tra mức và bỏ qua, nhưng chuỗi đã được định dạng xong rồi. Trong mã nguồn thật nó trông thế này:

log.debug("user=" + user.toJson() + " cart=" + cart.summary());

logger.debug(f"trạng thái: {tinh_toan_dat_tien()}")

log.Printf("chi tiết: %s", strings.Join(danhSachDai, ","))

Cả ba đều tính hết đối số kể cả khi mức log là WARN. So sánh dòng hai với dòng bốn: 43,7 ns cho một log bị tắt, 58,4 ns cho một log được ghi thật — ba phần tư chi phí của một dòng log nằm ở việc dựng chuỗi, phần vẫn xảy ra khi bạn tắt log. Ba cách chữa, tuỳ ngôn ngữ:

if (log.isDebugEnabled()) log.debug("user=" + user.toJson());
log.debug("user={}", user);                    // dinh dang lazy

log.Debug().Str("user", u).Msg("")             // zerolog: khong dung chuoi

logger.debug("trạng thái: %s", tinh_toan)      # % lazy, khong dung f-string

Điểm chung: đừng dựng chuỗi ở chỗ gọi — truyền tham số rời và để thư viện quyết định có ghép chúng lại hay không.

Ba lời khuyên có số liệu đằng sau

Giữ bộ đệm, nhưng xả định kỳ — bộ đệm nhanh gấp 6,6 lần, đổi lại là mất vài dòng cuối nếu tiến trình bị giết; xả mỗi giây hoặc mỗi 4 KB là điểm cân bằng của hầu hết thư viện. Ghi log ở một luồng riêng — nếu buộc phải xả hoặc fsync, đưa việc đó ra khỏi đường đi của yêu cầu; một hàng đợi không chặn cộng một luồng ghi biến 516 µs của yêu cầu thành 0,05 µs, cái giá là hàng đợi đầy khi ghi chậm hơn sinh log và lúc đó phải chọn có ý thức: chặn (mất tốc độ) hay bỏ dòng (mất log). Và đếm số dòng log mỗi yêu cầu — con số này rất hay bị bỏ qua: một dịch vụ ghi 30 dòng cho mỗi yêu cầu ở mức INFO đang tốn 30 × 0,3 = 9 µs mỗi yêu cầu chỉ cho việc ghi, cộng dung lượng, cộng chi phí thu thập và lưu trữ ở phía sau.

Mẫu số chung

Bảng đầu bài phơi ra một khuôn phổ quát: chi phí không nằm ở việc chuẩn bị dữ liệu mà ở mỗi lần đẩy nó qua một ranh giới bền vững (bộ đệm → nhân → đĩa), nên đòn bẩy là gom nhiều lần đẩy thành một, và "bền vững ngay lập tức" (fsync/flush mỗi lần) là cái đắt nhất phải trả có ý thức.

Trong thế giới Java, đây đúng là lý do log appender nghiêm túc dùng AsyncAppender (đẩy việc ghi sang luồng riêng, gom lô) thay vì ghi đồng bộ mỗi dòng, và là lý do BufferedWriter tồn tại; cùng khuôn ở tầng DB là addBatch()/executeBatch() của JDBC — gom nghìn câu chèn thành một chuyến thay vì round-trip mỗi câu, y như gom dòng log thành một write.

Trong Go, bufio.Writer là bản dịch trực tiếp của "giữ bộ đệm", và lời khuyên chuẩn là đừng Flush/Sync mỗi dòng mà gom rồi xả định kỳ; zerolog/zap nhanh chính nhờ vừa hoãn dựng chuỗi (dòng DEBUG tắt gần như miễn phí) vừa ghi theo lô.

Còn ở cơ sở dữ liệu, đây đúng là group commit: fsync cái WAL mỗi giao dịch là điểm nghẽn kinh điển (đúng dòng 515,903 µs), nên Postgres/MySQL gom nhiều commit vào một lần fsync (commit_delay, innodb_flush_log_at_trx_commit) — đánh đổi độ trễ một chút lấy thông lượng gấp bội, cùng bài học "đừng bền-vững từng-cái-một".

Mẫu số chung: soạn một mẩu dữ liệu thì rẻ; đẩy nó qua ranh giới (ra khỏi tiến trình, xuống đĩa, sang mạng) mới đắt, và bền-vững-tức-thì cho mỗi mẩu là đắt nhất — nên tối ưu đúng là gom nhiều lần đẩy thành một chuyến (buffer, batch, group commit), không phải mài giũa phần soạn. Vì thế câu hỏi đúng khi ghi/gửi nhiều thứ nhỏ không phải "mỗi cái soạn có nhanh không" mà là "tôi đang băng qua ranh giới bao nhiêu lần, và có gom lại được không — mỗi lần đòi bền-vững ngay có thật sự cần không".

Muốn tự đo dịch vụ của mình ghi bao nhiêu và tốn bao nhiêu cho việc đó, trong ba mươi giây:

p=<pid>
b1=$(awk '/^write_bytes/{print $2}' /proc/$p/io)
sleep 10
b2=$(awk '/^write_bytes/{print $2}' /proc/$p/io)
echo "ghi $(( (b2-b1)/10 )) byte moi giay"

# neu log ra tep
f=/var/log/dich-vu.log
l1=$(wc -l < $f); sleep 10; l2=$(wc -l < $f)
echo "$(( (l2-l1)/10 )) dong log moi giay"

# chi phi uoc tinh, lay 0,3 us moi dong tu bang tren
awk -v n=$(( (l2-l1)/10 )) 'BEGIN{printf "khoang %.1f%% mot nhan CPU chi de ghi log\n", n*0.3/10000}'

Nếu con số cuối vượt vài phần trăm, hãy xem lại mức log trước khi tối ưu bất cứ thứ gì khác — đó thường là cải thiện dễ nhất trong toàn bộ hệ thống.

Phần sau: đồng hồ và nguồn thời gian — đo chi phí một lần lấy giờ.