[XRay][profiler] Part 5: Profiler File Writing

[dberris]

Summary

This is part of the larger XRay Profiling Mode effort.

This patch implements the profile writing mechanism, to allow profiles
collected through the profiler mode to be persisted to files.

Follow-on patches would allow us to load these profiles and start
converting/analysing them through the llvm-xray tool.

Depends on D44620.

[kpw]

LGTM, once the dependent changes get in.

compiler-rt/lib/xray/xray_profile_collector.cc

263 ↗

(On Diff #143677)

Is this just needing to rebase?

compiler-rt/lib/xray/xray_profiler.cc

132 ↗

(On Diff #143677)

I'd really like to see this written so that we can write somewhere other than files (in a follow up patch). Imho, we should build on an ostream so that this could be a network transport layer.

[dberris]

Rebase

compiler-rt/lib/xray/xray_profiling.cc

 //===-- xray_profiling.cc ---------------------------------------*- C++ -*-===//
 //
 //                     The LLVM Compiler Infrastructure
 //
 // This file is distributed under the University of Illinois Open Source
 // License. See LICENSE.TXT for details.
 //
 //===----------------------------------------------------------------------===//
 //
 // This file is a part of XRay, a dynamic runtime instrumentation system.
 //
 // This is the implementation of a profiling handler.
 //
 //===----------------------------------------------------------------------===//
 #include <memory>
+#include <time.h>
 
 #include "sanitizer_common/sanitizer_atomic.h"
 #include "sanitizer_common/sanitizer_flags.h"
 #include "xray/xray_interface.h"
 #include "xray/xray_log_interface.h"
 
 #include "xray_flags.h"
 #include "xray_profile_collector.h"
 #include "xray_profiling_flags.h"
 #include "xray_recursion_guard.h"
 #include "xray_tsc.h"
 #include "xray_utils.h"
 #include <pthread.h>
 
 namespace __xray {
 
 namespace {
 
+constexpr uptr XRayProfilingVersion = 0x20180424;
+
+struct XRayProfilingFileHeader {
+  const u64 MagicBytes = 0x7872617970726f66; // Identifier for XRay profiling
+                                             // files 'xrayprof' in hex.
+  const uptr Version = XRayProfilingVersion;
+  uptr Timestamp = 0; // System time in nanoseconds.
+  uptr PID = 0;       // Process ID.
+};
+
 atomic_sint32_t ProfilerLogFlushStatus = {
     XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING};
 
 atomic_sint32_t ProfilerLogStatus = {XRayLogInitStatus::XRAY_LOG_UNINITIALIZED};
 
 SpinMutex ProfilerOptionsMutex;
 
 struct alignas(64) ProfilingData {
#else
   return "";
 #endif
 }
 
 atomic_sint32_t ProfileFlushStatus = {
     XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING};
 
 XRayLogFlushStatus profilingFlush() XRAY_NEVER_INSTRUMENT {
-  // When flushing, all we really do is reset the global state, and only when
-  // the log has already been finalized.
   if (atomic_load(&ProfilerLogStatus, memory_order_acquire) !=
       XRayLogInitStatus::XRAY_LOG_FINALIZED) {
     if (Verbosity())
       Report("Not flushing profiles, profiling not been finalized.\n");
     return XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING;
   }
 
   s32 Result = XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING;
   if (!atomic_compare_exchange_strong(&ProfilerLogFlushStatus, &Result,
                                       XRayLogFlushStatus::XRAY_LOG_FLUSHING,
                                       memory_order_acq_rel)) {
     if (Verbosity())
       Report("Not flushing profiles, implementation still finalizing.\n");
   }
 
+  // At this point, we'll create the file that will contain the profile, but
+  // only if the options say so.
+  if (!profilingFlags()->no_flush) {
+    int Fd = -1;
+    Fd = getLogFD();
+    if (Fd == -1) {
+      if (__sanitizer::Verbosity())
+        Report(
+            "profiler: Failed to acquire a file descriptor, dropping data.\n");
+    } else {
+      XRayProfilingFileHeader Header;
+      Header.Timestamp = NanoTime();
+      Header.PID = internal_getpid();
+      retryingWriteAll(Fd, reinterpret_cast<const char *>(&Header),
+                       reinterpret_cast<const char *>(&Header) +
+                           sizeof(Header));
+
+      // Now for each of the threads, write out the profile data as we would see
+      // it in memory, verbatim.
+      XRayBuffer B = profileCollectorService::nextBuffer({nullptr, 0});
+      while (B.Data != nullptr && B.Size != 0) {
+        retryingWriteAll(Fd, reinterpret_cast<const char *>(B.Data),
+                         reinterpret_cast<const char *>(B.Data) + B.Size);
+        B = profileCollectorService::nextBuffer(B);
+      }
+
+      // Then we close out the file.
+      internal_close(Fd);
+    }
+  }
+
   profileCollectorService::reset();
 
   atomic_store(&ProfilerLogStatus, XRayLogFlushStatus::XRAY_LOG_FLUSHED,
                memory_order_release);
 
   return XRayLogFlushStatus::XRAY_LOG_FLUSHED;
 }
 
profilingLoggingInit(size_t BufferSize, size_t BufferMax, void *Options,
   }
 
   {
     SpinMutexLock Lock(&ProfilerOptionsMutex);
     FlagParser ConfigParser;
     auto *F = profilingFlags();
     F->setDefaults();
     registerProfilerFlags(&ConfigParser, F);
-    const char *ProfilerCompileFlags = profilingCompilerDefinedFlags();
-    ConfigParser.ParseString(ProfilerCompileFlags);
+    ConfigParser.ParseString(profilingCompilerDefinedFlags());
+    const char *Env = GetEnv("XRAY_PROFILING_OPTIONS");
+    if (Env == nullptr)
+      Env = "";
+    ConfigParser.ParseString(Env);
+
+    // Then parse the configuration string provided.
     ConfigParser.ParseString(static_cast<const char *>(Options));
     if (Verbosity())
       ReportUnrecognizedFlags();
   }
 
   // We need to reset the profile data collection implementation now.
   profileCollectorService::reset();
 
bool profilingDynamicInitializer() XRAY_NEVER_INSTRUMENT {
   // Set up the flag defaults from the static defaults and the
   // compiler-provided defaults.
   {
     SpinMutexLock Lock(&ProfilerOptionsMutex);
     auto *F = profilingFlags();
     F->setDefaults();
     FlagParser ProfilingParser;
     registerProfilerFlags(&ProfilingParser, F);
-    const char *ProfilerCompileFlags = profilingCompilerDefinedFlags();
-    ProfilingParser.ParseString(ProfilerCompileFlags);
+    ProfilingParser.ParseString(profilingCompilerDefinedFlags());
   }
 
   XRayLogImpl Impl{
       profilingLoggingInit,
       profilingFinalize,
       profilingHandleArg0,
       profilingFlush,
   };

compiler-rt/lib/xray/xray_profiling_flags.inc

 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,
           "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/lib/xray/xray_utils.h

 #include <utility>
 
 namespace __xray {
 
 // Default implementation of the reporting interface for sanitizer errors.
 void printToStdErr(const char *Buffer);
 
 // EINTR-safe write routine, provided a file descriptor and a character range.
-void retryingWriteAll(int Fd, char *Begin, char *End);
+void retryingWriteAll(int Fd, const char *Begin, const char *End);
 
 // Reads a long long value from a provided file.
 bool readValueFromFile(const char *Filename, long long *Value);
 
 // EINTR-safe read routine, providing a file descriptor and a character range.
 std::pair<ssize_t, bool> retryingReadSome(int Fd, char *Begin, char *End);
 
 // EINTR-safe open routine, uses flag-provided values for initialising a log
 // file.
 int getLogFD();
 
 } // namespace __xray
 
 #endif // XRAY_UTILS_H

compiler-rt/lib/xray/xray_utils.cc

 // This file is a part of XRay, a dynamic runtime instrumentation system.
 //
 //===----------------------------------------------------------------------===//
 #include "xray_utils.h"
 
 #include "sanitizer_common/sanitizer_common.h"
 #include "xray_defs.h"
 #include "xray_flags.h"
-#include <stdlib.h>
 #include <cstdio>
 #include <errno.h>
 #include <fcntl.h>
 #include <iterator>
+#include <stdlib.h>
 #include <sys/types.h>
 #include <tuple>
 #include <unistd.h>
 #include <utility>
 
 namespace __xray {
 
 void printToStdErr(const char *Buffer) XRAY_NEVER_INSTRUMENT {
   fprintf(stderr, "%s", Buffer);
 }
 
-void retryingWriteAll(int Fd, char *Begin, char *End) XRAY_NEVER_INSTRUMENT {
+void retryingWriteAll(int Fd, const char *Begin, const char *End) XRAY_NEVER_INSTRUMENT {
   if (Begin == End)
     return;
   auto TotalBytes = std::distance(Begin, End);
   while (auto Written = write(Fd, Begin, TotalBytes)) {
     if (Written < 0) {
       if (errno == EINTR)
         continue; // Try again.
       Report("Failed to write; errno = %d\n", errno);
if (Line[0] != '\0' && (*End == '\n' || *End == '\0')) {
     *Value = Tmp;
     Result = true;
   }
   return Result;
 }
 
 int getLogFD() XRAY_NEVER_INSTRUMENT {
   // Open a temporary file once for the log.
-  static char TmpFilename[256] = {};
-  static char TmpWildcardPattern[] = "XXXXXX";
-  auto Argv = GetArgv();
-  const char *Progname = Argv[0] == nullptr ? "(unknown)" : Argv[0];
+  char TmpFilename[256] = {};
+  char TmpWildcardPattern[] = "XXXXXX";
+  auto **Argv = GetArgv();
+  const char *Progname = !Argv ? "(unknown)" : Argv[0];
   const char *LastSlash = internal_strrchr(Progname, '/');
 
   if (LastSlash != nullptr)
     Progname = LastSlash + 1;
 
   const int HalfLength = sizeof(TmpFilename) / 2 - sizeof(TmpWildcardPattern);
   int NeededLength = internal_snprintf(
       TmpFilename, sizeof(TmpFilename), "%.*s%.*s.%s", HalfLength,

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: %run %t
+// RUN: rm xray-log.profiling-multi-* || true
+// 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: rm xray-log.profiling-multi-* || true
 //
 // UNSUPPORTED: target-is-mips64,target-is-mips64el
 
 #include "xray/xray_interface.h"
 #include "xray/xray_log_interface.h"
 #include <cassert>
 #include <cstdio>
 #include <string>
 #include <thread>
 
-#define XRAY_ALWAYS_INSTRUMENT [[clang::xray_always_instrument]]
-#define XRAY_NEVER_INSTRUMENT [[clang::xray_never_instrument]]
-
-XRAY_ALWAYS_INSTRUMENT void f2() { return; }
-XRAY_ALWAYS_INSTRUMENT void f1() { f2(); }
-XRAY_ALWAYS_INSTRUMENT void f0() { f1(); }
+[[clang::xray_always_instrument]] void f2() { return; }
+[[clang::xray_always_instrument]] void f1() { f2(); }
+[[clang::xray_always_instrument]] void f0() { f1(); }
 
 using namespace std;
 
 volatile int buffer_counter = 0;
 
-XRAY_NEVER_INSTRUMENT void process_buffer(const char *, XRayBuffer) {
+[[clang::xray_never_instrument]] void process_buffer(const char *, XRayBuffer) {
   // FIXME: Actually assert the contents of the buffer.
   ++buffer_counter;
 }
 
-XRAY_ALWAYS_INSTRUMENT int main(int, char **) {
+[[clang::xray_always_instrument]] int main(int, char **) {
   assert(__xray_log_select_mode("xray-profiling") ==
          XRayLogRegisterStatus::XRAY_REGISTRATION_OK);
   assert(__xray_log_get_current_mode() != nullptr);
   std::string current_mode = __xray_log_get_current_mode();
   assert(current_mode == "xray-profiling");
   assert(__xray_patch() == XRayPatchingStatus::SUCCESS);
   assert(__xray_log_init(0, 0, nullptr, 0) ==
          XRayLogInitStatus::XRAY_LOG_INITIALIZED);

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: %run %t
+// RUN: rm xray-log.profiling-single-* || true
+// 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: rm xray-log.profiling-single-* || true
 //
 // UNSUPPORTED: target-is-mips64,target-is-mips64el
 
 #include "xray/xray_interface.h"
 #include "xray/xray_log_interface.h"
 #include <cassert>
 #include <cstdio>
 #include <string>