[XRay] Use TSC delta encoding for custom/typed events

Summary:
This change updates the version number for FDR logs to 5, and update the
trace processing to support changes in the custom event records.

In the runtime, since we're already writing down the record preamble to
handle CPU migrations and TSC wraparound, we can use the same TSC delta
encoding in the custom event and typed event records that we use in
function event records. We do the same change to typed events (which
were unsupported before this change in the trace processing) which now
show up in the trace.

Future changes should increase our testing coverage to make custom and
typed events as first class entities in the FDR mode log processing
tools.

This change is also a good example of how we end up supporting new
record types in the FDR mode implementation. This shows the places where
new record types are added and supported.

Depends on D54139.

Reviewers: mboerger

Subscribers: hiraditya, arphaman, jfb, llvm-commits

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

git-svn-id: https://llvm.org/svn/llvm-project/compiler-rt/trunk@346293 91177308-0d34-0410-b5e6-96231b3b80d8

3 files changed, 84 insertions, 69 deletions

diff --git a/lib/xray/xray_fdr_controller.h b/lib/xray/xray_fdr_controller.h
index a0bad5206..5c04cbf7d 100644
--- a/lib/xray/xray_fdr_controller.h
+++ b/lib/xray/xray_fdr_controller.h
@@ -23,7 +23,7 @@
 
 namespace __xray {
 
-template <size_t Version = 3> class FDRController {
+template <size_t Version = 5> class FDRController {
   BufferQueue *BQ;
   BufferQueue::Buffer &B;
   FDRLogWriter &W;
@@ -144,8 +144,8 @@ template <size_t Version = 3> class FDRController {
   }
 
   enum class PreambleResult { NoChange, WroteMetadata, InvalidBuffer };
-  PreambleResult functionPreamble(uint64_t TSC,
-                                  uint16_t CPU) XRAY_NEVER_INSTRUMENT {
+  PreambleResult recordPreamble(uint64_t TSC,
+                                uint16_t CPU) XRAY_NEVER_INSTRUMENT {
     if (UNLIKELY(LatestCPU != CPU || LatestTSC == 0)) {
       // We update our internal tracking state for the Latest TSC and CPU we've
       // seen, then write out the appropriate metadata and function records.
@@ -248,7 +248,7 @@ public:
         !prepareBuffer(sizeof(MetadataRecord) + sizeof(FunctionRecord)))
       return returnBuffer();
 
-    auto PreambleStatus = functionPreamble(TSC, CPU);
+    auto PreambleStatus = recordPreamble(TSC, CPU);
     if (PreambleStatus == PreambleResult::InvalidBuffer)
       return returnBuffer();
 
@@ -270,7 +270,7 @@ public:
     if (!prepareBuffer(sizeof(MetadataRecord) + sizeof(FunctionRecord)))
       return returnBuffer();
 
-    auto PreambleStatus = functionPreamble(TSC, CPU);
+    auto PreambleStatus = recordPreamble(TSC, CPU);
     if (PreambleStatus == PreambleResult::InvalidBuffer)
       return returnBuffer();
 
@@ -291,7 +291,7 @@ public:
                         uint64_t Arg) XRAY_NEVER_INSTRUMENT {
     if (finalized() ||
         !prepareBuffer((2 * sizeof(MetadataRecord)) + sizeof(FunctionRecord)) ||
-        functionPreamble(TSC, CPU) == PreambleResult::InvalidBuffer)
+        recordPreamble(TSC, CPU) == PreambleResult::InvalidBuffer)
       return returnBuffer();
 
     auto Delta = TSC - LatestTSC;
@@ -311,7 +311,7 @@ public:
         !prepareBuffer(sizeof(MetadataRecord) + sizeof(FunctionRecord)))
       return returnBuffer();
 
-    auto PreambleStatus = functionPreamble(TSC, CPU);
+    auto PreambleStatus = recordPreamble(TSC, CPU);
     if (PreambleStatus == PreambleResult::InvalidBuffer)
       return returnBuffer();
 
@@ -332,26 +332,28 @@ public:
                    int32_t EventSize) XRAY_NEVER_INSTRUMENT {
     if (finalized() ||
         !prepareBuffer((2 * sizeof(MetadataRecord)) + EventSize) ||
-        functionPreamble(TSC, CPU) == PreambleResult::InvalidBuffer)
+        recordPreamble(TSC, CPU) == PreambleResult::InvalidBuffer)
       return returnBuffer();
 
-    LatestTSC = 0;
+    auto Delta = TSC - LatestTSC;
+    LatestTSC = TSC;
     UndoableFunctionEnters = 0;
     UndoableTailExits = 0;
-    return W.writeCustomEvent(TSC, CPU, Event, EventSize);
+    return W.writeCustomEvent(Delta, Event, EventSize);
   }
 
   bool typedEvent(uint64_t TSC, uint16_t CPU, uint16_t EventType,
                   const void *Event, int32_t EventSize) XRAY_NEVER_INSTRUMENT {
     if (finalized() ||
         !prepareBuffer((2 * sizeof(MetadataRecord)) + EventSize) ||
-        functionPreamble(TSC, CPU) == PreambleResult::InvalidBuffer)
+        recordPreamble(TSC, CPU) == PreambleResult::InvalidBuffer)
       return returnBuffer();
 
-    LatestTSC = 0;
+    auto Delta = TSC - LatestTSC;
+    LatestTSC = TSC;
     UndoableFunctionEnters = 0;
     UndoableTailExits = 0;
-    return W.writeTypedEvent(TSC, EventType, Event, EventSize);
+    return W.writeTypedEvent(Delta, EventType, Event, EventSize);
   }
 
   bool flush() XRAY_NEVER_INSTRUMENT {
diff --git a/lib/xray/xray_fdr_log_writer.h b/lib/xray/xray_fdr_log_writer.h
index a85acf48f..5f94969a7 100644
--- a/lib/xray/xray_fdr_log_writer.h
+++ b/lib/xray/xray_fdr_log_writer.h
@@ -110,8 +110,7 @@ public:
     return true;
   }
 
