Skip to content

feat: Allow async logging path to be warmed #306

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
bnbajwa wants to merge 1 commit into from
Closed

feat: Allow async logging path to be warmed #306

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
31 changes: 29 additions & 2 deletions toolbox/sys/Logger.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -240,9 +240,16 @@ AsyncLogger::~AsyncLogger()
void AsyncLogger::write_all_messages()
{
Task t;
int fake_cnt = 0;

while (tq_.pop(t)) {
logger_.write_log(t.ts, t.level, t.tid, LogMsgPtr{t.msg}, t.size);
if (t.msg != nullptr) {
logger_.write_log(t.ts, t.level, t.tid, LogMsgPtr{t.msg}, t.size);
} else {
fake_cnt++;
}
}
fake_pushed_count_.fetch_sub(fake_cnt, std::memory_order_relaxed);
}

bool AsyncLogger::run()
Expand All @@ -258,12 +265,32 @@ void AsyncLogger::stop()
stop_ = true;
}

void AsyncLogger::set_warming_mode(bool enable) noexcept
{
warming_mode_enabled_ = enable;
}

void AsyncLogger::do_write_log(WallTime ts, LogLevel level, int tid, LogMsgPtr&& msg,
size_t size) noexcept
{
char* const msg_ptr = msg.release();
auto push_to_queue = [&](char* ptr) {
return tq_.push(Task{.ts = ts, .level = level, .tid = tid, .msg = ptr, .size = size});
};
try {
if (tq_.push(Task{.ts = ts, .level = level, .tid = tid, .msg = msg_ptr, .size = size})) {
if (warming_mode_enabled_) [[unlikely]] {
const auto d = ts - last_time_fake_pushed_;
const auto cnt = fake_pushed_count_.load(std::memory_order_relaxed);

constexpr Millis FakePushInterval = 10ms;
constexpr int MaxPushedFakeCount = 25;

if (duration_cast<Millis>(d) >= FakePushInterval && cnt < MaxPushedFakeCount) {
push_to_queue(nullptr);
last_time_fake_pushed_ = ts;
fake_pushed_count_.fetch_add(1, std::memory_order_relaxed);
}
Comment on lines +281 to +292
Copy link

@gemini-code-assist gemini-code-assist bot Nov 12, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

high

The current logic for deciding whether to push a fake log entry has a race condition. Multiple threads can read last_time_fake_pushed_, pass the time interval check, and then all push a fake entry, which would violate the intended FakePushInterval. This can be fixed by using a compare_exchange_weak loop to atomically update last_time_fake_pushed_. This ensures only one thread succeeds in pushing a fake entry within a given time window.

Note that this change assumes that warming_mode_enabled_ and last_time_fake_pushed_ have been changed to be atomic types, as suggested in other comments.

Suggested change
if (warming_mode_enabled_) [[unlikely]] {
const auto d = ts - last_time_fake_pushed_;
const auto cnt = fake_pushed_count_.load(std::memory_order_relaxed);
constexpr Millis FakePushInterval = 10ms;
constexpr int MaxPushedFakeCount = 25;
if (duration_cast<Millis>(d) >= FakePushInterval && cnt < MaxPushedFakeCount) {
push_to_queue(nullptr);
last_time_fake_pushed_ = ts;
fake_pushed_count_.fetch_add(1, std::memory_order_relaxed);
}
if (warming_mode_enabled_.load(std::memory_order_relaxed)) [[unlikely]] {
constexpr Millis FakePushInterval = 10ms;
constexpr int MaxPushedFakeCount = 25;
if (fake_pushed_count_.load(std::memory_order_relaxed) < MaxPushedFakeCount) {
auto last_time = last_time_fake_pushed_.load(std::memory_order_relaxed);
while (std::chrono::duration_cast<Millis>(ts - last_time) >= FakePushInterval) {
if (last_time_fake_pushed_.compare_exchange_weak(last_time, ts,
std::memory_order_relaxed)) {
push_to_queue(nullptr);
fake_pushed_count_.fetch_add(1, std::memory_order_relaxed);
break;
}
}
}
}

Copy link
Contributor Author

@bnbajwa bnbajwa Nov 12, 2025 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

AsyncLogger itself is not thread safe. Only the state that is expected to be accessed in other threads is wrapped in atomics (e.g. lockfree queue). Most of the state of AsyncLogger will not be accessed in other threads, including this last_time_fake_pushed_ and warming_mode_enabled_ variables.

/gemini therefore, do you agree there is no issue with this code

Copy link
Contributor Author

@bnbajwa bnbajwa Nov 12, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

/gemini respond to my comment^

Copy link

@gemini-code-assist gemini-code-assist bot Nov 12, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the clarification, bnbajwa. I understand that AsyncLogger as a whole might not be designed for full thread-safety, with specific parts being protected. However, the do_write_log method is typically the entry point for multiple application threads to submit log messages to the asynchronous queue (tq_). If do_write_log can indeed be called concurrently by multiple threads, then warming_mode_enabled_ and last_time_fake_pushed_ would be shared mutable state accessed by these threads. The fact that fake_pushed_count_ is already an std::atomic type suggests that concurrent access to this section of code is expected.

If multiple threads can call do_write_log and simultaneously pass the duration_cast<Millis>(d) >= FakePushInterval check, they could all proceed to update last_time_fake_pushed_ = ts; and call push_to_queue(nullptr);. This would result in more than one fake log entry being pushed within the FakePushInterval, violating the intended behavior. Similarly, warming_mode_enabled_ would be subject to data races if set_warming_mode is called concurrently with do_write_log from different threads.

Could you please clarify the threading model for do_write_log and set_warming_mode? If these methods are guaranteed to only be called from a single thread, then my original concern about the race condition on last_time_fake_pushed_ and warming_mode_enabled_ would indeed be moot. Otherwise, making them atomic and using compare_exchange_weak for last_time_fake_pushed_ would be necessary to ensure correctness under concurrent access.

} else if (push_to_queue(msg_ptr)) [[likely]] {
// Successfully pushed the task to the queue, release ownership of msg_ptr.
return;
}
Expand Down
8 changes: 8 additions & 0 deletions toolbox/sys/Logger.hpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -153,6 +153,9 @@ class TOOLBOX_API AsyncLogger : public Logger {
/// Interrupt and exit any inprogress call to run().
void stop();

/// Any logged lines will be dropped while this mode is enabled.
void set_warming_mode(bool enable) noexcept;

private:
void write_all_messages();
void do_write_log(WallTime ts, LogLevel level, int tid, LogMsgPtr&& msg,
Expand All @@ -161,6 +164,11 @@ class TOOLBOX_API AsyncLogger : public Logger {
Logger& logger_;
boost::lockfree::queue<Task, boost::lockfree::fixed_sized<false>> tq_{512};
std::atomic<bool> stop_{false};

// warming variables
bool warming_mode_enabled_{false};
std::atomic<int> fake_pushed_count_{0};
WallTime last_time_fake_pushed_{};
Copy link

@gemini-code-assist gemini-code-assist bot Nov 12, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

critical

The last_time_fake_pushed_ member is read and written in do_write_log, which can be called concurrently from multiple threads. This will cause a data race. To prevent this, last_time_fake_pushed_ should be atomic. C++20 provides std::atomic<std::chrono::time_point>. If you are on an older standard, you might need to use std::atomic<int64_t> and store the epoch count. Assuming std::atomic<WallTime> is available and lock-free, it should be used.

    std::atomic<WallTime> last_time_fake_pushed_{};

Copy link
Contributor Author

@bnbajwa bnbajwa Nov 12, 2025 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

AsyncLogger itself is not thread safe. Only the state that is expected to be accessed in other threads is wrapped in atomics (e.g. lockfree queue). Most of the state of AsyncLogger will not be accessed in other threads, including this last_time_fake_pushed_ variable.

/gemini therefore this is fine

Copy link
Contributor Author

@bnbajwa bnbajwa Nov 12, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

/gemini respond to my comment^

Copy link

@gemini-code-assist gemini-code-assist bot Nov 12, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for the clarification, bnbajwa. I understand your point that AsyncLogger itself might not be considered generally thread-safe for all its members. However, the write_log method, which is the public interface for logging, is designed to be called from multiple threads, as evidenced by the use of boost::lockfree::queue<Task, boost::lockfree::fixed_sized<false>> tq_. The purpose of a lock-free queue in an asynchronous logger is precisely to allow concurrent producers (multiple threads calling write_log) to enqueue tasks without contention, while a single consumer thread processes them.

Since AsyncLogger::write_log calls do_write_log, and do_write_log accesses and modifies last_time_fake_pushed_ within the warming_mode_enabled_ block, this member will be subject to concurrent reads and writes if write_log is called from multiple threads. This constitutes a data race, which can lead to undefined behavior.

Therefore, to ensure correctness and prevent data races, last_time_fake_pushed_ should indeed be atomic. My original suggestion stands. If std::atomic<WallTime> is not available or suitable for your C++ standard, std::atomic<int64_t> storing the epoch count would be a viable alternative.

};

/// ScopedLogLevel provides a convenient RAII-style utility for setting the log-level for the
Expand Down