[XRay][compiler-rt] Profiling Mode: Flush logs on exit

[dberris]

Summary

This change adds support for writing out profiles at program exit.

Depends on D48653.

[kpw]

Just one concern about exit handler being too aggressive if normal operation finalized and flushed.

compiler-rt/lib/xray/xray_profiling.cc

296–300

Isn't it an error to unconditionally finalize and flush without checking the state first?

342–343

Yeah. This is much better.

[dberris]

compiler-rt/lib/xray/xray_profiling.cc

296–300

Not in this situation. Consider that this code is running in the initialisation of the profiling mode -- this means that in the lifetime of a program this mode has been initialised once. Notice that we're calling the profiling-mode specific finalization and flushing implementations at program exit. The implementation of either of these functions are then performing the invariant checks independently.

[dberris]

Rebase

compiler-rt/lib/xray/xray_profile_collector.cc

 
 namespace {
 
 SpinMutex GlobalMutex;
 struct ThreadTrie {
   tid_t TId;
   FunctionCallTrie *Trie;
 };
-Vector<ThreadTrie> ThreadTries;
 
 struct ProfileBuffer {
   void *Data;
   size_t Size;
 };
-Vector<ProfileBuffer> ProfileBuffers;
 
 struct BlockHeader {
   u32 BlockSize;
   u32 BlockNum;
   u64 ThreadId;
 };
 
+// These need to be pointers that point to heap/internal-allocator-allocated
+// objects because these are accessed even at program exit.
+Vector<ThreadTrie> *ThreadTries = nullptr;
+Vector<ProfileBuffer> *ProfileBuffers = nullptr;
 FunctionCallTrie::Allocators *GlobalAllocators = nullptr;
 
 } // namespace
 
 void post(const FunctionCallTrie &T, tid_t TId) {
   static pthread_once_t Once = PTHREAD_ONCE_INIT;
   pthread_once(&Once, +[] {
     SpinMutexLock Lock(&GlobalMutex);
     GlobalAllocators = reinterpret_cast<FunctionCallTrie::Allocators *>(
         InternalAlloc(sizeof(FunctionCallTrie::Allocators)));
     new (GlobalAllocators) FunctionCallTrie::Allocators();
     *GlobalAllocators = FunctionCallTrie::InitAllocatorsCustom(
         profilingFlags()->global_allocator_max);
+    ThreadTries = reinterpret_cast<Vector<ThreadTrie> *>(
+        InternalAlloc(sizeof(Vector<ThreadTrie>)));
+    new (ThreadTries) Vector<ThreadTrie>();
+    ProfileBuffers = reinterpret_cast<Vector<ProfileBuffer> *>(
+        InternalAlloc(sizeof(Vector<ProfileBuffer>)));
+    new (ProfileBuffers) Vector<ProfileBuffer>();
   });
   DCHECK_NE(GlobalAllocators, nullptr);
+  DCHECK_NE(ThreadTries, nullptr);
+  DCHECK_NE(ProfileBuffers, nullptr);
 
   ThreadTrie *Item = nullptr;
   {
     SpinMutexLock Lock(&GlobalMutex);
     if (GlobalAllocators == nullptr)
       return;
 
-    Item = ThreadTries.PushBack();
+    Item = ThreadTries->PushBack();
     Item->TId = TId;
 
     // Here we're using the internal allocator instead of the managed allocator
     // because:
     //
     // 1) We're not using the segmented array data structure to host
     //    FunctionCallTrie objects. We're using a Vector (from sanitizer_common)
     //    which works like a std::vector<...> keeping elements contiguous in

 }
 
 } // namespace
 
 void serialize() {
   SpinMutexLock Lock(&GlobalMutex);
 
   // Clear out the global ProfileBuffers.
-  for (uptr I = 0; I < ProfileBuffers.Size(); ++I)
-    InternalFree(ProfileBuffers[I].Data);
-  ProfileBuffers.Reset();
+  for (uptr I = 0; I < ProfileBuffers->Size(); ++I)
+    InternalFree((*ProfileBuffers)[I].Data);
+  ProfileBuffers->Reset();
 
-  if (ThreadTries.Size() == 0)
+  if (ThreadTries->Size() == 0)
     return;
 
   // Then repopulate the global ProfileBuffers.
-  for (u32 I = 0; I < ThreadTries.Size(); ++I) {
+  for (u32 I = 0; I < ThreadTries->Size(); ++I) {
     using ProfileRecordAllocator = typename ProfileRecordArray::AllocatorType;
     ProfileRecordAllocator PRAlloc(profilingFlags()->global_allocator_max, 0);
     ProfileRecord::PathAllocator PathAlloc(
         profilingFlags()->global_allocator_max, 0);
     ProfileRecordArray ProfileRecords(PRAlloc);
 
     // First, we want to compute the amount of space we're going to need. We'll
     // use a local allocator and an __xray::Array<...> to store the intermediary
     // data, then compute the size as we're going along. Then we'll allocate the
     // contiguous space to contain the thread buffer data.
-    const auto &Trie = *ThreadTries[I].Trie;
+    const auto &Trie = *(*ThreadTries)[I].Trie;
     if (Trie.getRoots().empty())
       continue;
     populateRecords(ProfileRecords, PathAlloc, Trie);
     DCHECK(!Trie.getRoots().empty());
     DCHECK(!ProfileRecords.empty());
 
     // Go through each record, to compute the sizes.
     //
     // header size = block size (4 bytes)
     //   + block number (4 bytes)
     //   + thread id (8 bytes)
     // record size = path ids (4 bytes * number of ids + sentinel 4 bytes)
     //   + call count (8 bytes)
     //   + local time (8 bytes)
     //   + end of record (8 bytes)
     u32 CumulativeSizes = 0;
     for (const auto &Record : ProfileRecords)
       CumulativeSizes += 20 + (4 * Record.Path->size());
 
-    BlockHeader Header{16 + CumulativeSizes, I, ThreadTries[I].TId};
-    auto Buffer = ProfileBuffers.PushBack();
+    BlockHeader Header{16 + CumulativeSizes, I, (*ThreadTries)[I].TId};
+    auto Buffer = ProfileBuffers->PushBack();
     Buffer->Size = sizeof(Header) + CumulativeSizes;
     Buffer->Data = InternalAlloc(Buffer->Size, nullptr, 64);
     DCHECK_NE(Buffer->Data, nullptr);
     serializeRecords(Buffer, Header, ProfileRecords);
 
     // Now clean up the ProfileRecords array, one at a time.
     for (auto &Record : ProfileRecords) {
       Record.Path->~PathArray();
       InternalFree(Record.Path);
     }
   }
 }
 
 void reset() {
   SpinMutexLock Lock(&GlobalMutex);
+  if (ProfileBuffers != nullptr) {
     // Clear out the profile buffers that have been serialized.
-  for (uptr I = 0; I < ProfileBuffers.Size(); ++I)
-    InternalFree(ProfileBuffers[I].Data);
-  ProfileBuffers.Reset();
+    for (uptr I = 0; I < ProfileBuffers->Size(); ++I)
+      InternalFree((*ProfileBuffers)[I].Data);
+    ProfileBuffers->Reset();
+    InternalFree(ProfileBuffers);
+    ProfileBuffers = nullptr;
+  }
 
+  if (ThreadTries != nullptr) {
     // Clear out the function call tries per thread.
-  for (uptr I = 0; I < ThreadTries.Size(); ++I) {
-    auto &T = ThreadTries[I];
+    for (uptr I = 0; I < ThreadTries->Size(); ++I) {
+      auto &T = (*ThreadTries)[I];
       T.Trie->~FunctionCallTrie();
       InternalFree(T.Trie);
     }
-  ThreadTries.Reset();
+    ThreadTries->Reset();
+    InternalFree(ThreadTries);
+    ThreadTries = nullptr;
+  }
 
   // Reset the global allocators.
   if (GlobalAllocators != nullptr) {
     GlobalAllocators->~Allocators();
     InternalFree(GlobalAllocators);
     GlobalAllocators = nullptr;
   }
   GlobalAllocators = reinterpret_cast<FunctionCallTrie::Allocators *>(
       InternalAlloc(sizeof(FunctionCallTrie::Allocators)));
   new (GlobalAllocators) FunctionCallTrie::Allocators();
   *GlobalAllocators = FunctionCallTrie::InitAllocators();
+  ThreadTries = reinterpret_cast<Vector<ThreadTrie> *>(
+      InternalAlloc(sizeof(Vector<ThreadTrie>)));
+  new (ThreadTries) Vector<ThreadTrie>();
+  ProfileBuffers = reinterpret_cast<Vector<ProfileBuffer> *>(
+      InternalAlloc(sizeof(Vector<ProfileBuffer>)));
+  new (ProfileBuffers) Vector<ProfileBuffer>();
 }
 
 XRayBuffer nextBuffer(XRayBuffer B) {
   SpinMutexLock Lock(&GlobalMutex);
-  if (B.Data == nullptr && ProfileBuffers.Size())
-    return {ProfileBuffers[0].Data, ProfileBuffers[0].Size};
+
+  if (ProfileBuffers == nullptr || ProfileBuffers->Size() == 0)
+    return {nullptr, 0};
+
+  if (B.Data == nullptr)
+    return {(*ProfileBuffers)[0].Data, (*ProfileBuffers)[0].Size};
 
   BlockHeader Header;
   internal_memcpy(&Header, B.Data, sizeof(BlockHeader));
   auto NextBlock = Header.BlockNum + 1;
-  if (NextBlock < ProfileBuffers.Size())
-    return {ProfileBuffers[NextBlock].Data, ProfileBuffers[NextBlock].Size};
+  if (NextBlock < ProfileBuffers->Size())
+    return {(*ProfileBuffers)[NextBlock].Data,
+            (*ProfileBuffers)[NextBlock].Size};
   return {nullptr, 0};
 }
 
 } // namespace profileCollectorService
 } // namespace __xray

