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

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.

Reviewers: echristo, kpw, pelikan

Reviewed By: kpw

Subscribers: llvm-commits

Differential Revision: https://reviews.llvm.org/D45998

llvm-svn: 334472

compiler-rt/lib/xray/xray_profiling.cc

@@ -13,6 +13,7 @@
 //
 //===----------------------------------------------------------------------===//
 #include <memory>
+#include <time.h>
 
 #include "sanitizer_common/sanitizer_atomic.h"
 #include "sanitizer_common/sanitizer_flags.h"
@@ -31,6 +32,16 @@ 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};
 
@@ -89,8 +100,6 @@ 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())
@@ -106,6 +115,37 @@ XRayLogFlushStatus profilingFlush() XRAY_NEVER_INSTRUMENT {
       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,
@@ -221,8 +261,13 @@ profilingLoggingInit(size_t BufferSize, size_t BufferMax, void *Options,
     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();
@@ -265,8 +310,7 @@ bool profilingDynamicInitializer() XRAY_NEVER_INSTRUMENT {
     F->setDefaults();
     FlagParser ProfilingParser;
     registerProfilerFlags(&ProfilingParser, F);
-    const char *ProfilerCompileFlags = profilingCompilerDefinedFlags();
-    ProfilingParser.ParseString(ProfilerCompileFlags);
+    ProfilingParser.ParseString(profilingCompilerDefinedFlags());
   }
 
   XRayLogImpl Impl{

compiler-rt/lib/xray/xray_profiling_flags.inc

@@ -24,3 +24,6 @@ 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/test/xray/TestCases/Posix/profiling-multi-threaded.cc

@@ -3,7 +3,13 @@
 //
 // 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
 
@@ -14,23 +20,20 @@
 #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);

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

@@ -3,7 +3,13 @@
 //
 // 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