-  bool writeCustomEvent(uint64_t TSC, uint16_t CPU, const void *Event,
-                        int32_t EventSize) {
+  bool writeCustomEvent(int32_t Delta, const void *Event, int32_t EventSize) {
     // We write the metadata record and the custom event data into the buffer
     // first, before we atomically update the extents for the buffer. This
     // allows us to ensure that any threads reading the extents of the buffer
@@ -119,7 +118,7 @@ public:
     // (no partial writes accounted).
     MetadataRecord R =
         createMetadataRecord<MetadataRecord::RecordKinds::CustomEventMarker>(
-            EventSize, TSC, CPU);
+            EventSize, Delta);
     NextRecord = reinterpret_cast<char *>(internal_memcpy(
                      NextRecord, reinterpret_cast<char *>(&R), sizeof(R))) +
                  sizeof(R);
@@ -131,13 +130,13 @@ public:
     return true;
   }
 
-  bool writeTypedEvent(uint64_t TSC, uint16_t EventType, const void *Event,
+  bool writeTypedEvent(int32_t Delta, uint16_t EventType, const void *Event,
                        int32_t EventSize) {
     // We do something similar when writing out typed events, see
     // writeCustomEvent(...) above for details.
     MetadataRecord R =
         createMetadataRecord<MetadataRecord::RecordKinds::TypedEventMarker>(
-            EventSize, TSC, EventType);
+            EventSize, Delta, EventType);
     NextRecord = reinterpret_cast<char *>(internal_memcpy(
                      NextRecord, reinterpret_cast<char *>(&R), sizeof(R))) +
                  sizeof(R);
diff --git a/lib/xray/xray_fdr_logging.cc b/lib/xray/xray_fdr_logging.cc
index 916ee6034..83f4f97a2 100644
--- a/lib/xray/xray_fdr_logging.cc
+++ b/lib/xray/xray_fdr_logging.cc
@@ -47,6 +47,7 @@ static atomic_sint32_t LoggingStatus = {
     XRayLogInitStatus::XRAY_LOG_UNINITIALIZED};
 
 namespace {
+
 // Group together thread-local-data in a struct, then hide it behind a function
 // call so that it can be initialized on first use instead of as a global. We
 // force the alignment to 64-bytes for x86 cache line alignment, as this
@@ -143,26 +144,31 @@ static XRayFileHeader &fdrCommonHeaderInfo() {
   static pthread_once_t OnceInit = PTHREAD_ONCE_INIT;
   static bool TSCSupported = true;
   static uint64_t CycleFrequency = NanosecondsPerSecond;
-  pthread_once(&OnceInit, +[] {
-    XRayFileHeader &H = reinterpret_cast<XRayFileHeader &>(HStorage);
-    // Version 2 of the log writes the extents of the buffer, instead of
-    // relying on an end-of-buffer record.
-    // Version 3 includes PID metadata record
-    // Version 4 includes CPU data in the custom event records
-    H.Version = 4;
-    H.Type = FileTypes::FDR_LOG;
-
-    // Test for required CPU features and cache the cycle frequency
-    TSCSupported = probeRequiredCPUFeatures();
-    if (TSCSupported)
-      CycleFrequency = getTSCFrequency();
-    H.CycleFrequency = CycleFrequency;
-
-    // FIXME: Actually check whether we have 'constant_tsc' and
-    // 'nonstop_tsc' before setting the values in the header.
-    H.ConstantTSC = 1;
-    H.NonstopTSC = 1;
-  });
+  pthread_once(
+      &OnceInit, +[] {
+        XRayFileHeader &H = reinterpret_cast<XRayFileHeader &>(HStorage);
+        // Version 2 of the log writes the extents of the buffer, instead of
+        // relying on an end-of-buffer record.
+        // Version 3 includes PID metadata record.
+        // Version 4 includes CPU data in the custom event records.
+        // Version 5 uses relative deltas for custom and typed event records,
+        // and removes the CPU data in custom event records (similar to how
+        // function records use deltas instead of full TSCs and rely on other
+        // metadata records for TSC wraparound and CPU migration).
+        H.Version = 5;
+        H.Type = FileTypes::FDR_LOG;
+
+        // Test for required CPU features and cache the cycle frequency
+        TSCSupported = probeRequiredCPUFeatures();
+        if (TSCSupported)
+          CycleFrequency = getTSCFrequency();
+        H.CycleFrequency = CycleFrequency;
+
+        // FIXME: Actually check whether we have 'constant_tsc' and
+        // 'nonstop_tsc' before setting the values in the header.
+        H.ConstantTSC = 1;
+        H.NonstopTSC = 1;
+      });
   return reinterpret_cast<XRayFileHeader &>(HStorage);
 }
 
@@ -200,9 +206,11 @@ XRayBuffer fdrIterator(const XRayBuffer B) {
   // buffers to expect).
   static std::aligned_storage<sizeof(XRayFileHeader)>::type HeaderStorage;
   static pthread_once_t HeaderOnce = PTHREAD_ONCE_INIT;
-  pthread_once(&HeaderOnce, +[] {
-    reinterpret_cast<XRayFileHeader &>(HeaderStorage) = fdrCommonHeaderInfo();
-  });
+  pthread_once(
+      &HeaderOnce, +[] {
+        reinterpret_cast<XRayFileHeader &>(HeaderStorage) =
+            fdrCommonHeaderInfo();
+      });
 
   // We use a convenience alias for code referring to Header from here on out.
   auto &Header = reinterpret_cast<XRayFileHeader &>(HeaderStorage);
@@ -407,7 +415,8 @@ static TSCAndCPU getTimestamp() XRAY_NEVER_INSTRUMENT {
   // Test once for required CPU features
   static pthread_once_t OnceProbe = PTHREAD_ONCE_INIT;
   static bool TSCSupported = true;
-  pthread_once(&OnceProbe, +[] { TSCSupported = probeRequiredCPUFeatures(); });
+  pthread_once(
+      &OnceProbe, +[] { TSCSupported = probeRequiredCPUFeatures(); });
 
   if (TSCSupported) {
     Result.TSC = __xray::readTSC(Result.CPU);
@@ -550,10 +559,11 @@ void fdrLoggingHandleCustomEvent(void *Event,
   if (EventSize >
       static_cast<std::size_t>(std::numeric_limits<int32_t>::max())) {
     static pthread_once_t Once = PTHREAD_ONCE_INIT;
-    pthread_once(&Once, +[] {
-      Report("Custom event size too large; truncating to %d.\n",
-             std::numeric_limits<int32_t>::max());
-    });
+    pthread_once(
+        &Once, +[] {
+          Report("Custom event size too large; truncating to %d.\n",
+                 std::numeric_limits<int32_t>::max());
+        });
   }
 
   auto &TLD = getThreadLocalData();
@@ -579,10 +589,11 @@ void fdrLoggingHandleTypedEvent(
   if (EventSize >
       static_cast<std::size_t>(std::numeric_limits<int32_t>::max())) {
     static pthread_once_t Once = PTHREAD_ONCE_INIT;
-    pthread_once(&Once, +[] {
-      Report("Typed event size too large; truncating to %d.\n",
-             std::numeric_limits<int32_t>::max());
-    });
+    pthread_once(
+        &Once, +[] {
+          Report("Typed event size too large; truncating to %d.\n",
+                 std::numeric_limits<int32_t>::max());
+        });
   }
 
   auto &TLD = getThreadLocalData();
@@ -660,25 +671,28 @@ XRayLogInitStatus fdrLoggingInit(size_t, size_t, void *Options,
   }
 
   static pthread_once_t OnceInit = PTHREAD_ONCE_INIT;
-  pthread_once(&OnceInit, +[] {
-    atomic_store(&TicksPerSec,
-                 probeRequiredCPUFeatures() ? getTSCFrequency()
-                                            : __xray::NanosecondsPerSecond,
-                 memory_order_release);
-    pthread_key_create(&Key, +[](void *TLDPtr) {
-      if (TLDPtr == nullptr)
-        return;
-      auto &TLD = *reinterpret_cast<ThreadLocalData *>(TLDPtr);
-      if (TLD.BQ == nullptr)
-        return;
-      if (TLD.Buffer.Data == nullptr)
-        return;
-      auto EC = TLD.BQ->releaseBuffer(TLD.Buffer);
-      if (EC != BufferQueue::ErrorCode::Ok)
-        Report("At thread exit, failed to release buffer at %p; error=%s\n",
-               TLD.Buffer.Data, BufferQueue::getErrorString(EC));
-    });
-  });
+  pthread_once(
+      &OnceInit, +[] {
+        atomic_store(&TicksPerSec,
+                     probeRequiredCPUFeatures() ? getTSCFrequency()
+                                                : __xray::NanosecondsPerSecond,
+                     memory_order_release);
+        pthread_key_create(
+            &Key, +[](void *TLDPtr) {
+              if (TLDPtr == nullptr)
+                return;
+              auto &TLD = *reinterpret_cast<ThreadLocalData *>(TLDPtr);
+              if (TLD.BQ == nullptr)
+                return;
+              if (TLD.Buffer.Data == nullptr)
+                return;
+              auto EC = TLD.BQ->releaseBuffer(TLD.Buffer);
+              if (EC != BufferQueue::ErrorCode::Ok)
+                Report("At thread exit, failed to release buffer at %p; "
+                       "error=%s\n",
+                       TLD.Buffer.Data, BufferQueue::getErrorString(EC));
+            });
+      });
 
   atomic_store(&ThresholdTicks,
                atomic_load_relaxed(&TicksPerSec) *