Skip to content

Commit f3fa1d4

Browse files
authored
perf(logger): allocation-free formatting and prompt async writer wakeup (#117)
1 parent dd0848d commit f3fa1d4

10 files changed

Lines changed: 359 additions & 71 deletions

File tree

AGENTS.md

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -357,7 +357,7 @@ PATH="/c/msys64/mingw64/bin:$PATH" ./build/mingw-debug/tests/DetourModKit_tests.
357357
| Scanner | Stateless -- inherently safe | N/A (startup only) |
358358
| HookManager | SRWLOCK-backed reader/writer locks; two-phase shutdown (disable under shared lock, clear under exclusive lock), both phases walking `m_hook_creation_order` in reverse so inline/mid hooks layered on one address unwind newest-first instead of in bucket order; `m_mutator_gate` blocks new mutators (including all VMT operations) during teardown; CAS on `m_shutdown_called` serializes shutdown/remove_all_hooks; double-checked fast-fail on `m_shutdown_called` in all mutators; every public mutation or teardown entry point also fails closed (`HookError::ReentrantCallRejected`, a false/zero result, or a logged no-op for void lifecycle calls) when the per-thread reentrancy guard is set, so a call from inside a `with_*` callback returns or no-ops instead of recursively acquiring the non-recursive lock; the batch toggles (`enable_hooks`/`disable_hooks`/`*_all`) collect their log lines under the lock and emit them after release so a synchronous sink flush or a blocking async overflow never stalls an exclusive acquirer; destructor fallback (when `DMK_Shutdown()` was not called) acquires `m_mutator_gate` exclusively, flips `m_shutdown_called`, drains readers via exclusive `m_hooks_mutex`, then clears the maps -- under loader lock it pins the module and swaps each map's contents into heap storage allocated via `new (std::nothrow)` so the storage outlives the destructor without ever draining, mirroring the leak-on-loader-lock discipline used in `Logger::shutdown_internal` and `ConfigWatcher::~ConfigWatcher` | `shared_lock` SRWLOCK reader for `with_inline_hook()` |
359359
| Logger | `atomic<shared_ptr>` for lock-free async reads; `shutdown_internal` and `disable_async_mode` are safe across repeated shutdown / enable_async_mode cycles: when the writer thread has to be detached under loader lock, the module is pinned and the `shared_ptr<AsyncLogger>` is moved into a per-call permanent cell (normal path: `new (std::nothrow)`; fallback path: non-CRT permanent storage), so a heap allocation failure cannot drop the last handle while the writer may still be running | Single atomic load on log level check |
360-
| AsyncLogger | Lock-free MPMC queue (Vyukov-style); post-join drain on shutdown (at most one message per producer can be lost in the nanosecond race between drain and force-zero -- accepted trade-off to avoid atomic overhead on every enqueue); timestamp caching in write batches | Atomic sequence numbers per slot |
360+
| AsyncLogger | Lock-free MPMC queue (Vyukov-style); post-join drain on shutdown (at most one message per producer can be lost in the nanosecond race between drain and force-zero -- accepted trade-off to avoid atomic overhead on every enqueue); a producer wakes a parked writer through a seq_cst pending-count/flag handshake (`m_pending_messages` is made non-zero before the queue slot is published, the writer publishes `m_writer_waiting` before checking that count and blocking, and the producer notifies under `m_flush_mutex` only when the flag is set), so the busy-writer hot path stays lock-free and syscall-free yet a push can never strand a message until the flush-interval timeout; timestamp caching in write batches | Atomic sequence numbers per slot; flag-gated writer wakeup |
361361
| InputPoller | Atomic `m_active_states[]` array; the poll thread re-reserves its deferred-callback staging vector to the live binding count each cycle and stages it under a catch, so a runtime binding growth past the startup reserve cannot reallocate-then-throw out of the `jthread` body; a failed callback batch is dropped, not fatal | `shared_lock` (uncontended SRWLOCK reader) guarding the `m_active_states` pointer swap + `memory_order_relaxed` load per binding; keyboard/mouse reads route through a poll-thread-private per-cycle `KeyStateCache` so each distinct VK gets one coherent `GetAsyncKeyState` sample per cycle, not one call per binding reference |
362362
| InputManager | `mutex` for lifecycle, `atomic<shared_ptr<InputPoller>>` for reads | `atomic<shared_ptr<InputPoller>>` acquire-load, then the poller's `shared_lock` + relaxed load (not lock-free) |
363363
| InputIntercept (internal `src/input_intercept.*`) | File-scope atomics shared between the poll thread and the game's threads (XInput callers, window message thread); owns its safetyhook InlineHooks directly (not via HookManager) because the poll thread reads the trampoline and the hook lifetime is coupled to the poll thread; consume-until-release latch and wheel-pulse state are poll-thread-private; teardown skipped under loader lock (detours left installed against the pinned module) | Lock-free atomic loads in each detour; allocation-free, non-throwing detour bodies |

README.md

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -131,10 +131,10 @@ See the [Config Hot-Reload Guide](docs/config-hot-reload/README.md) for the thre
131131
<summary><strong>Async Logger</strong></summary>
132132
133133
- Lock-free, bounded queue-based async logger decoupling log production from file I/O
134-
- Minimal latency on the producer side with batched writes on the consumer thread
134+
- Minimal latency on the producer side with batched writes on the consumer thread; a parked writer is woken promptly through a pending-count/flag handshake, so no message waits out the flush interval
135135
- Configurable overflow policies: DropNewest / DropOldest / Block / SyncFallback
136136
- Bounded Block policy with 16 ms default timeout (one frame at 60 fps) to prevent thread starvation
137-
- Inline buffer optimization for messages <= 512 bytes
137+
- Inline buffer optimization for messages <= 512 bytes; a formatted log line that fits is rendered into a stack buffer and never materializes a heap string
138138
- Message size validation with truncation for messages > 16 MB
139139
140140
</details>

include/DetourModKit/async_logger.hpp

Lines changed: 31 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -113,7 +113,7 @@ namespace DetourModKit
113113
std::chrono::system_clock::time_point timestamp;
114114
std::thread::id thread_id;
115115

116-
static constexpr size_t MAX_INLINE_SIZE = 512;
116+
static constexpr size_t MAX_INLINE_SIZE = LOG_INLINE_MESSAGE_SIZE;
117117
static constexpr size_t MAX_VALID_LENGTH = MAX_MESSAGE_SIZE;
118118
std::array<char, MAX_INLINE_SIZE> buffer;
119119
size_t length{0};
@@ -343,6 +343,15 @@ namespace DetourModKit
343343

344344
[[nodiscard]] bool is_running() const noexcept;
345345

346+
/**
347+
* @brief Reports whether the writer thread is currently parked on the flush condition variable.
348+
* @details Observability accessor for the idle-park state set by the writer immediately before it
349+
* blocks in wait_for and cleared when it wakes. Lets a test or diagnostic confirm the
350+
* writer has reached the parked path deterministically instead of relying on a fixed
351+
* sleep. The flag can flip at any time, so treat the result as a point-in-time snapshot.
352+
*/
353+
[[nodiscard]] bool is_writer_waiting() const noexcept;
354+
346355
[[nodiscard]] size_t queue_size() const noexcept;
347356

348357
/**
@@ -371,6 +380,20 @@ namespace DetourModKit
371380

372381
bool handle_overflow(LogMessage &&message) noexcept;
373382

383+
/**
384+
* @brief Wakes the writer thread if it is parked on m_flush_cv after a successful push.
385+
* @details A successful producer has already made m_pending_messages non-zero before publishing
386+
* a new queue slot, or preserved it while replacing an old slot. The writer publishes
387+
* m_writer_waiting before checking that same pending count and blocking. Those seq_cst
388+
* operations form a store/load handshake: if the writer misses the pending state, the
389+
* producer observes m_writer_waiting and notifies under m_flush_mutex; if the producer
390+
* observes false, the writer's pending-count predicate sees the work and does not block.
391+
* notify_all (not notify_one) is used so a flusher waiting on the same condition variable
392+
* cannot absorb the notification and leave the writer asleep. When the writer is
393+
* draining, this is a seq_cst flag load with no mutex or syscall.
394+
*/
395+
void notify_writer() noexcept;
396+
374397
DynamicMPMCQueue m_queue;
375398
AsyncLoggerConfig m_config;
376399

@@ -383,6 +406,13 @@ namespace DetourModKit
383406

384407
std::mutex m_flush_mutex;
385408
std::condition_variable m_flush_cv;
409+
410+
// Set true by the writer immediately before it parks on m_flush_cv and cleared when it wakes.
411+
// Producers read it outside m_flush_mutex after a successful queue push; the seq_cst order shared
412+
// with m_pending_messages makes a racing push either visible to the writer's wait predicate or
413+
// visible here as a parked-writer wake.
414+
std::atomic<bool> m_writer_waiting{false};
415+
386416
std::atomic<size_t> m_pending_messages{0};
387417
std::atomic<size_t> m_dropped_messages{0};
388418
};

