Skip to content

Commit 0ad0fdb

Browse files
perf: add pluggable log sink, reuse thread-local buffers, and expand coverage
1 parent c550d39 commit 0ad0fdb

3 files changed

Lines changed: 235 additions & 97 deletions

File tree

ScopeTimer.log

Lines changed: 27 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,27 @@
1+
[simpleWork] TID=001 | void simpleWork() | start=2025-11-13 02:15:05.556 | end=2025-11-13 02:15:05.559 | elapsed=3.138ms
2+
[nestedScopes:inner 1] TID=001 | void nestedScopes() | start=2025-11-13 02:15:05.561 | end=2025-11-13 02:15:05.563 | elapsed=1.883ms
3+
[nestedScopes:inner 2] TID=001 | void nestedScopes() | start=2025-11-13 02:15:05.563 | end=2025-11-13 02:15:05.566 | elapsed=3.033ms
4+
[nestedScopes:outer] TID=001 | void nestedScopes() | start=2025-11-13 02:15:05.560 | end=2025-11-13 02:15:05.567 | elapsed=6.838ms
5+
[multi:second] TID=001 | void multipleTimersSameScope() | start=2025-11-13 02:15:05.568 | end=2025-11-13 02:15:05.569 | elapsed=1.004ms
6+
[multi:first] TID=001 | void multipleTimersSameScope() | start=2025-11-13 02:15:05.567 | end=2025-11-13 02:15:05.569 | elapsed=1.892ms
7+
[conditionalWork] TID=001 | void conditionalWork(bool) | start=2025-11-13 02:15:05.570 | end=2025-11-13 02:15:05.572 | elapsed=1.505ms
8+
[loopedWork:iteration] TID=001 | void loopedWork(int) | start=2025-11-13 02:15:05.572 | end=2025-11-13 02:15:05.572 | elapsed=382.000us
9+
[loopedWork:iteration] TID=001 | void loopedWork(int) | start=2025-11-13 02:15:05.572 | end=2025-11-13 02:15:05.573 | elapsed=381.000us
10+
[loopedWork:iteration] TID=001 | void loopedWork(int) | start=2025-11-13 02:15:05.573 | end=2025-11-13 02:15:05.573 | elapsed=379.000us
11+
[loopedWork:iteration] TID=001 | void loopedWork(int) | start=2025-11-13 02:15:05.573 | end=2025-11-13 02:15:05.574 | elapsed=385.000us
12+
[loopedWork:iteration] TID=001 | void loopedWork(int) | start=2025-11-13 02:15:05.574 | end=2025-11-13 02:15:05.574 | elapsed=384.000us
13+
[loopedWork:total] TID=001 | void loopedWork(int) | start=2025-11-13 02:15:05.572 | end=2025-11-13 02:15:05.574 | elapsed=1.959ms
14+
[threadedWork:worker] TID=002 | threadedWork(int)::<lambda()> | start=2025-11-13 02:15:05.574 | end=2025-11-13 02:15:05.575 | elapsed=632.000us
15+
[threadedWork:worker] TID=003 | threadedWork(int)::<lambda()> | start=2025-11-13 02:15:05.574 | end=2025-11-13 02:15:05.575 | elapsed=881.000us
16+
[threadedWork:worker] TID=004 | threadedWork(int)::<lambda()> | start=2025-11-13 02:15:05.574 | end=2025-11-13 02:15:05.575 | elapsed=1.006ms
17+
[threadedWork:total] TID=001 | void threadedWork(int) | start=2025-11-13 02:15:05.574 | end=2025-11-13 02:15:05.575 | elapsed=1.141ms
18+
[Worker:constructor] TID=001 | Worker::Worker() | start=2025-11-13 02:15:05.575 | end=2025-11-13 02:15:05.576 | elapsed=630.000us
19+
[Worker:singleTask] TID=001 | void Worker::doTask(std::string_view) const | start=2025-11-13 02:15:05.576 | end=2025-11-13 02:15:05.577 | elapsed=1.259ms
20+
[Worker:task] TID=001 | void Worker::doTask(std::string_view) const | start=2025-11-13 02:15:05.577 | end=2025-11-13 02:15:05.578 | elapsed=1.259ms
21+
[Worker:task] TID=001 | void Worker::doTask(std::string_view) const | start=2025-11-13 02:15:05.578 | end=2025-11-13 02:15:05.580 | elapsed=1.258ms
22+
[Worker:task] TID=001 | void Worker::doTask(std::string_view) const | start=2025-11-13 02:15:05.580 | end=2025-11-13 02:15:05.581 | elapsed=1.259ms
23+
[Worker:doMultipleTasks] TID=001 | void Worker::doMultipleTasks(int, bool) const | start=2025-11-13 02:15:05.577 | end=2025-11-13 02:15:05.581 | elapsed=3.795ms
24+
[Worker:task] TID=001 | void Worker::doTask(std::string_view) const | start=2025-11-13 02:15:05.581 | end=2025-11-13 02:15:05.582 | elapsed=1.259ms
25+
[Worker:task] TID=001 | void Worker::doTask(std::string_view) const | start=2025-11-13 02:15:05.582 | end=2025-11-13 02:15:05.583 | elapsed=1.254ms
26+
[ScopeTimer] TID=001 | LifetimeTracked | start=2025-11-13 02:15:05.583 | end=2025-11-13 02:15:05.586 | elapsed=3.092ms
27+
[ScopeTimer] TID=001 | int main() | start=2025-11-13 02:15:05.556 | end=2025-11-13 02:15:05.586 | elapsed=30.894ms

include/ScopeTimer.hpp

Lines changed: 151 additions & 76 deletions
Original file line numberDiff line numberDiff line change
@@ -96,10 +96,14 @@
9696
#include <cstdlib>
9797
#include <cstring>
9898
#include <ctime>
99+
#include <fcntl.h>
100+
#include <functional>
99101
#include <mutex>
100102
#include <optional>
101103
#include <string>
102104
#include <string_view>
105+
#include <sys/stat.h>
106+
#include <unistd.h>
103107
#include <utility>
104108

105109
#if defined(__GNUC__) || defined(__clang__)
@@ -260,12 +264,12 @@ namespace xyzzy::scopetimer {
260264
formatTime(endWall, fmtBufs.endBuf, sizeof(fmtBufs.endBuf));
261265
formatElapsed(elapsedNs, fmtBufs.elapsedBuf, sizeof(fmtBufs.elapsedBuf));
262266

263-
// Final line buffer
264-
char line[512];
267+
// Final line buffer reused per thread to avoid repeated stack allocation.
268+
auto& lineBuf = lineBuffer();
265269

266270
// Build the log line
267271
int n = std::snprintf(
268-
line, sizeof(line),
272+
lineBuf.data, sizeof(lineBuf.data),
269273
"[%.*s] TID=%03u | %.*s | start=%s | end=%s | elapsed=%s\n",
270274
static_cast<int>(label_.size()), label_.data(),
271275
threadNum_,
@@ -276,22 +280,20 @@ namespace xyzzy::scopetimer {
276280
);
277281

278282
// Convert snprintf result to a safe byte count
279-
const std::size_t len = ScopeTimerDetail::finalize_snprintf_result(n, line, sizeof(line));
283+
const std::size_t len = ScopeTimerDetail::finalize_snprintf_result(n, lineBuf.data, sizeof(lineBuf.data));
280284

281285
// Keep log lines non-interleaved (mutex only around IO)
282286
std::lock_guard lock(outMutex());
283287

284-
if (FILE* fp = logFile()) {
285-
if (len) {
286-
std::fwrite(line, 1, len, fp);
287-
}
288+
if (len) {
289+
sinkWriteFn_(lineBuf.data, len);
290+
}
288291

289-
// Periodic flush to keep logs visible even with large buffers
290-
unsigned cnt = lineCounter().fetch_add(1, std::memory_order_relaxed) + 1;
292+
// Periodic flush to keep logs visible even with large buffers
293+
unsigned cnt = lineCounter().fetch_add(1, std::memory_order_relaxed) + 1;
291294

292-
if (cnt % flushInterval() == 0) { // configurable via SCOPE_TIMER_FLUSH_N
293-
std::fflush(fp);
294-
}
295+
if (cnt % flushInterval() == 0) { // configurable via SCOPE_TIMER_FLUSH_N
296+
sinkFlushFn_();
295297
}
296298
}
297299

@@ -345,12 +347,6 @@ namespace xyzzy::scopetimer {
345347
return tid;
346348
}
347349

348-
// Accessor for the singleton FILE* so I can flush/close at process exit.
349-
static inline FILE*& fileHandle() noexcept {
350-
static FILE* fp{ nullptr };
351-
return fp;
352-
}
353-
354350
/**
355351
* @brief Returns the periodic flush interval for the ScopeTimer log.
356352
*
@@ -407,63 +403,6 @@ namespace xyzzy::scopetimer {
407403
logDirInitialized_ = true;
408404
}
409405

410-
/**
411-
* @brief Provides a singleton FILE* for logging with a large user buffer.
412-
*
413-
* The log file path is controlled by the SCOPE_TIMER_DIR environment variable,
414-
* defaulting to /tmp/ScopeTimer.log. Uses a 1 MiB buffer for high-throughput buffered IO.
415-
*
416-
* @return FILE* Pointer to the opened log file, or nullptr on failure.
417-
*/
418-
static inline FILE* logFile() noexcept {
419-
FILE*& fp = fileHandle();
420-
421-
if(fp) {
422-
return fp;
423-
}
424-
425-
static std::string lastFailedPath;
426-
static bool lastAttemptFailed = false;
427-
428-
// Singleton FILE* with large user buffer for high-throughput buffered IO
429-
const std::string path = logDirectory() + "ScopeTimer.log";
430-
431-
if (lastAttemptFailed && path == lastFailedPath) {
432-
return nullptr;
433-
}
434-
435-
if (FILE* f = std::fopen(path.c_str(), "a")) {
436-
// Use a static buffer for the FILE*, 1 MiB for throughput
437-
static auto buf = new char[1 << 20];
438-
std::setvbuf(f, buf, _IOFBF, 1 << 20);
439-
fp = f;
440-
lastAttemptFailed = false;
441-
lastFailedPath.clear();
442-
443-
// Ensure flush+close at process shutdown
444-
static bool registered = false;
445-
446-
if(!registered) {
447-
std::atexit([]() noexcept {
448-
FILE* fh = fileHandle();
449-
450-
if(fh) {
451-
std::fflush(fh);
452-
std::fclose(fh);
453-
// do not reset fh here; process is exiting
454-
}
455-
});
456-
registered = true;
457-
}
458-
}
459-
460-
if (!fp) {
461-
lastFailedPath = path;
462-
lastAttemptFailed = true;
463-
}
464-
return fp;
465-
}
466-
467406
// One-time-selected elapsed-time formatter infrastructure
468407
// I call through a cached function pointer to avoid branching in the hot path.
469408
enum class TimeFormat { Auto, Seconds, Millis, Micros, Nanos };
@@ -614,6 +553,44 @@ namespace xyzzy::scopetimer {
614553
return formatBuffers().endBuf;
615554
}
616555

556+
struct LineBuffer {
557+
char data[512];
558+
};
559+
560+
static inline LineBuffer& lineBuffer() noexcept {
561+
return tlsLineBuffer_;
562+
}
563+
564+
static void defaultSinkWrite(const char* data, std::size_t len) noexcept;
565+
static void defaultSinkFlush() noexcept;
566+
static void noopSinkFlush() noexcept;
567+
568+
using SinkWriteFn = std::function<void(const char*, std::size_t)>;
569+
using SinkFlushFn = std::function<void()>;
570+
571+
static inline SinkWriteFn sinkWriteFn_{
572+
[](const char* data, std::size_t len) {
573+
defaultSinkWrite(data, len);
574+
}
575+
};
576+
static inline SinkFlushFn sinkFlushFn_{
577+
[] {
578+
defaultSinkFlush();
579+
}
580+
};
581+
582+
static inline void setLogSinkForTests(SinkWriteFn writeFn, SinkFlushFn flushFn) noexcept {
583+
if (writeFn) {
584+
closeLogFd();
585+
sinkWriteFn_ = std::move(writeFn);
586+
sinkFlushFn_ = flushFn ? std::move(flushFn) : SinkFlushFn{noopSinkFlush};
587+
} else {
588+
closeLogFd();
589+
sinkWriteFn_ = defaultSinkWrite;
590+
sinkFlushFn_ = defaultSinkFlush;
591+
}
592+
}
593+
617594
inline void assignLabel(detail::LabelData&& data) noexcept {
618595
if (!data.storage.empty()) {
619596
labelStorage_ = std::move(data.storage);
@@ -631,9 +608,69 @@ namespace xyzzy::scopetimer {
631608
uint32_t threadNum_; ///< Unique thread ID number.
632609

633610
static inline thread_local FormatBuffers tlsFormatBuffers_{};
611+
static inline thread_local LineBuffer tlsLineBuffer_{};
634612
static inline std::string logDirCache_{"/tmp/"};
635613
static inline bool logDirInitialized_{false};
636614

615+
static inline bool ensureLogFdOpen() noexcept {
616+
int& fd = logFd();
617+
if (fd >= 0) {
618+
return true;
619+
}
620+
621+
static std::string lastFailedPath;
622+
static bool lastAttemptFailed = false;
623+
624+
const std::string path = logDirectory() + "ScopeTimer.log";
625+
626+
if (lastAttemptFailed && path == lastFailedPath) {
627+
return false;
628+
}
629+
630+
if (int newFd = ::open(path.c_str(), O_CREAT | O_WRONLY | O_APPEND, 0644); newFd >= 0) {
631+
fd = newFd;
632+
lastAttemptFailed = false;
633+
lastFailedPath.clear();
634+
registerLogFdCleanup();
635+
return true;
636+
}
637+
638+
lastFailedPath = path;
639+
lastAttemptFailed = true;
640+
return false;
641+
}
642+
643+
static inline void registerLogFdCleanup() noexcept {
644+
static bool registered = false;
645+
if (!registered) {
646+
std::atexit([]() noexcept {
647+
closeLogFd();
648+
});
649+
registered = true;
650+
}
651+
}
652+
653+
static inline int& logFd() noexcept {
654+
static int fd = -1;
655+
return fd;
656+
}
657+
658+
static inline void closeLogFd() noexcept {
659+
int& fd = logFd();
660+
if (fd >= 0) {
661+
::close(fd);
662+
fd = -1;
663+
}
664+
}
665+
666+
static inline int defaultLogFdForTests() noexcept {
667+
return logFd();
668+
}
669+
670+
static inline void closeLogFdForTests() noexcept {
671+
closeLogFd();
672+
}
673+
637674
/**
638675
* I store both a steady_clock (startSteady_) and a system_clock (startWall_) timestamp:
639676
* - startSteady_: Used for computing precise elapsed durations, immune to system clock changes.
@@ -782,3 +819,41 @@ namespace xyzzy::scopetimer {
782819
#endif // NDEBUG
783820

784821
} // namespace xyzzy::scopetimer
822+
823+
// Back-compatibility alias so existing code that referenced ::ewm::scopetimer keeps working.
824+
namespace ewm {
825+
namespace scopetimer = ::xyzzy::scopetimer;
826+
}
827+
828+
inline void xyzzy::scopetimer::ScopeTimer::defaultSinkWrite(const char* data, std::size_t len) noexcept {
829+
if (len == 0) {
830+
return;
831+
}
832+
if (!ensureLogFdOpen()) {
833+
return;
834+
}
835+
int fd = logFd();
836+
if (fd < 0) {
837+
return;
838+
}
839+
ssize_t unused = ::write(fd, data, len);
840+
(void)unused;
841+
}
842+
843+
inline void xyzzy::scopetimer::ScopeTimer::defaultSinkFlush() noexcept {
844+
int fd = logFd();
845+
if (fd >= 0) {
846+
::fsync(fd);
847+
}
848+
}
849+
850+
#ifdef __clang__
851+
#pragma clang diagnostic push
852+
#pragma clang diagnostic ignored "-Wunused-parameter"
853+
#endif
854+
inline void xyzzy::scopetimer::ScopeTimer::noopSinkFlush() noexcept {
855+
// Intentionally blank: used when tests inject a sink but do not need flush semantics.
856+
}
857+
#ifdef __clang__
858+
#pragma clang diagnostic pop
859+
#endif

0 commit comments

Comments
 (0)