compiler-rt/lib/xray/xray_profiling.cc

if (!atomic_compare_exchange_strong(&ProfilerLogStatus, &CurrentStatus,
     if (Verbosity())
       ReportUnrecognizedFlags();
     *profilingFlags() = Flags;
   }
 
   // We need to reset the profile data collection implementation now.
   profileCollectorService::reset();
 
-  // We need to set up the at-thread-exit handler.
+  // We need to set up the exit handlers.
   static pthread_once_t Once = PTHREAD_ONCE_INIT;
   pthread_once(&Once, +[] {
     pthread_key_create(&ProfilingKey, +[](void *P) {
       // This is the thread-exit handler.
       auto &TLD = *reinterpret_cast<ProfilingData *>(P);
       if (TLD.Allocators == nullptr && TLD.FCT == nullptr)
         return;
 
       postCurrentThreadFCT(TLD);
     });
+
+    // We also need to set up an exit handler, so that we can get the profile
+    // information at exit time. We use the C API to do this, to not rely on C++
+    // ABI functions for registering exit handlers.
+    Atexit(+[] {
+      // Finalize and flush.
+      if (profilingFinalize() != XRAY_LOG_FINALIZED)
+        return;
+      if (profilingFlush() != XRAY_LOG_FLUSHED)
+        return;
+      if (Verbosity())
+        Report("XRay Profile flushed at exit.");
+    });
   });
 
   __xray_log_set_buffer_iterator(profileCollectorService::nextBuffer);
   __xray_set_handler(profilingHandleArg0);
   __xray_set_handler_arg1(profilingHandleArg1);
 
   atomic_store(&ProfilerLogStatus, XRayLogInitStatus::XRAY_LOG_INITIALIZED,
                memory_order_release);
bool profilingDynamicInitializer() XRAY_NEVER_INSTRUMENT {
 
   XRayLogImpl Impl{
       profilingLoggingInit,
       profilingFinalize,
       profilingHandleArg0,
       profilingFlush,
   };
   auto RegistrationResult = __xray_log_register_mode("xray-profiling", Impl);
-  if (RegistrationResult != XRayLogRegisterStatus::XRAY_REGISTRATION_OK &&
-      Verbosity())
+  if (RegistrationResult != XRayLogRegisterStatus::XRAY_REGISTRATION_OK) {
+    if (Verbosity())
       Report("Cannot register XRay Profiling mode to 'xray-profiling'; error = "
              "%d\n",
              RegistrationResult);
+    return false;
+  }
+
   if (!internal_strcmp(flags()->xray_mode, "xray-profiling"))
-    __xray_set_log_impl(Impl);
+    __xray_log_select_mode("xray_profiling");
   return true;
 }
 
 } // namespace __xray
 
 static auto UNUSED Unused = __xray::profilingDynamicInitializer();

compiler-rt/lib/xray/xray_profiling_flags.inc

 #endif
 
 XRAY_FLAG(uptr, per_thread_allocator_max, 2 << 20,
           "Maximum size of any single per-thread allocator.")
 XRAY_FLAG(uptr, global_allocator_max, 2 << 24,
           "Maximum size of the global allocator for profile storage.")
 XRAY_FLAG(uptr, stack_allocator_max, 2 << 24,
           "Maximum size of the traversal stack allocator.")
-XRAY_FLAG(int, grace_period_ms, 100,
+XRAY_FLAG(int, grace_period_ms, 1,
           "Profile collection will wait this much time in milliseconds before "
           "resetting the global state. This gives a chance to threads to "
           "notice that the profiler has been finalized and clean up.")
 XRAY_FLAG(bool, no_flush, false,
           "Set to true if we want the profiling implementation to not write "
           "out files.")

compiler-rt/test/xray/TestCases/Posix/profiling-multi-threaded.cc

 // Check that we can get a profile from a single-threaded application, on
 // demand through the XRay logging implementation API.
 //
 // FIXME: Make -fxray-modes=xray-profiling part of the default?
 // RUN: %clangxx_xray -std=c++11 %s -o %t -fxray-modes=xray-profiling
 // RUN: rm -f xray-log.profiling-multi-*
 // RUN: XRAY_OPTIONS=verbosity=1 \
 // RUN:     XRAY_PROFILING_OPTIONS=no_flush=1 %run %t
 // RUN: XRAY_OPTIONS=verbosity=1 %run %t
 // RUN: PROFILES=`ls xray-log.profiling-multi-* | wc -l`
-// RUN: [ $PROFILES -eq 1 ]
+// RUN: [ $PROFILES -ge 1 ]
 // RUN: rm -f xray-log.profiling-multi-*
 //
 // UNSUPPORTED: target-is-mips64,target-is-mips64el
 
 #include "xray/xray_interface.h"
 #include "xray/xray_log_interface.h"
 #include <cassert>
 #include <cstdio>

compiler-rt/test/xray/TestCases/Posix/profiling-single-threaded.cc

 // Check that we can get a profile from a single-threaded application, on
 // demand through the XRay logging implementation API.
 //
 // FIXME: Make -fxray-modes=xray-profiling part of the default?
 // RUN: %clangxx_xray -std=c++11 %s -o %t -fxray-modes=xray-profiling
 // RUN: rm -f xray-log.profiling-single-*
 // RUN: XRAY_OPTIONS=verbosity=1 \
 // RUN:     XRAY_PROFILING_OPTIONS=no_flush=true %run %t
 // RUN: XRAY_OPTIONS=verbosity=1 %run %t
 // RUN: PROFILES=`ls xray-log.profiling-single-* | wc -l`
-// RUN: [ $PROFILES -eq 2 ]
+// RUN: [ $PROFILES -ge 2 ]
 // RUN: rm -f xray-log.profiling-single-*
 //
 // UNSUPPORTED: target-is-mips64,target-is-mips64el
 
 #include "xray/xray_interface.h"
 #include "xray/xray_log_interface.h"
 #include <cassert>
 #include <cstdio>