Ba phần trước đo cái giá của việc sinh log và lưu log. Phần này đo cái ít ai đo: chuyện gì xảy ra trong lúc xoay vòng. Tôi cho một tiến trình ghi liên tục 300.000 dòng đánh số, chạy logrotate thật ở giữa, rồi đếm xem còn lại bao nhiêu. Con số không bằng nhau, và không có dòng lỗi nào nói cho tôi biết điều đó.
Bảng số liệu
Container debian:12-slim, logrotate thật, một tiến trình Python giữ file mở ở chế độ nối thêm và ghi liên tục. Mỗi dòng dài 130 byte và mang số thứ tự riêng, nên sau khi xong tôi gom mọi tệp app.log* lại và đếm số thứ tự duy nhất.
Cách 1 — copytruncate (chép nội dung sang tệp mới rồi cắt cụt tệp gốc):
| Đã ghi | 300 000 dòng |
| Số lần xoay vòng | 2 |
| Còn lại sau khi gom mọi tệp | 295 683 dòng |
| Mất | 4 317 dòng — 1,44% |
Trung bình khoảng 2 159 dòng mỗi lần xoay.
Cách 2 — đổi tên tệp, tiến trình không được báo mở lại:
| Tệp | Số dòng |
|---|---|
app.log (tệp mới) |
0 |
app.log.rotated (tệp cũ) |
200 000 |
Nén:
| Dữ liệu | Gốc | Sau gzip -6 |
Tỷ lệ | Tốc độ |
|---|---|---|---|---|
Log nhân tạo (120 ký tự x lặp) |
24,80 MB | 0,54 MB | 46,02× | 210 MB/s |
| Log JSON thật | 30,75 MB | 4,06 MB | 7,57× | 103 MB/s |
Điều đáng nhớ
Nói lại theo cách khác, vì cả hai cách xoay vòng đều hỏng và hỏng khác kiểu:
copytruncate mất dữ liệu thật. 4.317 dòng biến mất vĩnh viễn, chỉ với hai lần xoay. Chúng không nằm trong tệp cũ, không nằm trong tệp mới, không nằm ở đâu cả. Và không có lỗi nào: logrotate báo thành công, tiến trình ghi vẫn chạy bình thường, log vẫn có vẻ liên tục.
Đổi tên thì không mất dòng nào, nhưng mọi dòng đi sai chỗ. Tệp app.log mới — cái mà công cụ thu gom log đang theo dõi — có đúng 0 dòng, trong khi cả 200.000 dòng vẫn chảy vào tệp đã bị đổi tên. Từ góc nhìn của hệ thống giám sát, dịch vụ vừa im lặng hoàn toàn.
Cả hai kiểu hỏng đều im lặng tuyệt đối. Đây mới là điều đáng sợ. Tôi chỉ phát hiện được vì đã đánh số từng dòng từ trước rồi đếm lại — không có mốc đối chiếu đó thì cả hai thí nghiệm đều trông như thành công.
Và tỷ lệ nén của người khác vô dụng với bạn. Cùng một lệnh gzip -6, cùng một máy, cùng một lần chạy: 46,02 lần trên dữ liệu nhân tạo và 7,57 lần trên log JSON thật. Lệch 6,1 lần, chỉ vì nội dung khác nhau.
Vì sao
copytruncate làm hai việc không phải là một: đọc toàn bộ tệp sang chỗ khác, rồi cắt tệp gốc về 0. Giữa hai việc đó có một khoảng thời gian, và mọi dòng được ghi trong khoảng đó sẽ bị cắt mất — nó đã không kịp vào bản sao, và nó bị xoá khỏi bản gốc. Cửa sổ càng rộng khi tệp càng lớn (chép lâu hơn) và tiến trình ghi càng nhanh. Ở đây tệp vài chục megabyte và tiến trình ghi hết tốc lực, nên cửa sổ ăn mất khoảng 2.159 dòng mỗi lần.
Lý do người ta vẫn dùng copytruncate là nó tránh được vấn đề thứ hai. Trong Linux, một tiến trình đang mở tệp thì giữ inode, không giữ tên. Đổi tên app.log thành app.log.1 không đụng gì tới tiến trình đó: nó vẫn ghi vào đúng inode cũ, giờ mang tên mới. Tệp app.log mới tạo là một inode khác, và sẽ trống rỗng cho tới khi tiến trình được bảo mở lại tệp — thường bằng SIGHUP, hoặc bằng chỉ thị postrotate trong cấu hình logrotate.
Nên đây không phải hai lựa chọn tốt và xấu, mà là hai lựa chọn hỏng theo hai cách:
| Cách | Hỏng gì | Chữa bằng |
|---|---|---|
copytruncate |
mất dòng trong cửa sổ chép–cắt | không chữa được, chỉ giảm bằng cách xoay ít hơn |
| đổi tên | tiến trình ghi vào tệp cũ | postrotate gửi tín hiệu cho tiến trình mở lại |
Cách đúng là cách thứ hai kèm bước báo mở lại. copytruncate chỉ nên dùng khi bạn không có cách nào bảo tiến trình mở lại tệp.
Còn chuyện nén: gzip tìm chuỗi lặp trong một cửa sổ trượt. Dữ liệu nhân tạo của tôi là 120 ký tự x giống hệt nhau ở mọi dòng — gần như toàn bộ tệp là một chuỗi lặp, nên tỷ lệ 46 lần. Log JSON thật vẫn rất lặp ở phần khung ({"level":"INFO","service":), nhưng có trace_id ngẫu nhiên 16 chữ số hex và user_id rải rác — những phần đó gần như không nén được, và chúng kéo tỷ lệ chung xuống 7,57.
Nghĩa là gì trong thực tế
- Kiểm tra ngay hôm nay xem cấu hình của bạn có
copytruncatekhông. Một dònggrep -r copytruncate /etc/logrotate.d/là đủ. Nếu có, bạn đang mất log mỗi lần xoay vòng, và tỷ lệ mất tăng theo tốc độ ghi. - Nếu buộc phải dùng
copytruncate, hãy xoay theo kích thước lớn và ít lần hơn. Mất mát tính theo số lần xoay, không theo lượng dữ liệu. Xoay mỗi giờ tốn gấp 24 lần xoay mỗi ngày. - Nếu đổi tên, đừng quên
postrotate. Thiếu nó thì bạn không mất log — bạn mất toàn bộ luồng log kể từ lần xoay đầu tiên, và điều đó tệ hơn nhiều. - Ước lượng dung lượng bằng tỷ lệ nén đo trên chính log của bạn. Với 10.000 dòng mỗi giây ở 161 byte, một ngày là 139 GB thô. Nén 7,57 lần còn 18,4 GB; nếu bạn lỡ tin con số 46 lần thì ngân sách sẽ là 3,0 GB — sai gấp sáu.
- Nén tốn 0,30 giây cho 30,75 MB (103 MB/s). Ở quy mô một ngày, đó là khoảng 22 phút CPU — không đáng kể, nhưng đủ để đừng chạy nó vào giờ cao điểm.
Chỗ tôi không kết luận được
Con số 1,44% không phải hằng số. Nó là kết quả của tốc độ ghi của tôi, kích thước tệp lúc xoay, và tốc độ đĩa. Một dịch vụ ghi thưa hơn sẽ mất ít hơn; một dịch vụ ghi dày hơn với tệp lớn hơn sẽ mất nhiều hơn. Cái tôi tin là có mất, và mất theo mỗi lần xoay — không phải con số phần trăm cụ thể.
Tiến trình ghi của tôi flush theo từng dòng. Một ứng dụng dùng đệm lớn sẽ có hành vi khác, và có thể mất nhiều hơn vì cả một đệm bị cắt cùng lúc. Tôi không đo trường hợp đó.
Tôi không đo logrotate với delaycompress, dateext, hay xoay theo thời gian. Chúng không đổi bản chất của hai kiểu hỏng ở trên, nhưng chúng đổi tần suất xoay, và tần suất mới là thứ quyết định tổng mất mát.
Một chỗ đo hỏng, và nó hỏng ồn ào. Lần đo nén thứ hai của tôi chạy trong một container mới không cài python3, nên nhánh sinh dữ liệu nhân tạo chết với python3: command not found và bảng in ra nen nan lan — không phải một con số sai, mà là chữ nan chình ình. Tôi vẫn còn số 46,02 từ lần chạy trước, nhưng lấy hai con số từ hai lần chạy khác nhau để so sánh là thói quen xấu, nên tôi cài python3 rồi đo lại cả hai trong cùng một lần. Kết quả trùng khớp: vẫn 46,02 và 7,57.
Đáng nói là lỗi này vô hại đúng vì nó ồn ào. Hai kiểu mất log ở trên mới là loại nguy hiểm: chúng trả về thành công.
Thử ba mươi giây
docker run --rm debian:12-slim bash -c '
apt-get -qq update >/dev/null && apt-get -qq install -y logrotate python3 >/dev/null
cat > /etc/logrotate.d/app <<CFG
/var/log/app.log { size 1k rotate 50 copytruncate missingok notifempty }
CFG
: > /var/log/app.log
python3 -c "
f=open(\"/var/log/app.log\",\"a\",buffering=1)
for i in range(1,200001): f.write(\"%08d\n\"%i)
" &
W=$!
while kill -0 $W 2>/dev/null; do logrotate -f /etc/logrotate.conf >/dev/null 2>&1; sleep 0.15; done
wait $W
CO=$(cat /var/log/app.log* | sort -u | wc -l)
echo "da ghi 200000 dong, con lai $CO -> mat $((200000-CO))"
'
logrotate sẽ báo thành công ở mọi lần chạy. Con số ở dòng cuối là thứ duy nhất nói cho bạn biết chuyện gì thật sự đã xảy ra.
