Ghi log là thứ nằm trên đường đi của mọi yêu cầu. Bài này đo xem mỗi dòng tốn bao nhiêu, và tiền đi đâu.
Sáu cách ghi cùng một dòng
| Cách ghi | µs mỗi dòng | So với nhanh nhất |
|---|---|---|
fprintf có bộ đệm |
0,045 | 1× |
| Chỉ định dạng chuỗi, không ghi đi đâu | 0,052 | 1,2× |
fprintf + fflush mỗi dòng |
0,287 | 6,4× |
write() thẳng, mỗi dòng một lời gọi |
0,295 | 6,6× |
stderr (không có bộ đệm), ra tệp |
0,316 | 7,0× |
write + fsync mỗi dòng |
515,903 | 11.464× |
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. 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.
| Cách viết | ns mỗi lần |
|---|---|
ghi(DEBUG, "chuỗi có sẵn") |
0,702 |
ghi(DEBUG, dinh_dang(i)) |
43,735 |
if (mức >= DEBUG) ghi(DEBUG, dinh_dang(i)) |
0,000 |
ghi(WARN, dinh_dang(i)) — log bật, ghi thật |
58,449 |
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. 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: chặn (mất tốc độ) hay bỏ dòng (mất log). Chọn có ý thức và ghi lại quyết định đó.
Đế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 với dung lượng, cộng với chi phí thu thập và lưu trữ ở phía sau.
Thử ba mươi giây
Đếm số dòng log mà dịch vụ của bạn sinh ra 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ờ.
