Skip to content

Add size based log rotation to butil/logging - #41

Closed
cw20050111-prog wants to merge 1 commit into
LinQuickDev:masterfrom
cw20050111-prog:2696
Closed

Add size based log rotation to butil/logging#41
cw20050111-prog wants to merge 1 commit into
LinQuickDev:masterfrom
cw20050111-prog:2696

Conversation

@cw20050111-prog

Copy link
Copy Markdown

Addresses the log rotation part of apache#2696.

What

butil/logging has no rotation today, which is one of the reasons users fall back to glog. This adds size based rotation, disabled by default.

flag default meaning
--log_rotate_size_mb 0 Rotate once the current log file is about to grow beyond this size in megabytes. 0 means never rotate.
--log_rotate_max_backups 10 Max number of rotated files kept besides the current one.

Both are registered with BUTIL_VALIDATE_GFLAG, so they are modifiable at run time through /flags. The names deliberately avoid glog's --max_log_size so that there is no collision under BRPC_WITH_GLOG.

When the limit would be exceeded, <log_file> is renamed to <log_file>.1, the existing backups are shifted down (.1 -> .2 -> ...) and the ones beyond --log_rotate_max_backups are removed, so .1 is always the most recent backup.

Where the check lives

In Log2File(). It is the single funnel for both the synchronous path (DefaultLogSink) and the asynchronous one (AsyncLogger::DoLog), so one check covers both, and it sits in the file writing layer rather than in a sink, which keeps it orthogonal to a possible future LogStream/LogStreamFactory refactor.

Details worth calling out:

  • The file is opened with "a", so its initial size is read with fstat() (GetFileSizeEx() on Windows) rather than being counted from zero after a restart.
  • The check happens before the write, so a single log is never split across two files.
  • A log larger than the limit is written as a whole. An empty file is never rotated, otherwise every oversized log would produce an empty backup.
  • Rotation is off by default, so upgrading changes neither the file names nor the existing files.

When the rename fails

The size that triggered a failed rotation does not change by itself, so retrying on the next log would close, reopen and rename the file for every single log. Instead the size at which rotation failed is remembered and rotation is retried only once the file has grown by another --log_rotate_size_mb. The error is printed once rather than per log, and logs keep being appended to the current file in the meantime.

If the file turns out to be smaller than it was when rotation failed, it has been replaced or truncated from the outside and rotation resumes immediately. This is what happens when an external tool renames the log file away: the next write recreates it, and rotation recovers on its own instead of staying disabled for the lifetime of the process.

Running an external rotator such as logrotate on the same file is documented as unsupported, since the two sets of rules interfere and the number of files kept is no longer bounded by --log_rotate_max_backups.

Multiple processes

Sharing one log file between several processes is documented as unsupported together with rotation, as agreed in apache#2696: on POSIX LoggingLock only serializes the threads of a single process, and after the rename the other processes would keep writing to the renamed inode. Adding flock was considered and deliberately left out.

Tests

LogRotationTest in test/logging_unittest.cc, 8 cases: disabled by default, rotation and pruning of old backups, --log_rotate_max_backups=1, a log larger than the limit, the size of an existing file being picked up after a restart, the asynchronous path, backing off when the rename keeps failing, and recovering after the log file is replaced from the outside. The assertions do not depend on how much the rest of the process logs into the same file. The whole test_butil suite passes on x86_64 in CI and on aarch64 (openEuler 24.03, gcc 12.3).

Besides the unit tests, the change was exercised on a 308 core aarch64 machine (openEuler 24.03, gcc 12.3) with a multi threaded load generator whose every log carries a thread id and a sequence number:

scenario result
16 threads x 20k logs, 8 rotations, sync and async 320000/320000 distinct records kept, no split or interleaved line, largest backup 6 bytes below the limit
1.7GB written with a 2MB limit and 3 backups, ~800 rotations disk usage stayed at 8.2MB throughout
~1500 rotations over 11 minutes, sampled every 30s RSS and the number of open file descriptors both flat, file count and disk usage constant
--log_rotate_size_mb flipped through /flags while running takes effect immediately in both directions
--log_rotate_max_backups lowered from 10 to 2 through /flags the 8 files beyond the new limit are reclaimed by the next rotation
process killed at 7.9MB and restarted rotated after 2.5MB more, i.e. the existing size was picked up
rotation off vs 8 and 86 rotations per run, 5 runs each 1.186s vs 1.206s and 1.144s, the difference is below the run to run noise
every backup slot blocked so the rename always fails one error line, 320000/320000 kept, no measurable slowdown
log file renamed away by an external tool mid run one error line, then rotation recovered on its own
two processes writing to one log file 23.5% of the records silently lost, which is why the docs say this is unsupported
6MB filesystem, budget larger than the filesystem pruning old backups reclaims space and logging continues; with rotation off the file sticks at the filesystem limit and every later log is lost

The Windows half of the change has no CI anywhere in the project, so it was cross compiled with mingw-w64 (-DUNICODE -Wall, clean) as a compile time check. It has not been run on Windows.

Left out on purpose

Time based rotation, compression of old files and a "current" symlink, so that this first change stays reviewable.

Add --log_rotate_size_mb (0, disabled by default) and
--log_rotate_max_backups (10). When the current log file is about to
grow beyond the limit it is renamed to "<log_file>.1", the older
backups are shifted down and the ones beyond the limit are removed, so
".1" is always the most recent backup.

The check lives in Log2File(), the single funnel of both DefaultLogSink
and AsyncLogger::DoLog, so rotation covers synchronous and asynchronous
logging alike and stays orthogonal to any later LogStream refactor. The
file is opened in append mode, so its initial size is read with
fstat()/GetFileSizeEx() instead of being counted from zero. A log
larger than the limit is written as a whole rather than producing empty
backups.

The size that triggered a failed rotation does not change by itself, so
retrying on the next log would close, reopen and rename the file for
every single log. Instead the size at which rotation failed is
remembered and rotation is retried once the file has grown by another
--log_rotate_size_mb, with the error printed once rather than per log.
A file smaller than it was at that point has been replaced from the
outside, which lets rotation resume immediately.

Sharing one log file between several processes is not supported
together with rotation and is documented as such: on POSIX LoggingLock
only serializes the threads of a single process, and after the rename
the other processes would keep writing to the renamed inode. Running an
external rotator such as logrotate on the same file is unsupported for
the same reason.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant