Question on spdlog rotation size

[dentiny]

Hi team, I have a question on max size for rotating file sink: https://github.com/gabime/spdlog/blob/1245bf8e8a19d914271df03124da9593f3634a9c/include/spdlog/sinks/rotating_file_sink.h#L24-L28

My understand for the parameter is:

• Every time you log certain amount of data, if the overall size for the current log file is larger than configured max size for rotating file sink, the current file is sealed (until reused and overwritten due to limited file size), and a new file will be created.

But after reading through the code, I found the implementation is:

• Every time accumulated logging size is larger than configured, we "flush" the data from spdlog library into buffered IO library (still in application buffer, but application doesn't have any control over it)
• All other things happen in the background, in detail, it's unsure (1) when does buffered IO library flushes data into page cache, and more importantly, (2) when does filesystem flushes page cache into disk
• The thing is, rotation only happens when persisted file size is larger than 0, which happens after (2). https://github.com/gabime/spdlog/blob/1245bf8e8a19d914271df03124da9593f3634a9c/include/spdlog/sinks/rotating_file_sink-inl.h#L83-L86

I guess the reason is: if we sync every time when accumulated data size is larger than configured max size Example code:

if (accumulated_size >= max_size_) {
  fflush(data)
  sync()
}

we would have unintended and unexpected latency on critical path, since logging is expected to be cheap and low latency. So the design choice here is let library decide when to flush data to page cache, and let filesystem to decide when to persist to disk.

• The former has relatively lower latency (10s of nanosec), just a syscall from application buffer to kernel buffer
• The later is expensive (generally single digit microsec)

If I don't mis-understand, spdlog doesn't provide any guarantee for rotating size; and in theory each log file could be infinitely large. I feel like the best way to implement is to leverage background thread or async IO.

[gabime]

filehelper.size() > 0

This was added to deal with full disk cases #2261.

In theory I think your are you are right, although I didnt see any issue reports on this. Maybe there are other ways to fix #2261..

[dentiny]

In theory I think your are you are right, although I didnt see any issue reports on this.

Hi @gabime thanks for the reply!

I'm happy to provide more context. I have some issues when using ray, production issue see: https://github.com/ray-project/ray/issues/45678 The TLDR here is: people see log become too big in production, due the above issue I mentioned, that spdlog doesn't have a full control for overall log files size, people using spdlog as their logging library doesn't have a hard cap on disk usage upper limit.

As for the issue you've mention: https://github.com/gabime/spdlog/issues/2261 My proposed solution is:

• Suppose I set the rotation size to be 10 bytes, and max file number to be 10, so theoretically the overall max file size for log is 100 bytes
• Let's assume the file system contains exactly 100 bytes free space, which would fail to write 11-th file due to out-of-disk

My proposed solution would be:

• Behave just like the old implementation (before your fix PR): when the overall size reaches the configured max file size, we perform a write;
• To avoid overwrite situation (which is caused by out-of-disk), we attempt to open a new file and write new content;
• If file creation fails, we directly returns, leaving an error message on the stderr; AND we delete the oldest file for rotation.

Actually this is what glog does: https://github.com/google/glog/blob/6c5c692c8e423f651c74de9477ff0b5a59008bcc/src/logging.cc#L1090-L1148

Pseudocode looks like the following:

// Invoked right before function returns.
absl::Cleanup cleanup = delete_oldest_log_if_necessary

if cur_size >= max_size:
  file_handle = NULL
if file_handle == NULL:
  if (!create_new_file()):
    return

// Write content to log as normal

The caveat is:

• We would have file creation, which is a synchronous blocking IO operation on the critical section, every time we plan to create a new file due to size limitation;
• We would loss one message, every time we suffer out-of-disk issue, but I assume that's super rare.

[gabime]

people see log become too big in production

Can you point me to those issues? Seems that https://github.com/ray-project/ray/issues/45678 was about not using the rotating log at all.

[dentiny]

Can you point me to those issues? Seems that ray-project/ray#45678 was about not using the rotating log at all.

The TLDR is:

• Ray by default sets max rotation size and max file count, so we should have a hard cap on max size
  • https://docs.ray.io/en/latest/ray-observability/user-guides/configure-logging.html#log-rotation
• But users find these hard caps are not respected, in detail, the generated file size is larger than (max size * max file count), so I'm checking into spdlog internal implementation, and found buffering content in the memory could lead to this issue.

[gabime]

But users find these hard caps are not respected, in detail, the generated file size is larger than (max size * max file count).

It could be something else, I see there a discussion about env params and some log_monitor.py and branches to be merged..

Please provide a simple way to reproduce before we search for solutions.

[dentiny]

Hi @gabime , sorry for the confusion, I think for the issue raised in ray, there're two things:

• Log rotation doesn't work as expected
• Log file being excessively large

The issue I want to discuss in this thread is the first item.

Assume you set the max size = 10, and file number = 1. What's the expected behavior if you log "helloworld" for twice?

My expectation is there's only one file exists on the disk, with content "helloworld" with size 10. But due to the implementation I detailed at the issue description, there's no guarantee what it would be.

[gabime]

Please provide code to reproduce. Otherwise those are just guesses.

[dentiny]

Hi @gabime , I think there's a bug in ray, not any issue related to spdlog. Thank you very much for the help!