[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

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

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

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

This is never called AFAICT.

51

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

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.

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.

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

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

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;
   }

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);

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

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(); }
+
+[[clang::xray_always_instrument]] void __attribute__((noinline)) fD() {
+  std::this_thread::sleep_for(std::chrono::milliseconds(100));
+}
+
+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();
+    std::cout << "Thread execution var = " << var << std::endl;
+  });
+  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 }

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: