Performance improvement of syscall logger

.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 }}

calf/SyscallLogger.h

@@ -10,6 +10,7 @@
 #include <cstdlib>
 #include <cstring>
 #include <fcntl.h>
+#include <pthread.h>
 #include <string>
 #include <sys/file.h>
 #include <sys/syscall.h>
@@ -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 262144
+#endif
+
 #ifdef CALF_LOG_FORMAT_PROTOBUF
 #define CALF_SYSCALL_LOGGER_TYPE PerfettoSyscallLogger
 #else
@@ -34,6 +42,67 @@ struct CALF_SYSCALL_LOGGER_TYPE : CalfLogBase<CALF_SYSCALL_LOGGER_TYPE> {
     inline static std::atomic<int> 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<std::size_t>(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<CALF_SYSCALL_LOGGER_TYPE> {
     }
 
 #ifdef CALF_LOG_FORMAT_PROTOBUF
-    static pid_t processId() { return static_cast<pid_t>(calf_syscall(SYS_getpid)); }
+    static pid_t processId() {
+        registerLifecycleHandlers();
+        if (cachedPid != 0) {
+            return cachedPid;
+        }
+        cachedPid = static_cast<pid_t>(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,32 +161,73 @@ struct CALF_SYSCALL_LOGGER_TYPE : CalfLogBase<CALF_SYSCALL_LOGGER_TYPE> {
     }
 
     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<std::size_t>(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<std::size_t>(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<size_t>(len - written));
+            const long result =
+                calf_syscall(SYS_write, fileFD, buf + written, static_cast<size_t>(len - written));
             if (result <= 0) {
-#ifdef CALF_LOG_FORMAT_PROTOBUF
-                calf_syscall(SYS_flock, fileFD, LOCK_UN);
-#endif
                 return;
             }
             written += static_cast<int>(result);
         }
-#ifdef CALF_LOG_FORMAT_PROTOBUF
-        calf_syscall(SYS_flock, fileFD, LOCK_UN);
 #endif
     }
 
     static void rawWriteStr(const char *buf) {
         rawWriteBytes(buf, static_cast<int>(::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<CALF_SYSCALL_LOGGER_TYPE> {
 
     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

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<char>(input)),
                            std::istreambuf_iterator<char>());
     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;