From 57c7f5c9edc8c3a37150181c0604c090c1cd73b1 Mon Sep 17 00:00:00 2001 From: Marco Edoardo Santimaria Date: Tue, 13 Oct 2026 09:13:38 +0200 Subject: [PATCH 1/3] Performance improvement of syscall logger --- calf/SyscallLogger.h | 157 ++++++++++++++++++++++++++++--- tests/syscall_protobuf_tests.cpp | 64 ++++++++++--- 2 files changed, 197 insertions(+), 24 deletions(-) diff --git a/calf/SyscallLogger.h b/calf/SyscallLogger.h index b2a3bc7..9d47769 100644 --- a/calf/SyscallLogger.h +++ b/calf/SyscallLogger.h @@ -10,6 +10,7 @@ #include #include #include +#include #include #include #include @@ -19,6 +20,13 @@ #include "format/BaseLogger.h" #include "format/LogFormat.h" +// Trace-event buffer capacity (bytes per thread). Events accumulate here and are flushed to +// disk in bulk when the buffer fills or the process exits. Tune up for even fewer syscalls on +// heavy syscall traces; keep modest if many threads each allocate one. +#ifndef CALF_LOG_BUFFER_CAPACITY +#define CALF_LOG_BUFFER_CAPACITY 65536 +#endif + #ifdef CALF_LOG_FORMAT_PROTOBUF #define CALF_SYSCALL_LOGGER_TYPE PerfettoSyscallLogger #else @@ -34,6 +42,67 @@ struct CALF_SYSCALL_LOGGER_TYPE : CalfLogBase { inline static std::atomic traceFileState{0}; #endif + // Caches for getpid()/gettid() so the per-event hot path issues no syscall for them. + // pid/tid are constant for a thread's lifetime; the only invalidation is fork(), handled + // by the atfork child hook below (clears them so the child re-reads its real pid/tid). + static thread_local pid_t cachedPid; + static thread_local long cachedTid; + + // Trace-event buffer: events append here and are written to disk in bulk only when the + // buffer is full or the owning thread/process terminates. This avoids one write+flock + // syscall per event. Each thread owns its buffer, matching the per-thread fileFD below. + static constexpr std::size_t traceBufferCapacity = CALF_LOG_BUFFER_CAPACITY; + static thread_local char traceBuffer[CALF_LOG_BUFFER_CAPACITY]; + static thread_local std::size_t traceBufferUsed; + + // Flush the owning thread's buffer when the thread exits (so short-lived worker threads + // do not silently drop buffered events); the atexit handler covers the root thread. + struct TraceFlushOnExit { + ~TraceFlushOnExit() { flushTraceBuffer(); } + }; +#ifdef CALF_LOG_FORMAT_PROTOBUF + inline static thread_local TraceFlushOnExit traceFlushGuard; +#endif + + // Write the accumulated trace bytes to disk (single flock+write+unflock), then reset. + // The buffer must be empty on entry to the child path of fork(), so the atfork child hook + // drops inherited in-flight bytes instead of writing a parent's events into the child file. + static void flushTraceBuffer() { + if (traceBufferUsed == 0) { + return; + } + ensureFileOpen(); +#ifdef CALF_LOG_FORMAT_PROTOBUF + calf_syscall(SYS_flock, fileFD, LOCK_EX); +#endif + std::size_t written = 0; + while (written < traceBufferUsed) { + const long result = calf_syscall(SYS_write, fileFD, traceBuffer + written, + traceBufferUsed - written); + if (result <= 0) { + break; + } + written += static_cast(result); + } +#ifdef CALF_LOG_FORMAT_PROTOBUF + calf_syscall(SYS_flock, fileFD, LOCK_UN); +#endif + traceBufferUsed = 0; + } + + static void registerLifecycleHandlers() { + static const bool registered = [] { + ::pthread_atfork(nullptr, nullptr, +[] { + cachedPid = 0; + cachedTid = 0; + traceBufferUsed = 0; // child file differs; inherit nothing + }); + ::atexit(+[] { flushTraceBuffer(); }); // force-dump any partial tail on exit + return true; + }(); + (void)registered; + } + // Syscall function pointer — defaults to ::syscall. using SyscallFn = long (*)(long, ...); inline static thread_local SyscallFn syscallFn = ::syscall; @@ -62,9 +131,23 @@ struct CALF_SYSCALL_LOGGER_TYPE : CalfLogBase { } #ifdef CALF_LOG_FORMAT_PROTOBUF - static pid_t processId() { return static_cast(calf_syscall(SYS_getpid)); } + static pid_t processId() { + registerLifecycleHandlers(); + if (cachedPid != 0) { + return cachedPid; + } + cachedPid = static_cast(calf_syscall(SYS_getpid)); + return cachedPid; + } - static long threadId() { return calf_syscall(SYS_gettid); } + static long threadId() { + registerLifecycleHandlers(); + if (cachedTid != 0) { + return cachedTid; + } + cachedTid = calf_syscall(SYS_gettid); + return cachedTid; + } #endif explicit CALF_SYSCALL_LOGGER_TYPE() { @@ -78,24 +161,40 @@ struct CALF_SYSCALL_LOGGER_TYPE : CalfLogBase { } static void rawWriteBytes(const char *buf, int len) { - ensureFileOpen(); #ifdef CALF_LOG_FORMAT_PROTOBUF - calf_syscall(SYS_flock, fileFD, LOCK_EX); -#endif + const auto size = static_cast(len); + // Oversized single write goes straight out so we never copy it twice. + if (size >= traceBufferCapacity) { + flushTraceBuffer(); + ensureFileOpen(); + calf_syscall(SYS_flock, fileFD, LOCK_EX); + std::size_t written = 0; + while (written < size) { + const long result = calf_syscall(SYS_write, fileFD, buf + written, size - written); + if (result <= 0) { + break; + } + written += static_cast(result); + } + calf_syscall(SYS_flock, fileFD, LOCK_UN); + return; + } + if (traceBufferUsed + size > traceBufferCapacity) { + flushTraceBuffer(); // make room + } + std::memcpy(traceBuffer + traceBufferUsed, buf, size); + traceBufferUsed += size; +#else + ensureFileOpen(); int written = 0; while (written < len) { - const long result = calf_syscall(SYS_write, fileFD, buf + written, - static_cast(len - written)); + const long result = + calf_syscall(SYS_write, fileFD, buf + written, static_cast(len - written)); if (result <= 0) { -#ifdef CALF_LOG_FORMAT_PROTOBUF - calf_syscall(SYS_flock, fileFD, LOCK_UN); -#endif return; } written += static_cast(result); } -#ifdef CALF_LOG_FORMAT_PROTOBUF - calf_syscall(SYS_flock, fileFD, LOCK_UN); #endif } @@ -103,7 +202,32 @@ struct CALF_SYSCALL_LOGGER_TYPE : CalfLogBase { rawWriteBytes(buf, static_cast(::strlen(buf))); } - static void flush() {} + // Force-write any buffered bytes to disk now. Called by the atexit handler and by any + // caller that needs durability before process/thread exit (buffered bytes are otherwise + // lost when a thread terminates). + static void forceFlush() { +#ifdef CALF_LOG_FORMAT_PROTOBUF + flushTraceBuffer(); +#endif + } + + // Discard the per-thread caching. After a fork()/exec() or between isolated test scopes, + // this forces the next processId()/threadId() to hit the real syscall once more. + static void resetPidTidCache() { + cachedPid = 0; + cachedTid = 0; + } + + // Called by ProtobufLogBase after every SliceEnd, i.e. once per recorded syscall. + // Only a genuinely full buffer triggers a write; otherwise events stay buffered and are + // flushed when the buffer fills or the process terminates (atexit). + static void flush() { +#ifdef CALF_LOG_FORMAT_PROTOBUF + if (traceBufferUsed >= traceBufferCapacity) { + flushTraceBuffer(); + } +#endif + } static void reopenRootArray() { ensureFileOpen(); @@ -127,6 +251,9 @@ struct CALF_SYSCALL_LOGGER_TYPE : CalfLogBase { static void ensureFileOpen() { #ifdef CALF_LOG_FORMAT_PROTOBUF + // odr-use the per-thread flush guard so it constructs (and its destructor flushes the + // thread's buffer) for every thread that actually records events. + (void)&traceFlushGuard; const auto currentPid = processId(); if (fileFD != -1 && filePid != currentPid) { calf_syscall(SYS_close, fileFD); @@ -242,6 +369,10 @@ inline thread_local char CALF_SYSCALL_LOGGER_TYPE::filePath[PATH_MAX] = {'\0'}; #ifdef CALF_LOG_FORMAT_PROTOBUF inline thread_local pid_t CALF_SYSCALL_LOGGER_TYPE::filePid = 0; #endif +inline thread_local pid_t CALF_SYSCALL_LOGGER_TYPE::cachedPid = 0; +inline thread_local long CALF_SYSCALL_LOGGER_TYPE::cachedTid = 0; +inline thread_local char CALF_SYSCALL_LOGGER_TYPE::traceBuffer[CALF_SYSCALL_LOGGER_TYPE::traceBufferCapacity]; +inline thread_local std::size_t CALF_SYSCALL_LOGGER_TYPE::traceBufferUsed = 0; using SyscallLogger = CALF_SYSCALL_LOGGER_TYPE; #undef CALF_SYSCALL_LOGGER_TYPE diff --git a/tests/syscall_protobuf_tests.cpp b/tests/syscall_protobuf_tests.cpp index 2dbc92e..8243493 100644 --- a/tests/syscall_protobuf_tests.cpp +++ b/tests/syscall_protobuf_tests.cpp @@ -112,26 +112,65 @@ TEST(SyscallProtobufLoggerTest, PreservesInterfaceAndWritesProtobuf) { }); } for (auto &thread : threads) { - thread.join(); + thread.join(); // worker threads flush their per-thread buffers on exit } EXPECT_EQ(threadPaths[0], path); EXPECT_EQ(threadPaths[1], path); + // Events are buffered and only written in bulk; flush the main thread's tail so the + // full trace is on disk before we read it back. + SyscallLogger::forceFlush(); + std::ifstream input(path, std::ios::binary); const std::string data((std::istreambuf_iterator(input)), std::istreambuf_iterator()); perfetto::protos::Trace trace; ASSERT_TRUE(trace.ParseFromString(data)); - ASSERT_EQ(trace.packet_size(), 10); - EXPECT_TRUE(trace.packet(0).has_track_descriptor()); - EXPECT_EQ(trace.packet(1).track_event().type(), - perfetto::protos::TrackEvent::TYPE_SLICE_BEGIN); - EXPECT_EQ(trace.packet(1).track_event().debug_annotations(0).string_value(), "scope=2"); - EXPECT_EQ(trace.packet(2).track_event().type(), - perfetto::protos::TrackEvent::TYPE_INSTANT); - EXPECT_EQ(trace.packet(2).track_event().debug_annotations(0).string_value(), "event=written"); - EXPECT_EQ(trace.packet(3).track_event().type(), - perfetto::protos::TrackEvent::TYPE_SLICE_END); + + // With buffering, each thread's events are written in one chunk on thread exit/force + // flush, so the inter-thread ordering is a function of flush order, not write order. + // Assert the full content set instead of fixed packet indices. + int trackDescriptors = 0; + int sliceBegins = 0; + int instants = 0; + int sliceEnds = 0; + bool sawScopeAnnotation = false; + bool sawEventAnnotation = false; + for (const auto &packet : trace.packet()) { + if (packet.has_track_descriptor()) { + ++trackDescriptors; + continue; + } + const auto &ev = packet.track_event(); + switch (ev.type()) { + case perfetto::protos::TrackEvent::TYPE_SLICE_BEGIN: + ++sliceBegins; + break; + case perfetto::protos::TrackEvent::TYPE_INSTANT: + ++instants; + break; + case perfetto::protos::TrackEvent::TYPE_SLICE_END: + ++sliceEnds; + break; + default: + break; + } + for (const auto &ann : ev.debug_annotations()) { + if (ann.string_value() == "scope=2") { + sawScopeAnnotation = true; + } + if (ann.string_value() == "event=written") { + sawEventAnnotation = true; + } + } + } + EXPECT_EQ(trace.packet_size(), 10); + EXPECT_EQ(trackDescriptors, 3); // one per thread (main + 2 workers) + EXPECT_EQ(sliceBegins, 3); + EXPECT_EQ(instants, 1); + EXPECT_EQ(sliceEnds, 3); + EXPECT_TRUE(sawScopeAnnotation); + EXPECT_TRUE(sawEventAnnotation); EXPECT_EQ(std::filesystem::path(path).extension(), ".perfetto-trace"); EXPECT_EQ(std::filesystem::path(path).filename(), "calf_" + std::to_string(::getpid()) + ".perfetto-trace"); @@ -147,6 +186,9 @@ TEST(SyscallProtobufLoggerTest, RoutesPerfettoSystemCallsThroughConfiguredHandle SET_CALF_SYSCALL_HANDLER(recordingSyscall); ENABLE_LOGGER(); SyscallLogger::resetProtobufState(); + // Prior tests ran on the main thread and cached pid/tid; drop that so the routing below + // actually exercises the configured syscall handler. + SyscallLogger::resetPidTidCache(); { SyscallLoggingSuspender suspended; From 9d42296aeb96df48ac1f03b6e5169d93f1b300c9 Mon Sep 17 00:00:00 2001 From: Marco Edoardo Santimaria Date: Tue, 13 Oct 2026 10:24:10 +0200 Subject: [PATCH 2/3] Test increase cache size --- calf/SyscallLogger.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/calf/SyscallLogger.h b/calf/SyscallLogger.h index 9d47769..b2e709c 100644 --- a/calf/SyscallLogger.h +++ b/calf/SyscallLogger.h @@ -24,7 +24,7 @@ // disk in bulk when the buffer fills or the process exits. Tune up for even fewer syscalls on // heavy syscall traces; keep modest if many threads each allocate one. #ifndef CALF_LOG_BUFFER_CAPACITY -#define CALF_LOG_BUFFER_CAPACITY 65536 +#define CALF_LOG_BUFFER_CAPACITY 262144 #endif #ifdef CALF_LOG_FORMAT_PROTOBUF From bcee80c38e681eb687dbea4124a2a77421c371b1 Mon Sep 17 00:00:00 2001 From: Marco Edoardo Santimaria Date: Tue, 13 Oct 2026 15:45:48 +0200 Subject: [PATCH 3/3] ci-cd-fix --- .github/workflows/cpp-tests.yml | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/.github/workflows/cpp-tests.yml b/.github/workflows/cpp-tests.yml index 6e6304b..63341e5 100644 --- a/.github/workflows/cpp-tests.yml +++ b/.github/workflows/cpp-tests.yml @@ -19,17 +19,19 @@ jobs: matrix: build_type: [Debug, Release] compiler: - - gcc:9 - - gcc:10 - - gcc:11 - gcc:12 - gcc:13 - - silkeh/clang:13 - - silkeh/clang:14 + - gcc:14 + - gcc:15 + - gcc:16 - silkeh/clang:15 - silkeh/clang:16 - silkeh/clang:17 - silkeh/clang:18 + - silkeh/clang:19 + - silkeh/clang:20 + - silkeh/clang:21 + - silkeh/clang:22 container: image: ${{ matrix.compiler }}