[XRay][compiler-rt] Add an end-to-end test for FDR Logging

[dberris]

Summary

This change exercises the end-to-end functionality defined in the FDR
logging implementation. We also prepare for being able to run traces
generated by the FDR logging implementation from being analysed with the
llvm-xray command that comes with the LLVM distribution.

This also unblocks D31385, D31384, and D31345.

[kpw]

Thanks for the quick fix and for figuring out the lit configuration.

lib/xray/xray_fdr_logging.cc

65 ↗

(On Diff #93337)

Cool. I didn't grok the proper use of the void * args in xray_log_interface.h or how to switch on fdr via flags and just use the top level interface.

lib/xray/xray_utils.cc

96 ↗

(On Diff #93337)

This comment dangles now. There may still be a fix, necessary somewhere for how to configure Report, but the FIXME shouldn't be here.

test/xray/TestCases/Linux/fdr-mode.cc

3 ↗

(On Diff #93337)

I suspect we'll lose the exit code due to unix pipes returning the final commands exit code.

If the command returns a TRACE prefix as expected, then crashes, we want a failure.
If the shell that runs these is guaranteed to be bash, then the pipefail builtin option could help.

25–27 ↗

(On Diff #93337)

This is never called AFAICT.

51 ↗

(On Diff #93337)

Might as well lose this. It's not CHECKED.

[kpw]

LGTM with the spruce up specified.

[dberris]

• fixup: address review comments

test/xray/TestCases/Linux/fdr-mode.cc

3 ↗

(On Diff #93337)

Yes, this is currently not doing anything (notice that it's a FIXME as opposed to a RUN) :)

As soon as we fix the writing of the buffer sizes in the log, we'll be ready to turn this on.

compiler-rt/trunk/include/CMakeLists.txt

 set(SANITIZER_HEADERS
   sanitizer/allocator_interface.h
   sanitizer/asan_interface.h
   sanitizer/common_interface_defs.h
   sanitizer/coverage_interface.h
   sanitizer/dfsan_interface.h
   sanitizer/esan_interface.h
   sanitizer/linux_syscall_hooks.h
   sanitizer/lsan_interface.h
   sanitizer/msan_interface.h
   sanitizer/tsan_interface.h
   sanitizer/tsan_interface_atomic.h)
 
 set(XRAY_HEADERS
-  xray/xray_interface.h)
+  xray/xray_interface.h
+  xray/xray_log_interface.h)
 
 set(COMPILER_RT_HEADERS
   ${SANITIZER_HEADERS}
   ${XRAY_HEADERS})
 
 set(output_dir ${COMPILER_RT_OUTPUT_DIR}/include)
 
 # Copy compiler-rt headers to the build tree.

compiler-rt/trunk/include/xray/xray_log_interface.h

 void __xray_set_log_impl(XRayLogImpl Impl);
 XRayLogInitStatus __xray_log_init(size_t BufferSize, size_t MaxBuffers,
                                   void *Args, size_t ArgsSize);
 XRayLogInitStatus __xray_log_finalize();
 XRayLogFlushStatus __xray_log_flushLog();
 
 } // extern "C"
 
+namespace __xray {
+// Options used by the LLVM XRay FDR implementation.
+struct FDRLoggingOptions {
+  bool ReportErrors = false;
+  int Fd = -1;
+};
+
+} // namespace __xray
+
 #endif // XRAY_XRAY_LOG_INTERFACE_H

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

 //
 // The XRay whitepaper describes a mode of operation for function call trace
 // logging that involves writing small records into an in-memory circular
 // buffer, that then gets logged to disk on demand. To do this efficiently and
 // capture as much data as we can, we use smaller records compared to the
 // default mode of always writing fixed-size records.
 
 namespace __xray {
-
-// Options used by the FDR implementation.
-struct FDRLoggingOptions {
-  bool ReportErrors = false;
-  int Fd = -1;
-};
-
-// Flight Data Recorder mode implementation interfaces.
 XRayLogInitStatus fdrLoggingInit(size_t BufferSize, size_t BufferMax,
                                  void *Options, size_t OptionsSize);
 XRayLogInitStatus fdrLoggingFinalize();
 void fdrLoggingHandleArg0(int32_t FuncId, XRayEntryType Entry);
 XRayLogFlushStatus fdrLoggingFlush();
 XRayLogInitStatus fdrLoggingReset();
 
 } // namespace __xray
 
 #endif // XRAY_XRAY_FDR_LOGGING_H

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

 __sanitizer::atomic_sint32_t LogFlushStatus = {
     XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING};
 
 std::unique_ptr<FDRLoggingOptions> FDROptions;
 
 XRayLogInitStatus fdrLoggingInit(std::size_t BufferSize, std::size_t BufferMax,
                                  void *Options,
                                  size_t OptionsSize) XRAY_NEVER_INSTRUMENT {
-  assert(OptionsSize == sizeof(FDRLoggingOptions));
+  if (OptionsSize != sizeof(FDRLoggingOptions))
+    return static_cast<XRayLogInitStatus>(__sanitizer::atomic_load(
+        &LoggingStatus, __sanitizer::memory_order_acquire));
   s32 CurrentStatus = XRayLogInitStatus::XRAY_LOG_UNINITIALIZED;
-  if (__sanitizer::atomic_compare_exchange_strong(
+  if (!__sanitizer::atomic_compare_exchange_strong(
           &LoggingStatus, &CurrentStatus,
           XRayLogInitStatus::XRAY_LOG_INITIALIZING,
           __sanitizer::memory_order_release))
     return static_cast<XRayLogInitStatus>(CurrentStatus);
 
   FDROptions.reset(new FDRLoggingOptions());
-  *FDROptions = *reinterpret_cast<FDRLoggingOptions *>(Options);
-  if (FDROptions->ReportErrors)
-    SetPrintfAndReportCallback(printToStdErr);
-
+  memcpy(FDROptions.get(), Options, OptionsSize);
   bool Success = false;
   BQ = std::make_shared<BufferQueue>(BufferSize, BufferMax, Success);
   if (!Success) {
     Report("BufferQueue init failed.\n");
     return XRayLogInitStatus::XRAY_LOG_UNINITIALIZED;
   }
 
   // Install the actual handleArg0 handler after initialising the buffers.
   __xray_set_handler(fdrLoggingHandleArg0);
 
   __sanitizer::atomic_store(&LoggingStatus,
                             XRayLogInitStatus::XRAY_LOG_INITIALIZED,
                             __sanitizer::memory_order_release);
+  Report("XRay FDR init successful.\n");
   return XRayLogInitStatus::XRAY_LOG_INITIALIZED;
 }
 
 // Must finalize before flushing.
 XRayLogFlushStatus fdrLoggingFlush() XRAY_NEVER_INSTRUMENT {
   if (__sanitizer::atomic_load(&LoggingStatus,
                                __sanitizer::memory_order_acquire) !=
       XRayLogInitStatus::XRAY_LOG_FINALIZED)
     return XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING;
 
   s32 Result = XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING;
-  if (__sanitizer::atomic_compare_exchange_strong(
+  if (!__sanitizer::atomic_compare_exchange_strong(
           &LogFlushStatus, &Result, XRayLogFlushStatus::XRAY_LOG_FLUSHING,
           __sanitizer::memory_order_release))
     return static_cast<XRayLogFlushStatus>(Result);
 
   // Make a copy of the BufferQueue pointer to prevent other threads that may be
   // resetting it from blowing away the queue prematurely while we're dealing
   // with it.
   auto LocalBQ = BQ;
XRayLogFlushStatus fdrLoggingFlush() XRAY_NEVER_INSTRUMENT {
   __sanitizer::atomic_store(&LogFlushStatus,
                             XRayLogFlushStatus::XRAY_LOG_FLUSHED,
                             __sanitizer::memory_order_release);
   return XRayLogFlushStatus::XRAY_LOG_FLUSHED;
 }
 
 XRayLogInitStatus fdrLoggingFinalize() XRAY_NEVER_INSTRUMENT {
   s32 CurrentStatus = XRayLogInitStatus::XRAY_LOG_INITIALIZED;
-  if (__sanitizer::atomic_compare_exchange_strong(
+  if (!__sanitizer::atomic_compare_exchange_strong(
           &LoggingStatus, &CurrentStatus,
           XRayLogInitStatus::XRAY_LOG_FINALIZING,
           __sanitizer::memory_order_release))
     return static_cast<XRayLogInitStatus>(CurrentStatus);
 
   // Do special things to make the log finalize itself, and not allow any more
   // operations to be performed until re-initialized.
   BQ->finalize();
if (__sanitizer::atomic_compare_exchange_strong(
           XRayLogInitStatus::XRAY_LOG_INITIALIZED,
           __sanitizer::memory_order_release))
     return static_cast<XRayLogInitStatus>(CurrentStatus);
 
   // Release the in-memory buffer queue.
   BQ.reset();
 
   // Spin until the flushing status is flushed.
-  s32 CurrentFlushingStatus =
-      XRayLogFlushStatus::XRAY_LOG_FLUSHED;
+  s32 CurrentFlushingStatus = XRayLogFlushStatus::XRAY_LOG_FLUSHED;
   while (__sanitizer::atomic_compare_exchange_weak(
       &LogFlushStatus, &CurrentFlushingStatus,
       XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING,
       __sanitizer::memory_order_release)) {
     if (CurrentFlushingStatus == XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING)
       break;
     CurrentFlushingStatus = XRayLogFlushStatus::XRAY_LOG_FLUSHED;
   }

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

if (Impl.log_init == nullptr || Impl.log_finalize == nullptr ||
     return;
   }
 
   __sanitizer::SpinMutexLock Guard(&XRayImplMutex);
   GlobalXRayImpl.reset(new XRayLogImpl);
   *GlobalXRayImpl = Impl;
 }
 
-XRayLogInitStatus __xray_init(size_t BufferSize, size_t MaxBuffers, void *Args,
+XRayLogInitStatus __xray_log_init(size_t BufferSize, size_t MaxBuffers,
+                                  void *Args,
                                   size_t ArgsSize) XRAY_NEVER_INSTRUMENT {
   __sanitizer::SpinMutexLock Guard(&XRayImplMutex);
   if (!GlobalXRayImpl)
     return XRayLogInitStatus::XRAY_LOG_UNINITIALIZED;
   return GlobalXRayImpl->log_init(BufferSize, MaxBuffers, Args, ArgsSize);
 }
 
 XRayLogInitStatus __xray_log_finalize() XRAY_NEVER_INSTRUMENT {
   __sanitizer::SpinMutexLock Guard(&XRayImplMutex);

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

bool readValueFromFile(const char *Filename,
   if (Line[0] != '\0' && (*End == '\n' || *End == '\0')) {
     *Value = Tmp;
     Result = true;
   }
   return Result;
 }
 
 int getLogFD() XRAY_NEVER_INSTRUMENT {
-  // FIXME: Figure out how to make this less stderr-dependent.
-  SetPrintfAndReportCallback(printToStdErr);
   // 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];
   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,
       flags()->xray_logfile_base, HalfLength, Progname, TmpWildcardPattern);
   if (NeededLength > int(sizeof(TmpFilename))) {
     Report("XRay log file name too long (%d): %s\n", NeededLength, TmpFilename);
     return -1;
   }
   int Fd = mkstemp(TmpFilename);
   if (Fd == -1) {
     Report("XRay: Failed opening temporary file '%s'; not logging events.\n",
            TmpFilename);
     return -1;
   }
-  if (Verbosity())
-    fprintf(stderr, "XRay: Log file in '%s'\n", TmpFilename);
+  Report("XRay: Log file in '%s'\n", TmpFilename);
 
   return Fd;
 }
 
 } // namespace __xray

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

+// RUN: %clangxx_xray -std=c++11 %s -o %t
+// RUN: XRAY_OPTIONS="patch_premain=false xray_naive_log=false xray_logfile_base=fdr-logging-test- xray_fdr_log=true verbosity=1" %run %t 2>&1 | FileCheck %s
+// FIXME: %llvm_xray convert -instr_map=%t "`ls fdr-logging-test-* | head -1`" | FileCheck %s --check-prefix TRACE
+// RUN: rm fdr-logging-test-*
+
+#include "xray/xray_log_interface.h"
+#include <cassert>
+#include <chrono>
+#include <cstdio>
+#include <iostream>
+#include <stdlib.h>
+#include <thread>
+#include <time.h>
+
+constexpr auto kBufferSize = 16384;
+constexpr auto kBufferMax = 10;
+
+thread_local uint64_t var = 0;
+[[clang::xray_always_instrument]] void __attribute__((noinline)) fC() { ++var; }
+
+[[clang::xray_always_instrument]] void __attribute__((noinline)) fB() { fC(); }
+
+[[clang::xray_always_instrument]] void __attribute__((noinline)) fA() { fB(); }
+
+int main(int argc, char *argv[]) {
+  using namespace __xray;
+  FDRLoggingOptions Options;
+  std::cout << "Logging before init." << std::endl;
+  // CHECK: Logging before init.
+  auto status = __xray_log_init(kBufferSize, kBufferMax, &Options,
+                                sizeof(FDRLoggingOptions));
+  assert(status == XRayLogInitStatus::XRAY_LOG_INITIALIZED);
+  std::cout << "Init status " << status << std::endl;
+  // CHECK: Init status {{.*}}
+  std::cout << "Patching..." << std::endl;
+  // CHECK: Patching...
+  __xray_patch();
+  fA();
+  fC();
+  fB();
+  fA();
+  fC();
+  std::thread other_thread([]() {
+    fC();
+    fB();
+    fA();
+  });
+  other_thread.join();
+  std::cout << "Joined" << std::endl;
+  // CHECK: Joined
+  std::cout << "Finalize status " << __xray_log_finalize() << std::endl;
+  // CHECK: Finalize status {{.*}}
+  fC();
+  std::cout << "Main execution var = " << var << std::endl;
+  // CHECK: Main execution var = 6
+  std::cout << "Flush status " << __xray_log_flushLog() << std::endl;
+  // CHECK: Flush status {{.*}}
+  __xray_unpatch();
+  return 0;
+}
+
+// TRACE: { function }

compiler-rt/trunk/test/xray/lit.cfg

 # Setup default compiler flags use with -fxray-instrument option.
 clang_xray_cflags = (['-fxray-instrument', config.target_cflags])
 clang_xray_cxxflags = config.cxx_mode_flags + clang_xray_cflags
 
 
 def build_invocation(compile_flags):
   return ' ' + ' '.join([config.clang] + compile_flags) + ' '
 
+# Assume that llvm-xray is in the config.llvm_tools_dir.
+llvm_xray = os.path.join(config.llvm_tools_dir, 'llvm-xray')
+
 # Setup substitutions.
 config.substitutions.append(
     ('%clang ', build_invocation([config.target_cflags])))
 config.substitutions.append(
     ('%clangxx ',
      build_invocation(config.cxx_mode_flags + [config.target_cflags])))
 config.substitutions.append(
     ('%clang_xray ', build_invocation(clang_xray_cflags)))
 config.substitutions.append(
     ('%clangxx_xray', build_invocation(clang_xray_cxxflags)))
+config.substitutions.append(
+    ('%llvm_xray', llvm_xray))
 
 # Default test suffixes.
 config.suffixes = ['.c', '.cc', '.cpp']
 
 if config.host_os not in ['Linux']:
   config.unsupported = True
 elif '64' not in config.host_arch:
   if 'arm' in config.host_arch: