[XRay] [compiler-rt] unify all TSC API calls

[pelikan]

Summary

The current code unnecessarily checks for CPU features twice and doesn't take advantage of the infrastructure in xray_tsc.h at all. At the cost of going back to the old API, unify FDR's TSC handling with the rest of the code base and get rid of two arguments to processFunctionHook which will be subsequently used in D32844 for the first function call argument.

Should we decide to go from (return value + reference) to std::tuple<> is a separate matter (for a separate review).

The functional change here is very subtle - it will use TSC emulation calls everywhere, based on an unlikely static bool, in the same manner in both naïve and FDR modes.

[pelikan]

Actually, this is not NFC. The xray_tsc.h infrastructure doesn't check for old i386 CPUs and VMs where RDTSC is "not available" (because it's masked away, trapped and not handled properly). We should move this support into xray_tsc.h first, and remove the NFC tag.

[pelikan]

convert the entire amd64 TSC handling to do the correct thing in broken environments

[pelikan]

add a newline after clock_gettime(2)'s failure Report() string

[pelikan]

unify inmemory log as well

[dberris]

What are we trying to achieve here? It looks like it's sinking the decision on which implementation to invoke from the caller, down to the callee (readTSC) which gets less efficient.

While we don't have benchmarks yet upstream that measure the cost of these things, I'd really want to keep code in the readTSC(...) implementation to not have branches, and move branches out to the callers. It's unclear whether the benefit of reducing the arguments in processFunctionHook is worth it, if we're going to add more later anyway.

@eizan is working on getting some benchmarks upstream, but it would be good to make sure we're not unnecessarily being pessimistic with the implementation of key parts of the runtime.

lib/xray/xray_x86_64.inc

22

Why do we need this forward declaration?

26–28

I think we're going to have issues with this code in terms of performance impact. This is introducing a function call and synchronization on the first call, then in subsequent calls will introduce an unavoidable branch.

[dberris]

Is there anything else we need to do here?

lib/xray/xray_fdr_logging.cc

if (CurrentFlushingStatus == XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING)
       break;
     CurrentFlushingStatus = XRayLogFlushStatus::XRAY_LOG_FLUSHED;
   }
 
   // At this point, we know that the status is flushed, and that we can assume
   return XRayLogInitStatus::XRAY_LOG_UNINITIALIZED;
 }
 
-static std::tuple<uint64_t, unsigned char>
-getTimestamp() XRAY_NEVER_INSTRUMENT {
-  // We want to get the TSC as early as possible, so that we can check whether
-  // we've seen this CPU before. We also do it before we load anything else, to
-  // allow for forward progress with the scheduling.
-  unsigned char CPU;
-  uint64_t TSC;
-
-  // Test once for required CPU features
-  static bool TSCSupported = probeRequiredCPUFeatures();
-
-  if (TSCSupported) {
-    TSC = __xray::readTSC(CPU);
-  } else {
-    // FIXME: This code needs refactoring as it appears in multiple locations
-    timespec TS;
-    int result = clock_gettime(CLOCK_REALTIME, &TS);
-    if (result != 0) {
-      Report("clock_gettime(2) return %d, errno=%d", result, int(errno));
-      TS = {0, 0};
-    }
-    CPU = 0;
-    TSC = TS.tv_sec * __xray::NanosecondsPerSecond + TS.tv_nsec;
-  }
-  return std::make_tuple(TSC, CPU);
-}
-
 void fdrLoggingHandleArg0(int32_t FuncId,
                           XRayEntryType Entry) XRAY_NEVER_INSTRUMENT {
-  auto TSC_CPU = getTimestamp();
-  __xray_fdr_internal::processFunctionHook(FuncId, Entry, std::get<0>(TSC_CPU),
-                                           std::get<1>(TSC_CPU), clock_gettime,
+  __xray_fdr_internal::processFunctionHook(FuncId, Entry, clock_gettime,
                                            LoggingStatus, BQ);
 }
 
 void fdrLoggingHandleCustomEvent(void *Event,
                                  std::size_t EventSize) XRAY_NEVER_INSTRUMENT {
   using namespace __xray_fdr_internal;
-  auto TSC_CPU = getTimestamp();
-  auto &TSC = std::get<0>(TSC_CPU);
-  auto &CPU = std::get<1>(TSC_CPU);
+  uint8_t CPU;
+  uint64_t TSC = __xray::readTSC(CPU);
   thread_local bool Running = false;
   RecursionGuard Guard{Running};
   if (!Guard) {
     assert(Running && "RecursionGuard is buggy!");
     return;
   }
   if (EventSize > std::numeric_limits<int32_t>::max()) {
     using Empty = struct {};
void fdrLoggingHandleCustomEvent(void *Event,
   // Write the custom event metadata record, which consists of the following
   // information:
   //   - 8 bytes (64-bits) for the full TSC when the event started.
   //   - 4 bytes (32-bits) for the length of the data.
   MetadataRecord CustomEvent;
   CustomEvent.Type = uint8_t(RecordType::Metadata);
   CustomEvent.RecordKind =
       uint8_t(MetadataRecord::RecordKinds::CustomEventMarker);
-  constexpr auto TSCSize = sizeof(std::get<0>(TSC_CPU));
   std::memcpy(&CustomEvent.Data, &ReducedEventSize, sizeof(int32_t));
-  std::memcpy(&CustomEvent.Data[sizeof(int32_t)], &TSC, TSCSize);
+  std::memcpy(&CustomEvent.Data[sizeof(int32_t)], &TSC, sizeof(TSC));
   std::memcpy(RecordPtr, &CustomEvent, sizeof(CustomEvent));
   RecordPtr += sizeof(CustomEvent);
   std::memcpy(RecordPtr, Event, ReducedEventSize);
   endBufferIfFull();
 }
 
 XRayLogInitStatus fdrLoggingInit(std::size_t BufferSize, std::size_t BufferMax,
                                  void *Options,

lib/xray/xray_fdr_logging_impl.h

 
 /// Here's where the meat of the processing happens. The writer captures
 /// function entry, exit and tail exit points with a time and will create
 /// TSCWrap, NewCPUId and Function records as necessary. The writer might
 /// walk backward through its buffer and erase trivial functions to avoid
 /// polluting the log and may use the buffer queue to obtain or release a
 /// buffer.
 static void processFunctionHook(int32_t FuncId, XRayEntryType Entry,
-                                uint64_t TSC, unsigned char CPU,
                                 int (*wall_clock_reader)(clockid_t,
                                                          struct timespec *),
                                 __sanitizer::atomic_sint32_t &LoggingStatus,
                                 const std::shared_ptr<BufferQueue> &BQ);
 
 //-----------------------------------------------------------------------------|
 // The rest of the file is implementation.                                     |
 //-----------------------------------------------------------------------------|
if ((RecordPtr + MetadataRecSize) - BufferStart == MetadataRecSize) {
     writeEOBMetadata();
     if (!releaseThreadLocalBuffer(LocalBQ.get()))
       return;
     RecordPtr = nullptr;
   }
 }
 
 inline void processFunctionHook(
-    int32_t FuncId, XRayEntryType Entry, uint64_t TSC, unsigned char CPU,
+    int32_t FuncId, XRayEntryType Entry,
     int (*wall_clock_reader)(clockid_t, struct timespec *),
     __sanitizer::atomic_sint32_t &LoggingStatus,
     const std::shared_ptr<BufferQueue> &BQ) XRAY_NEVER_INSTRUMENT {
   // Prevent signal handler recursion, so in case we're already in a log writing
   // mode and the signal handler comes in (and is also instrumented) then we
   // don't want to be clobbering potentially partial writes already happening in
   // the thread. We use a simple thread_local latch to only allow one on-going
   // handleArg0 to happen at any given time.
   thread_local bool Running = false;
   RecursionGuard Guard{Running};
   if (!Guard) {
     assert(Running == true && "RecursionGuard is buggy!");
     return;
   }
 
   // In case the reference has been cleaned up before, we make sure we
   // initialize it to the provided BufferQueue.
   if (LocalBQ == nullptr)
     LocalBQ = BQ;
 
+  uint8_t CPU;
+  uint64_t TSC = readTSC(CPU);
   if (!isLogInitializedAndReady(LocalBQ, TSC, CPU, wall_clock_reader))
     return;
 
   // Before we go setting up writing new function entries, we need to be really
   // careful about the pointer math we're doing. This means we need to ensure
   // that the record we are about to write is going to fit into the buffer,
   // without overflowing the buffer.
   //

lib/xray/xray_inmemory_log.cc

static int __xray_OpenLogFile() XRAY_NEVER_INSTRUMENT {
   // before setting the values in the header.
   Header.ConstantTSC = 1;
   Header.NonstopTSC = 1;
   retryingWriteAll(F, reinterpret_cast<char *>(&Header),
                    reinterpret_cast<char *>(&Header) + sizeof(Header));
   return F;
 }
 
-template <class RDTSC>
-void __xray_InMemoryRawLog(int32_t FuncId, XRayEntryType Type,
-                           RDTSC ReadTSC) XRAY_NEVER_INSTRUMENT {
+void __xray_InMemoryRawLog(int32_t FuncId,
+                           XRayEntryType Type) XRAY_NEVER_INSTRUMENT {
   using Buffer =
       std::aligned_storage<sizeof(XRayRecord), alignof(XRayRecord)>::type;
   static constexpr size_t BuffLen = 1024;
   thread_local static Buffer InMemoryBuffer[BuffLen] = {};
   thread_local static size_t Offset = 0;
   static int Fd = __xray_OpenLogFile();
   if (Fd == -1)
     return;
   thread_local __xray::ThreadExitFlusher Flusher(
       Fd, reinterpret_cast<__xray::XRayRecord *>(InMemoryBuffer), Offset);
   thread_local pid_t TId = syscall(SYS_gettid);
 
   // First we get the useful data, and stuff it into the already aligned buffer
   // through a pointer offset.
   auto &R = reinterpret_cast<__xray::XRayRecord *>(InMemoryBuffer)[Offset];
   R.RecordType = RecordTypes::NORMAL;
-  R.TSC = ReadTSC(R.CPU);
+  R.TSC = __xray::readTSC(R.CPU);
   R.TId = TId;
   R.Type = Type;
   R.FuncId = FuncId;
   ++Offset;
   if (Offset == BuffLen) {
     std::lock_guard<std::mutex> L(LogMutex);
     auto RecordBuffer = reinterpret_cast<__xray::XRayRecord *>(InMemoryBuffer);
     retryingWriteAll(Fd, reinterpret_cast<char *>(RecordBuffer),
                      reinterpret_cast<char *>(RecordBuffer + Offset));
     Offset = 0;
   }
 }
 
-void __xray_InMemoryRawLogRealTSC(int32_t FuncId,
-                                  XRayEntryType Type) XRAY_NEVER_INSTRUMENT {
-  __xray_InMemoryRawLog(FuncId, Type, __xray::readTSC);
-}
-
-void __xray_InMemoryEmulateTSC(int32_t FuncId,
-                               XRayEntryType Type) XRAY_NEVER_INSTRUMENT {
-  __xray_InMemoryRawLog(FuncId, Type, [](uint8_t &CPU) XRAY_NEVER_INSTRUMENT {
-    timespec TS;
-    int result = clock_gettime(CLOCK_REALTIME, &TS);
-    if (result != 0) {
-      Report("clock_gettimg(2) return %d, errno=%d.", result, int(errno));
-      TS = {0, 0};
-    }
-    CPU = 0;
-    return TS.tv_sec * __xray::NanosecondsPerSecond + TS.tv_nsec;
-  });
-}
-
 static auto UNUSED Unused = [] {
-  auto UseRealTSC = probeRequiredCPUFeatures();
-  if (!UseRealTSC)
-    Report("WARNING: Required CPU features missing for XRay instrumentation, "
-           "using emulation instead.\n");
   if (flags()->xray_naive_log)
-    __xray_set_handler(UseRealTSC ? __xray_InMemoryRawLogRealTSC
-                                  : __xray_InMemoryEmulateTSC);
+    __xray_set_handler(__xray_InMemoryRawLog);
   return true;
 }();

lib/xray/xray_tsc.h

 // This file is a part of XRay, a dynamic runtime instrumentation system.
 //
 //===----------------------------------------------------------------------===//
 #ifndef XRAY_EMULATE_TSC_H
 #define XRAY_EMULATE_TSC_H
 
 namespace __xray {
 static constexpr uint64_t NanosecondsPerSecond = 1000ULL * 1000 * 1000;
+
+// Even if an architecture supports a TSC-like mechanism, a particular box can
+// still prevent us from using it; be it for security (SECCOMP), virtualization
+// (VMware's deterministic lockstep emulating RDTSC using APIC to eliminate VM
+// randomness) or age (older CPUs with broken/missing TSC support).  Therefore,
+// we always keep this function around.
+ALWAYS_INLINE uint64_t emulateReadTSC(uint8_t &CPU) XRAY_NEVER_INSTRUMENT {
+  timespec TS;
+  int result = clock_gettime(CLOCK_REALTIME, &TS);
+  if (result != 0) {
+    Report("clock_gettime(2) returned %d, errno=%d.\n", result, int(errno));
+    TS = {0, 0};
+  }
+  CPU = 0;
+  return TS.tv_sec * NanosecondsPerSecond + TS.tv_nsec;
+}
+
 }
 
 #if defined(__x86_64__)
 #include "xray_x86_64.inc"
 #elif defined(__powerpc64__)
 #include "xray_powerpc64.inc"
 #elif defined(__arm__) || defined(__aarch64__) || defined(__mips__)
 // Emulated TSC.

 #include <cstdint>
 #include <time.h>
 
 namespace __xray {
 
 inline bool probeRequiredCPUFeatures() XRAY_NEVER_INSTRUMENT { return true; }
 
 ALWAYS_INLINE uint64_t readTSC(uint8_t &CPU) XRAY_NEVER_INSTRUMENT {
-  timespec TS;
-  int result = clock_gettime(CLOCK_REALTIME, &TS);
-  if (result != 0) {
-    Report("clock_gettime(2) returned %d, errno=%d.", result, int(errno));
-    TS.tv_sec = 0;
-    TS.tv_nsec = 0;
-  }
-  CPU = 0;
-  return TS.tv_sec * NanosecondsPerSecond + TS.tv_nsec;
+  return emulateReadTSC(CPU);
 }
 
 inline uint64_t getTSCFrequency() XRAY_NEVER_INSTRUMENT {
   return NanosecondsPerSecond;
 }
 
 } // namespace __xray
 
 #else
 #error Target architecture is not supported.
 #endif // CPU architecture
 
 #endif // XRAY_EMULATE_TSC_H

lib/xray/xray_x86_64.inc

 #include <cstdint>
 #include <x86intrin.h>
 
 #include "sanitizer_common/sanitizer_internal_defs.h"
 #include "xray_defs.h"
 
 namespace __xray {
 
+bool probeRequiredCPUFeatures();
+
 ALWAYS_INLINE uint64_t readTSC(uint8_t &CPU) XRAY_NEVER_INSTRUMENT {
+  static bool TSCSupported = probeRequiredCPUFeatures();
+  if (UNLIKELY(!TSCSupported)) {
+    return emulateReadTSC(CPU);
+  }
   unsigned LongCPU;
   uint64_t TSC = __rdtscp(&LongCPU);
   CPU = LongCPU;
   return TSC;
 }
 
 uint64_t getTSCFrequency();
 
-bool probeRequiredCPUFeatures();
-
 } // namespace __xray