include/DetourModKit/logger.hpp

Lines changed: 49 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,8 @@
55
#include <string_view>
66
#include <mutex>
77
#include <memory>
8+
#include <array>
9+
#include <cstddef>
810
#include <format>
911
#include <atomic>
1012

@@ -55,6 +57,14 @@ namespace DetourModKit
5557
inline constexpr const char *DEFAULT_LOG_FILE_NAME = "DetourModKit_Log.txt";
5658
inline constexpr const char *DEFAULT_TIMESTAMP_FORMAT = "%Y-%m-%d %H:%M:%S";
5759

60+
// Upper bound, in bytes, on a log line that the formatted log() / try_log() fast path renders without
61+
// a heap allocation. Those templates format into a stack buffer of this size and forward a view when
62+
// the line fits, so a line up to this length never materializes a heap std::string. It mirrors the
63+
// async sink's inline message buffer (LogMessage::MAX_INLINE_SIZE), which likewise stores a line of
64+
// this size without touching the StringPool; longer lines take the documented overflow path on both
65+
// sides.
66+
inline constexpr std::size_t LOG_INLINE_MESSAGE_SIZE = 512;
67+
5868
// Forward declarations
5969
struct AsyncLoggerConfig;
6070
class AsyncLogger;
@@ -202,7 +212,13 @@ namespace DetourModKit
202212
{
203213
if (level >= m_current_log_level.load(std::memory_order_acquire))
204214
{
205-
log(level, std::format(fmt, std::forward<Args>(args)...));
215+
// Format into a stack buffer instead of through a std::format temporary so a line that fits
216+
// the inline buffer never heap-allocates. The view handed to the sink is consumed
217+
// synchronously (the async path copies it into LogMessage, the sync path writes it) before
218+
// this call returns, so it never outlives the stack buffer.
219+
static_cast<void>(format_dispatch([this, level](std::string_view formatted)
220+
{ return this->log(level, formatted); }, fmt,
221+
std::forward<Args>(args)...));
206222
}
207223
}
208224

@@ -255,7 +271,11 @@ namespace DetourModKit
255271
}
256272
try
257273
{
258-
return log_noexcept(level, std::format(fmt, std::forward<Args>(args)...));
274+
// Same allocation-free formatting as log(); the try/catch preserves the no-throw contract
275+
// because format_to_n and the std::format overflow fallback can both throw.
276+
return format_dispatch([this, level](std::string_view formatted) noexcept
277+
{ return this->log_noexcept(level, formatted); }, fmt,
278+
std::forward<Args>(args)...);
259279
}
260280
catch (...)
261281
{
@@ -296,6 +316,33 @@ namespace DetourModKit
296316
Logger(Logger &&) = delete;
297317
Logger &operator=(Logger &&) = delete;
298318

319+
/**
320+
* @brief Formats one log line into a stack buffer and hands it to @p sink.
321+
* @details Renders into a buffer the size of the async sink's inline message buffer
322+
* (LOG_INLINE_MESSAGE_SIZE). std::format_to_n reports the untruncated length, so a line
323+
* that fits is passed to @p sink as a view into the stack buffer with no heap allocation;
324+
* a std::format temporary would instead allocate for any result past the small-string
325+
* limit, which the async LogMessage then copies into its own inline buffer anyway. A line
326+
* longer than the inline buffer is the documented overflow case (the async sink stores it
327+
* via StringPool / heap up to MAX_MESSAGE_SIZE), so it is re-formatted once through
328+
* std::format to give @p sink the full line. The formatter only reads its arguments (it
329+
* never moves them), so forwarding the same pack to both format_to_n and the std::format
330+
* fallback is safe.
331+
* @return Whatever @p sink returns for the line.
332+
*/
333+
template <typename Sink, typename... Args>
334+
static auto format_dispatch(Sink &&sink, std::format_string<Args...> fmt, Args &&...args)
335+
{
336+
std::array<char, LOG_INLINE_MESSAGE_SIZE> buffer;
337+
const auto result = std::format_to_n(buffer.data(), buffer.size(), fmt, std::forward<Args>(args)...);
338+
const auto formatted = static_cast<std::size_t>(result.size);
339+
if (formatted <= buffer.size())
340+
{
341+
return sink(std::string_view(buffer.data(), formatted));
342+
}
343+
return sink(std::string_view(std::format(fmt, std::forward<Args>(args)...)));
344+
}
345+
299346
/**
300347
* @brief Shared shutdown logic used by both ~Logger() and shutdown().
301348
*/

0 commit comments

Comments
 (0)