[XRay][compiler-rt] FDR Mode: Allow multiple runs

[dberris]

Summary

Fix a bug in FDR mode which didn't allow for re-initialising the logging
in the same process. This change ensures that:

• When we flush the FDR mode logging, that the state of the logging implementation is XRAY_LOG_UNINITIALIZED.

• Fix up the thread-local initialisation to use aligned storage and pthread_getspecific as well as pthread_setspecific for the thread-specific data.

• Actually use the pointer provided to the thread-exit cleanup handling, instead of assuming that the thread has thread-local data associated with it, and reaching at thread-exit time.

In this change we also have an explicit test for two consecutive
sessions for FDR mode tracing, and ensuring both sessions succeed.

compiler-rt/trunk/lib/xray/xray_fdr_logging.cc

 // This file is a part of XRay, a dynamic runtime instrumentation system.
 //
 // Here we implement the Flight Data Recorder mode for XRay, where we use
 // compact structures to store records in memory as well as when writing out the
 // data to files.
 //
 //===----------------------------------------------------------------------===//
 #include "xray_fdr_logging.h"
-#include <pthread.h>
 #include <cassert>
 #include <errno.h>
 #include <limits>
 #include <memory>
+#include <pthread.h>
 #include <sys/syscall.h>
 #include <sys/time.h>
 #include <time.h>
 #include <unistd.h>
 
 #include "sanitizer_common/sanitizer_allocator_internal.h"
 #include "sanitizer_common/sanitizer_atomic.h"
 #include "sanitizer_common/sanitizer_common.h"
static_assert(std::is_trivially_destructible<ThreadLocalData>::value,
               "ThreadLocalData must be trivially destructible");
 
 static constexpr auto MetadataRecSize = sizeof(MetadataRecord);
 static constexpr auto FunctionRecSize = sizeof(FunctionRecord);
 
 // Use a global pthread key to identify thread-local data for logging.
 static pthread_key_t Key;
 
+// Global BufferQueue.
+static BufferQueue *BQ = nullptr;
+
+static atomic_sint32_t LogFlushStatus = {
+    XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING};
+
+static FDRLoggingOptions FDROptions;
+
+static SpinMutex FDROptionsMutex;
+
 // This function will initialize the thread-local data structure used by the FDR
 // logging implementation and return a reference to it. The implementation
 // details require a bit of care to maintain.
 //
 // First, some requirements on the implementation in general:
 //
 //   - XRay handlers should not call any memory allocation routines that may
 //     delegate to an instrumented implementation. This means functions like

 // non-trivial destructor, because the C++ runtime might call std::malloc(...)
 // to register calls to destructors. Deadlocks may arise when, for example, an
 // externally provided malloc implementation is XRay instrumented, and
 // initializing the thread-locals involves calling into malloc. A malloc
 // implementation that does global synchronization might be holding a lock for a
 // critical section, calling a function that might be XRay instrumented (and
 // thus in turn calling into malloc by virtue of registration of the
 // thread_local's destructor).
-static ThreadLocalData &getThreadLocalData() {
-  static_assert(alignof(ThreadLocalData) >= 64,
-                "ThreadLocalData must be cache line aligned.");
-  thread_local ThreadLocalData TLD;
-  thread_local bool UNUSED ThreadOnce = [] {
-    pthread_setspecific(Key, &TLD);
-    return false;
-  }();
-  return TLD;
+static ThreadLocalData &getThreadLocalData() {
+  thread_local typename std::aligned_storage<
+      sizeof(ThreadLocalData), alignof(ThreadLocalData)>::type TLDStorage{};
+
+  if (pthread_getspecific(Key) == NULL) {
+    new (reinterpret_cast<ThreadLocalData *>(&TLDStorage)) ThreadLocalData{};
+    pthread_setspecific(Key, &TLDStorage);
+  }
+
+  return *reinterpret_cast<ThreadLocalData *>(&TLDStorage);
 }
 
 static void writeNewBufferPreamble(tid_t Tid, timespec TS,
                                    pid_t Pid) XRAY_NEVER_INSTRUMENT {
   static constexpr int InitRecordsCount = 3;
   auto &TLD = getThreadLocalData();
   MetadataRecord Metadata[InitRecordsCount];
   {
static bool prepareBuffer(uint64_t TSC, unsigned char CPU,
                           size_t MaxSize) XRAY_NEVER_INSTRUMENT {
   auto &TLD = getThreadLocalData();
   char *BufferStart = static_cast<char *>(TLD.Buffer.Data);
   if ((TLD.RecordPtr + MaxSize) > (BufferStart + TLD.Buffer.Size)) {
     if (!releaseThreadLocalBuffer(*TLD.BQ))
       return false;
     auto EC = TLD.BQ->getBuffer(TLD.Buffer);
     if (EC != BufferQueue::ErrorCode::Ok) {
-      Report("Failed to acquire a buffer; error=%s\n",
+      Report("Failed to prepare a buffer; error = '%s'\n",
              BufferQueue::getErrorString(EC));
       return false;
     }
     setupNewBuffer(wall_clock_reader);
 
     // Always write the CPU metadata as the first record in the buffer.
     writeNewCPUIdMetadata(CPU, TSC);
   }
isLogInitializedAndReady(BufferQueue *LBQ, uint64_t TSC, unsigned char CPU,
   }
 
   if (TLD.Buffer.Data == nullptr) {
     auto EC = LBQ->getBuffer(TLD.Buffer);
     if (EC != BufferQueue::ErrorCode::Ok) {
       auto LS = atomic_load(&LoggingStatus, memory_order_acquire);
       if (LS != XRayLogInitStatus::XRAY_LOG_FINALIZING &&
           LS != XRayLogInitStatus::XRAY_LOG_FINALIZED)
-        Report("Failed to acquire a buffer; error=%s\n",
+        Report("Failed to acquire a buffer; error = '%s'\n",
                BufferQueue::getErrorString(EC));
       return false;
     }
 
     setupNewBuffer(wall_clock_reader);
 
     // Always write the CPU metadata as the first record in the buffer.
     writeNewCPUIdMetadata(CPU, TSC);

 /// function entry, exit and tail exit points with a time and will create
 /// TSCWrap, NewCPUId and Function records as necessary. The writer might
 /// walk backward through its buffer and erase trivial functions to avoid
 /// polluting the log and may use the buffer queue to obtain or release a
 /// buffer.
 static void processFunctionHook(int32_t FuncId, XRayEntryType Entry,
                                 uint64_t TSC, unsigned char CPU, uint64_t Arg1,
                                 int (*wall_clock_reader)(clockid_t,
-                                                         struct timespec *),
-                                BufferQueue *BQ) XRAY_NEVER_INSTRUMENT {
+                                                         struct timespec *))
+    XRAY_NEVER_INSTRUMENT {
   __asm volatile("# LLVM-MCA-BEGIN processFunctionHook");
   // Prevent signal handler recursion, so in case we're already in a log writing
   // mode and the signal handler comes in (and is also instrumented) then we
   // don't want to be clobbering potentially partial writes already happening in
   // the thread. We use a simple thread_local latch to only allow one on-going
   // handleArg0 to happen at any given time.
   RecursionGuard Guard{Running};
   if (!Guard) {
     DCHECK(atomic_load_relaxed(&Running) && "RecursionGuard is buggy!");
     return;
   }
 
   auto &TLD = getThreadLocalData();
 
-  // In case the reference has been cleaned up before, we make sure we
-  // initialize it to the provided BufferQueue.
   if (TLD.BQ == nullptr)
     TLD.BQ = BQ;
 
   if (!isLogInitializedAndReady(TLD.BQ, TSC, CPU, wall_clock_reader))
     return;
 
   // Before we go setting up writing new function entries, we need to be really
   // careful about the pointer math we're doing. This means we need to ensure
if (Entry == XRayEntryType::LOG_ARGS_ENTRY)
     writeCallArgumentMetadata(Arg1);
 
   // If we've exhausted the buffer by this time, we then release the buffer to
   // make sure that other threads may start using this buffer.
   endBufferIfFull();
   __asm volatile("# LLVM-MCA-END");
 }
 
-// Global BufferQueue.
-BufferQueue *BQ = nullptr;
-
-atomic_sint32_t LogFlushStatus = {XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING};
-
-FDRLoggingOptions FDROptions;
-
-SpinMutex FDROptionsMutex;
-
 static XRayFileHeader &fdrCommonHeaderInfo() {
   static std::aligned_storage<sizeof(XRayFileHeader)>::type HStorage;
   static pthread_once_t OnceInit = PTHREAD_ONCE_INIT;
   static bool TSCSupported = true;
   static uint64_t CycleFrequency = NanosecondsPerSecond;
   pthread_once(&OnceInit, +[] {
     XRayFileHeader &H = reinterpret_cast<XRayFileHeader &>(HStorage);
     // Version 2 of the log writes the extents of the buffer, instead of
XRayLogFlushStatus fdrLoggingFlush() XRAY_NEVER_INSTRUMENT {
   // We wait a number of milliseconds to allow threads to see that we've
   // finalised before attempting to flush the log.
   SleepForMillis(fdrFlags()->grace_period_ms);
 
   // At this point, we're going to uninstall the iterator implementation, before
   // we decide to do anything further with the global buffer queue.
   __xray_log_remove_buffer_iterator();
 
-  if (fdrFlags()->no_file_flush) {
-    if (Verbosity())
-      Report("XRay FDR: Not flushing to file, 'no_file_flush=true'.\n");
+  // Once flushed, we should set the global status of the logging implementation
+  // to "uninitialized" to allow for FDR-logging multiple runs.
+  auto ResetToUnitialized = at_scope_exit([] {
+    atomic_store(&LoggingStatus, XRayLogInitStatus::XRAY_LOG_UNINITIALIZED,
+                 memory_order_release);
+  });
 
-    // Clean up the buffer queue, and do not bother writing out the files!
+  auto CleanupBuffers = at_scope_exit([] {
+    if (BQ != nullptr) {
+      auto &TLD = getThreadLocalData();
+      if (TLD.RecordPtr != nullptr && TLD.BQ != nullptr)
+        releaseThreadLocalBuffer(*TLD.BQ);
       BQ->~BufferQueue();
       InternalFree(BQ);
       BQ = nullptr;
+    }
+  });
+
+  if (fdrFlags()->no_file_flush) {
+    if (Verbosity())
+      Report("XRay FDR: Not flushing to file, 'no_file_flush=true'.\n");
 
     atomic_store(&LogFlushStatus, XRayLogFlushStatus::XRAY_LOG_FLUSHED,
                  memory_order_release);
     return XRayLogFlushStatus::XRAY_LOG_FLUSHED;
   }
 
   // We write out the file in the following format:
   //
if (TSCSupported) {
     Result.TSC = TS.tv_sec * __xray::NanosecondsPerSecond + TS.tv_nsec;
   }
   return Result;
 }
 
 void fdrLoggingHandleArg0(int32_t FuncId,
                           XRayEntryType Entry) XRAY_NEVER_INSTRUMENT {
   auto TC = getTimestamp();
-  processFunctionHook(FuncId, Entry, TC.TSC, TC.CPU, 0, clock_gettime, BQ);
+  processFunctionHook(FuncId, Entry, TC.TSC, TC.CPU, 0, clock_gettime);
 }
 
 void fdrLoggingHandleArg1(int32_t FuncId, XRayEntryType Entry,
                           uint64_t Arg) XRAY_NEVER_INSTRUMENT {
   auto TC = getTimestamp();
-  processFunctionHook(FuncId, Entry, TC.TSC, TC.CPU, Arg, clock_gettime, BQ);
+  processFunctionHook(FuncId, Entry, TC.TSC, TC.CPU, Arg, clock_gettime);
 }
 
 void fdrLoggingHandleCustomEvent(void *Event,
                                  std::size_t EventSize) XRAY_NEVER_INSTRUMENT {
   auto TC = getTimestamp();
   auto &TSC = TC.TSC;
   auto &CPU = TC.CPU;
   RecursionGuard Guard{Running};
XRayLogInitStatus fdrLoggingInit(size_t BufferSize, size_t BufferMax,
   }
 
   static pthread_once_t OnceInit = PTHREAD_ONCE_INIT;
   pthread_once(&OnceInit, +[] {
     atomic_store(&TicksPerSec,
                  probeRequiredCPUFeatures() ? getTSCFrequency()
                                             : __xray::NanosecondsPerSecond,
                  memory_order_release);
-    pthread_key_create(&Key, +[](void *) {
-      auto &TLD = getThreadLocalData();
+    pthread_key_create(&Key, +[](void *TLDPtr) {
+      if (TLDPtr == nullptr)
+        return;
+      auto &TLD = *reinterpret_cast<ThreadLocalData *>(TLDPtr);
       if (TLD.BQ == nullptr)
         return;
       auto EC = TLD.BQ->releaseBuffer(TLD.Buffer);
       if (EC != BufferQueue::ErrorCode::Ok)
         Report("At thread exit, failed to release buffer at %p; error=%s\n",
                TLD.Buffer.Data, BufferQueue::getErrorString(EC));
     });
   });

compiler-rt/trunk/test/xray/TestCases/Posix/fdr-mode-multiple.cc

+// RUN: %clangxx_xray -g -std=c++11 %s -o %t -fxray-modes=xray-fdr
+// RUN: rm -f fdr-inmemory-test-*
+// RUN: XRAY_OPTIONS="patch_premain=false xray_logfile_base=fdr-inmemory-test- \
+// RUN:     verbosity=1" \
+// RUN: XRAY_FDR_OPTIONS="no_file_flush=true func_duration_threshold_us=0" \
+// RUN:     %run %t 2>&1 | FileCheck %s
+// RUN: FILES=`find %T -name 'fdr-inmemory-test-*' | wc -l`
+// RUN: [ $FILES -eq 0 ]
+// RUN: rm -f fdr-inmemory-test-*
+//
+// REQUIRES: x86_64-target-arch
+// REQUIRES: built-in-llvm-tree
+
+#include "xray/xray_log_interface.h"
+#include <cassert>
+#include <iostream>
+
+uint64_t var = 0;
+uint64_t buffers = 0;
+[[clang::xray_always_instrument]] void __attribute__((noinline)) f() { ++var; }
+
+int main(int argc, char *argv[]) {
+  assert(__xray_log_select_mode("xray-fdr") ==
+         XRayLogRegisterStatus::XRAY_REGISTRATION_OK);
+  auto status = __xray_log_init_mode(
+      "xray-fdr",
+      "buffer_size=4096:buffer_max=10:func_duration_threshold_us=0");
+  assert(status == XRayLogInitStatus::XRAY_LOG_INITIALIZED);
+  __xray_patch();
+
+  // Create enough entries.
+  for (int i = 0; i != 1 << 20; ++i) {
+    f();
+  }
+
+  // Then we want to verify that we're getting 10 buffers outside of the initial
+  // header.
+  auto finalize_status = __xray_log_finalize();
+  assert(finalize_status == XRayLogInitStatus::XRAY_LOG_FINALIZED);
+  auto process_status =
+      __xray_log_process_buffers([](const char *, XRayBuffer) { ++buffers; });
+  std::cout << "buffers = " << buffers << std::endl;
+  assert(process_status == XRayLogFlushStatus::XRAY_LOG_FLUSHED);
+  auto flush_status = __xray_log_flushLog();
+  assert(flush_status == XRayLogFlushStatus::XRAY_LOG_FLUSHED);
+  // We expect 11 buffers because 1 header buffer + 10 actual FDR buffers.
+  // CHECK: Buffers = 11
+  std::cout << "Buffers = " << buffers << std::endl;
+
+  // In this test we ensure that we can restart the cycle after the flush.
+  status = __xray_log_init_mode(
+      "xray-fdr",
+      "buffer_size=4096:buffer_max=10:func_duration_threshold_us=0");
+  assert(status == XRayLogInitStatus::XRAY_LOG_INITIALIZED);
+  __xray_patch();
+
+  // Create enough entries.
+  for (int i = 0; i != 1 << 20; ++i) {
+    f();
+  }
+
+  // Then we want to verify that we're getting 10 buffers outside of the initial
+  // header.
+  finalize_status = __xray_log_finalize();
+  assert(finalize_status == XRayLogInitStatus::XRAY_LOG_FINALIZED);
+  process_status =
+      __xray_log_process_buffers([](const char *, XRayBuffer) { ++buffers; });
+  std::cout << "buffers = " << buffers << std::endl;
+  assert(process_status == XRayLogFlushStatus::XRAY_LOG_FLUSHED);
+  flush_status = __xray_log_flushLog();
+  assert(flush_status == XRayLogFlushStatus::XRAY_LOG_FLUSHED);
+  // We expect 22 buffers because 1 header buffer + 10 actual FDR buffers, plus
+  // the number of buffers we got from the previous run (also 11).
+  // CHECK: Buffers = 22
+  std::cout << "Buffers = " << buffers << std::endl;
+}