[XRay] Use TSC delta encoding for custom/typed events
authorDean Michael Berris <dberris@google.com>
Wed, 7 Nov 2018 04:37:42 +0000 (04:37 +0000)
committerDean Michael Berris <dberris@google.com>
Wed, 7 Nov 2018 04:37:42 +0000 (04:37 +0000)
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

llvm-svn: 346293

22 files changed:
compiler-rt/lib/xray/xray_fdr_controller.h
compiler-rt/lib/xray/xray_fdr_log_writer.h
compiler-rt/lib/xray/xray_fdr_logging.cc
llvm/include/llvm/XRay/BlockIndexer.h
llvm/include/llvm/XRay/BlockPrinter.h
llvm/include/llvm/XRay/BlockVerifier.h
llvm/include/llvm/XRay/FDRRecords.h
llvm/include/llvm/XRay/FDRTraceExpander.h
llvm/include/llvm/XRay/FDRTraceWriter.h
llvm/include/llvm/XRay/RecordPrinter.h
llvm/lib/XRay/BlockIndexer.cpp
llvm/lib/XRay/BlockPrinter.cpp
llvm/lib/XRay/BlockVerifier.cpp
llvm/lib/XRay/FDRRecordProducer.cpp
llvm/lib/XRay/FDRRecords.cpp
llvm/lib/XRay/FDRTraceExpander.cpp
llvm/lib/XRay/FDRTraceWriter.cpp
llvm/lib/XRay/FileHeaderReader.cpp
llvm/lib/XRay/RecordInitializer.cpp
llvm/lib/XRay/RecordPrinter.cpp
llvm/lib/XRay/Trace.cpp
llvm/unittests/XRay/FDRRecordsTest.cpp

index a0bad520627f0642ba0dfa2b7aa6dc0e3316c10a..5c04cbf7d27a6b887db6a0e1a53b5ccfda04eb79 100644 (file)
@@ -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 {
index a85acf48f1e0ac9b4ff4699e8eccc9288b502bd3..5f94969a7d2dd680060b052494ff890fb78d2ebf 100644 (file)
@@ -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);
index 916ee603468754440a10e23b64e5a52b4f56ba95..83f4f97a2b416de54d6157c38f31721343a2eec8 100644 (file)
@@ -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) *
index 46a7243685fa358e3941d7c8a998aabe33d1b0d0..b42fa17f3fb7bd34e13071b8e43e7c5933787334 100644 (file)
@@ -54,6 +54,8 @@ public:
   Error visit(NewBufferRecord &) override;
   Error visit(EndBufferRecord &) override;
   Error visit(FunctionRecord &) override;
+  Error visit(CustomEventRecordV5 &) override;
+  Error visit(TypedEventRecord &) override;
 
   /// The flush() function will clear out the current state of the visitor, to
   /// allow for explicitly flushing a block's records to the currently
index 3a8f6e0d35ea3bc5a2822e9511c34312a94e5fcb..bfb21e2395172f693f3e29cf6480379603ac608b 100644 (file)
@@ -50,6 +50,8 @@ public:
   Error visit(NewBufferRecord &) override;
   Error visit(EndBufferRecord &) override;
   Error visit(FunctionRecord &) override;
+  Error visit(CustomEventRecordV5 &) override;
+  Error visit(TypedEventRecord &) override;
 
   void reset() { CurrentState = State::Start; }
 };
index b43a435e93bba563129597422c0121fedd3a01a4..46371c13891a7a79143f010527ab3bd80a68dbf7 100644 (file)
@@ -33,6 +33,7 @@ public:
     NewCPUId,
     TSCWrap,
     CustomEvent,
+    TypedEvent,
     Function,
     CallArg,
     EndOfBuffer,
@@ -58,6 +59,8 @@ public:
   Error visit(NewBufferRecord &) override;
   Error visit(EndBufferRecord &) override;
   Error visit(FunctionRecord &) override;
+  Error visit(CustomEventRecordV5 &) override;
+  Error visit(TypedEventRecord &) override;
 
   Error verify();
   void reset();
index 2d47ab3cfe5066de9182d22ecffb36b02374453c..9d48332d5083d15e56b732937561c0e039486482 100644 (file)
@@ -66,6 +66,7 @@ public:
     PIDEntry,
     NewBuffer,
     EndOfBuffer,
+    TypedEvent,
   };
 
   Type type() const override { return Type::Metadata; }
@@ -174,6 +175,52 @@ public:
   Error apply(RecordVisitor &V) override;
 };
 
+class CustomEventRecordV5 : public MetadataRecord {
+  int32_t Size = 0;
+  int32_t Delta = 0;
+  std::string Data{};
+  friend class RecordInitializer;
+
+public:
+  CustomEventRecordV5() = default;
+  explicit CustomEventRecordV5(int32_t S, int32_t D, std::string P)
+      : MetadataRecord(), Size(S), Delta(D), Data(std::move(P)) {}
+
+  MetadataType metadataType() const override {
+    return MetadataType::CustomEvent;
+  }
+
+  int32_t size() const { return Size; }
+  int32_t delta() const { return Delta; }
+  StringRef data() const { return Data; }
+
+  Error apply(RecordVisitor &V) override;
+};
+
+class TypedEventRecord : public MetadataRecord {
+  int32_t Size = 0;
+  int32_t Delta = 0;
+  uint16_t EventType = 0;
+  std::string Data{};
+  friend class RecordInitializer;
+
+public:
+  TypedEventRecord() = default;
+  explicit TypedEventRecord(int32_t S, int32_t D, uint16_t E, std::string P)
+      : MetadataRecord(), Size(S), Delta(D), Data(std::move(P)) {}
+
+  MetadataType metadataType() const override {
+    return MetadataType::TypedEvent;
+  }
+
+  int32_t size() const { return Size; }
+  int32_t delta() const { return Delta; }
+  uint16_t eventType() const { return EventType; }
+  StringRef data() const { return Data; }
+
+  Error apply(RecordVisitor &V) override;
+};
+
 class CallArgRecord : public MetadataRecord {
   uint64_t Arg;
   friend class RecordInitializer;
@@ -269,6 +316,8 @@ public:
   virtual Error visit(NewBufferRecord &) = 0;
   virtual Error visit(EndBufferRecord &) = 0;
   virtual Error visit(FunctionRecord &) = 0;
+  virtual Error visit(CustomEventRecordV5 &) = 0;
+  virtual Error visit(TypedEventRecord &) = 0;
 };
 
 class RecordInitializer : public RecordVisitor {
@@ -277,7 +326,7 @@ class RecordInitializer : public RecordVisitor {
   uint16_t Version;
 
 public:
-  static constexpr uint16_t DefaultVersion = 4u;
+  static constexpr uint16_t DefaultVersion = 5u;
 
   explicit RecordInitializer(DataExtractor &DE, uint32_t &OP, uint16_t V)
       : RecordVisitor(), E(DE), OffsetPtr(OP), Version(V) {}
@@ -295,6 +344,8 @@ public:
   Error visit(NewBufferRecord &) override;
   Error visit(EndBufferRecord &) override;
   Error visit(FunctionRecord &) override;
+  Error visit(CustomEventRecordV5 &) override;
+  Error visit(TypedEventRecord &) override;
 };
 
 } // namespace xray
index 64c459930b29807aec18e90baf66c4b63ae76d86..02a21bed5ce916fabab76ee8cbe22dc408bacdb3 100644 (file)
@@ -49,6 +49,8 @@ public:
   Error visit(NewBufferRecord &) override;
   Error visit(EndBufferRecord &) override;
   Error visit(FunctionRecord &) override;
+  Error visit(CustomEventRecordV5 &) override;
+  Error visit(TypedEventRecord &) override;
 
   // Must be called after all the records have been processed, to handle the
   // most recent record generated.
index 91488f89ecc529c3c8a2f239b54a60936a040ba7..7b3b5fa25eff4b31dae47b45ddfb7b2058444839 100644 (file)
@@ -43,6 +43,8 @@ public:
   Error visit(NewBufferRecord &) override;
   Error visit(EndBufferRecord &) override;
   Error visit(FunctionRecord &) override;
+  Error visit(CustomEventRecordV5 &) override;
+  Error visit(TypedEventRecord &) override;
 
 private:
   support::endian::Writer OS;
index bad1a5742b4529b7bdef6d809dd630133ef3aa7c..649c64ab6f5cbfbee1af0418f795ef3a349ca69b 100644 (file)
@@ -40,6 +40,8 @@ public:
   Error visit(NewBufferRecord &) override;
   Error visit(EndBufferRecord &) override;
   Error visit(FunctionRecord &) override;
+  Error visit(CustomEventRecordV5 &) override;
+  Error visit(TypedEventRecord &) override;
 };
 
 } // namespace xray
index 98e91f7de5487d0ce44627af24238a926ae93452..4dbe2d2717ad1cd88a445197870665249a33f164 100644 (file)
@@ -39,6 +39,16 @@ Error BlockIndexer::visit(CustomEventRecord &R) {
   return Error::success();
 }
 
+Error BlockIndexer::visit(CustomEventRecordV5 &R) {
+  CurrentBlock.Records.push_back(&R);
+  return Error::success();
+}
+
+Error BlockIndexer::visit(TypedEventRecord &R) {
+  CurrentBlock.Records.push_back(&R);
+  return Error::success();
+}
+
 Error BlockIndexer::visit(CallArgRecord &R) {
   CurrentBlock.Records.push_back(&R);
   return Error::success();
index c8b65fc12d766d711cbd457c836c27e0e7f30c20..0acebee0cbdd253943be032548bec574c8457808 100644 (file)
@@ -68,6 +68,24 @@ Error BlockPrinter::visit(CustomEventRecord &R) {
   return E;
 }
 
+Error BlockPrinter::visit(CustomEventRecordV5 &R) {
+  if (CurrentState == State::Metadata)
+    OS << "\n";
+  CurrentState = State::CustomEvent;
+  OS << "*  ";
+  auto E = RP.visit(R);
+  return E;
+}
+
+Error BlockPrinter::visit(TypedEventRecord &R) {
+  if (CurrentState == State::Metadata)
+    OS << "\n";
+  CurrentState = State::CustomEvent;
+  OS << "*  ";
+  auto E = RP.visit(R);
+  return E;
+}
+
 // Function call printing.
 Error BlockPrinter::visit(FunctionRecord &R) {
   if (CurrentState == State::Metadata)
index 62be1a87ab5b94e715f668b3ee944755d114ea74..5e949ec4e46afc3d34d1427335418b2f95a01bf1 100644 (file)
@@ -43,6 +43,8 @@ StringRef recordToString(BlockVerifier::State R) {
     return "CallArg";
   case BlockVerifier::State::EndOfBuffer:
     return "EndOfBuffer";
+  case BlockVerifier::State::TypedEvent:
+    return "TypedEvent";
   case BlockVerifier::State::StateMax:
   case BlockVerifier::State::Unknown:
     return "Unknown";
@@ -75,27 +77,34 @@ Error BlockVerifier::transition(State To) {
                        {State::NewCPUId,
                         {mask(State::NewCPUId) | mask(State::TSCWrap) |
                          mask(State::CustomEvent) | mask(State::Function) |
-                         mask(State::EndOfBuffer)}},
+                         mask(State::EndOfBuffer) | mask(State::TypedEvent)}},
 
                        {State::TSCWrap,
                         {mask(State::TSCWrap) | mask(State::NewCPUId) |
                          mask(State::CustomEvent) | mask(State::Function) |
-                         mask(State::EndOfBuffer)}},
+                         mask(State::EndOfBuffer) | mask(State::TypedEvent)}},
 
                        {State::CustomEvent,
                         {mask(State::CustomEvent) | mask(State::TSCWrap) |
                          mask(State::NewCPUId) | mask(State::Function) |
-                         mask(State::EndOfBuffer)}},
+                         mask(State::EndOfBuffer) | mask(State::TypedEvent)}},
+
+                       {State::TypedEvent,
+                        {mask(State::TypedEvent) | mask(State::TSCWrap) |
+                         mask(State::NewCPUId) | mask(State::Function) |
+                         mask(State::EndOfBuffer) | mask(State::CustomEvent)}},
 
                        {State::Function,
                         {mask(State::Function) | mask(State::TSCWrap) |
                          mask(State::NewCPUId) | mask(State::CustomEvent) |
-                         mask(State::CallArg) | mask(State::EndOfBuffer)}},
+                         mask(State::CallArg) | mask(State::EndOfBuffer) |
+                         mask(State::TypedEvent)}},
 
                        {State::CallArg,
                         {mask(State::CallArg) | mask(State::Function) |
                          mask(State::TSCWrap) | mask(State::NewCPUId) |
-                         mask(State::CustomEvent) | mask(State::EndOfBuffer)}},
+                         mask(State::CustomEvent) | mask(State::EndOfBuffer) |
+                         mask(State::TypedEvent)}},
 
                        {State::EndOfBuffer, {}}}};
 
@@ -145,6 +154,14 @@ Error BlockVerifier::visit(CustomEventRecord &) {
   return transition(State::CustomEvent);
 }
 
+Error BlockVerifier::visit(CustomEventRecordV5 &) {
+  return transition(State::CustomEvent);
+}
+
+Error BlockVerifier::visit(TypedEventRecord &) {
+  return transition(State::TypedEvent);
+}
+
 Error BlockVerifier::visit(CallArgRecord &) {
   return transition(State::CallArg);
 }
@@ -169,6 +186,7 @@ Error BlockVerifier::verify() {
   case State::EndOfBuffer:
   case State::NewCPUId:
   case State::CustomEvent:
+  case State::TypedEvent:
   case State::Function:
   case State::CallArg:
   case State::TSCWrap:
index 59b5697cd64e2c0c6e61e6de24d956abbbd7a795..122578010c435acbed71546374a45224f6c7630a 100644 (file)
@@ -53,14 +53,15 @@ metadataRecordType(const XRayFileHeader &Header, uint8_t T) {
   case MetadataRecordKinds::WalltimeMarkerKind:
     return make_unique<WallclockRecord>();
   case MetadataRecordKinds::CustomEventMarkerKind:
+    if (Header.Version >= 5)
+      return make_unique<CustomEventRecordV5>();
     return make_unique<CustomEventRecord>();
   case MetadataRecordKinds::CallArgumentKind:
     return make_unique<CallArgRecord>();
   case MetadataRecordKinds::BufferExtentsKind:
     return make_unique<BufferExtents>();
   case MetadataRecordKinds::TypedEventMarkerKind:
-    return createStringError(std::make_error_code(std::errc::invalid_argument),
-                             "Encountered an unsupported TypedEventMarker.");
+    return make_unique<TypedEventRecord>();
   case MetadataRecordKinds::PidKind:
     return make_unique<PIDRecord>();
   case MetadataRecordKinds::EnumEndMarker:
index 66d17ffcb53f760bcd3b5a0e9e19b662d63e7e0c..2b68a73686fbf95713cb71e2e96922e633c2f3ea 100644 (file)
@@ -26,6 +26,8 @@ Error PIDRecord::apply(RecordVisitor &V) { return V.visit(*this); }
 Error NewBufferRecord::apply(RecordVisitor &V) { return V.visit(*this); }
 Error EndBufferRecord::apply(RecordVisitor &V) { return V.visit(*this); }
 Error FunctionRecord::apply(RecordVisitor &V) { return V.visit(*this); }
+Error CustomEventRecordV5::apply(RecordVisitor &V) { return V.visit(*this); }
+Error TypedEventRecord::apply(RecordVisitor &V) { return V.visit(*this); }
 
 } // namespace xray
 } // namespace llvm
index adddb550ecd8ab938f5fb1b15b7b65c702c54873..e67f4b5d89f38429a8c751640ce930417661392b 100644 (file)
@@ -52,6 +52,39 @@ Error TraceExpander::visit(CustomEventRecord &R) {
   return Error::success();
 }
 
+Error TraceExpander::visit(CustomEventRecordV5 &R) {
+  resetCurrentRecord();
+  if (!IgnoringRecords) {
+    BaseTSC += R.delta();
+    CurrentRecord.TSC = BaseTSC;
+    CurrentRecord.CPU = CPUId;
+    CurrentRecord.PId = PID;
+    CurrentRecord.TId = TID;
+    CurrentRecord.Type = RecordTypes::CUSTOM_EVENT;
+    std::copy(R.data().begin(), R.data().end(),
+              std::back_inserter(CurrentRecord.Data));
+    BuildingRecord = true;
+  }
+  return Error::success();
+}
+
+Error TraceExpander::visit(TypedEventRecord &R) {
+  resetCurrentRecord();
+  if (!IgnoringRecords) {
+    BaseTSC += R.delta();
+    CurrentRecord.TSC = BaseTSC;
+    CurrentRecord.CPU = CPUId;
+    CurrentRecord.PId = PID;
+    CurrentRecord.TId = TID;
+    CurrentRecord.RecordType = R.eventType();
+    CurrentRecord.Type = RecordTypes::TYPED_EVENT;
+    std::copy(R.data().begin(), R.data().end(),
+              std::back_inserter(CurrentRecord.Data));
+    BuildingRecord = true;
+  }
+  return Error::success();
+}
+
 Error TraceExpander::visit(CallArgRecord &R) {
   CurrentRecord.CallArgs.push_back(R.arg());
   CurrentRecord.Type = RecordTypes::ENTER_ARG;
index 4f40593cba011a24abe87e6a0dde452b1bf1f545..d5f9697998638396c53aa04d1f2daf55635503f0 100644 (file)
@@ -102,6 +102,24 @@ Error FDRTraceWriter::visit(CustomEventRecord &R) {
   return Error::success();
 }
 
+Error FDRTraceWriter::visit(CustomEventRecordV5 &R) {
+  if (auto E = writeMetadata<5u>(OS, R.size(), R.delta()))
+    return E;
+  auto D = R.data();
+  ArrayRef<char> Bytes(D.data(), D.size());
+  OS.write(Bytes);
+  return Error::success();
+}
+
+Error FDRTraceWriter::visit(TypedEventRecord &R) {
+  if (auto E = writeMetadata<7u>(OS, R.size(), R.delta(), R.eventType()))
+    return E;
+  auto D = R.data();
+  ArrayRef<char> Bytes(D.data(), D.size());
+  OS.write(Bytes);
+  return Error::success();
+}
+
 Error FDRTraceWriter::visit(CallArgRecord &R) {
   return writeMetadata<6u>(OS, R.arg());
 }
index 9dea217840b88db3339aad6a60e3458a9787a34c..0b3fb8b6f692db919c4ad96134812949f9cceb0a 100644 (file)
@@ -63,10 +63,6 @@ Expected<XRayFileHeader> readBinaryFormatHeader(DataExtractor &HeaderExtractor,
   // Manually advance the offset pointer 16 bytes, after getting a raw memcpy
   // from the underlying data.
   OffsetPtr += 16;
-  if (FileHeader.Version < 1 || FileHeader.Version > 4)
-    return createStringError(std::make_error_code(std::errc::invalid_argument),
-                             "Unsupported XRay file version: %d at offset %d",
-                             FileHeader.Version, OffsetPtr);
   return std::move(FileHeader);
 }
 
index 2ebaa1cec26eb12223e50ca80e078f49274709b0..cc9dd4609498c28e47c8a174d0bae0c249b3226e 100644 (file)
@@ -151,6 +151,105 @@ Error RecordInitializer::visit(CustomEventRecord &R) {
   return Error::success();
 }
 
+Error RecordInitializer::visit(CustomEventRecordV5 &R) {
+  if (!E.isValidOffsetForDataOfSize(OffsetPtr,
+                                    MetadataRecord::kMetadataBodySize))
+    return createStringError(std::make_error_code(std::errc::bad_address),
+                             "Invalid offset for a custom event record (%d).",
+                             OffsetPtr);
+
+  auto BeginOffset = OffsetPtr;
+  auto PreReadOffset = OffsetPtr;
+
+  R.Size = E.getSigned(&OffsetPtr, sizeof(int32_t));
+  if (PreReadOffset == OffsetPtr)
+    return createStringError(
+        std::make_error_code(std::errc::invalid_argument),
+        "Cannot read a custom event record size field offset %d.", OffsetPtr);
+
+  PreReadOffset = OffsetPtr;
+  R.Delta = E.getSigned(&OffsetPtr, sizeof(int32_t));
+  if (PreReadOffset == OffsetPtr)
+    return createStringError(
+        std::make_error_code(std::errc::invalid_argument),
+        "Cannot read a custom event record TSC delta field at offset %d.",
+        OffsetPtr);
+
+  assert(OffsetPtr > BeginOffset &&
+         OffsetPtr - BeginOffset <= MetadataRecord::kMetadataBodySize);
+  OffsetPtr += MetadataRecord::kMetadataBodySize - (OffsetPtr - BeginOffset);
+
+  // Next we read in a fixed chunk of data from the given offset.
+  if (!E.isValidOffsetForDataOfSize(OffsetPtr, R.Size))
+    return createStringError(
+        std::make_error_code(std::errc::bad_address),
+        "Cannot read %d bytes of custom event data from offset %d.", R.Size,
+        OffsetPtr);
+
+  std::vector<uint8_t> Buffer;
+  Buffer.resize(R.Size);
+  if (E.getU8(&OffsetPtr, Buffer.data(), R.Size) != Buffer.data())
+    return createStringError(
+        std::make_error_code(std::errc::invalid_argument),
+        "Failed reading data into buffer of size %d at offset %d.", R.Size,
+        OffsetPtr);
+  R.Data.assign(Buffer.begin(), Buffer.end());
+  return Error::success();
+}
+
+Error RecordInitializer::visit(TypedEventRecord &R) {
+  if (!E.isValidOffsetForDataOfSize(OffsetPtr,
+                                    MetadataRecord::kMetadataBodySize))
+    return createStringError(std::make_error_code(std::errc::bad_address),
+                             "Invalid offset for a typed event record (%d).",
+                             OffsetPtr);
+
+  auto BeginOffset = OffsetPtr;
+  auto PreReadOffset = OffsetPtr;
+
+  R.Size = E.getSigned(&OffsetPtr, sizeof(int32_t));
+  if (PreReadOffset == OffsetPtr)
+    return createStringError(
+        std::make_error_code(std::errc::invalid_argument),
+        "Cannot read a typed event record size field offset %d.", OffsetPtr);
+
+  PreReadOffset = OffsetPtr;
+  R.Delta = E.getSigned(&OffsetPtr, sizeof(int32_t));
+  if (PreReadOffset == OffsetPtr)
+    return createStringError(
+        std::make_error_code(std::errc::invalid_argument),
+        "Cannot read a typed event record TSC delta field at offset %d.",
+        OffsetPtr);
+
+  PreReadOffset = OffsetPtr;
+  R.EventType = E.getU16(&OffsetPtr);
+  if (PreReadOffset == OffsetPtr)
+    return createStringError(
+        std::make_error_code(std::errc::invalid_argument),
+        "Cannot read a typed event record type field at offset %d.", OffsetPtr);
+
+  assert(OffsetPtr > BeginOffset &&
+         OffsetPtr - BeginOffset <= MetadataRecord::kMetadataBodySize);
+  OffsetPtr += MetadataRecord::kMetadataBodySize - (OffsetPtr - BeginOffset);
+
+  // Next we read in a fixed chunk of data from the given offset.
+  if (!E.isValidOffsetForDataOfSize(OffsetPtr, R.Size))
+    return createStringError(
+        std::make_error_code(std::errc::bad_address),
+        "Cannot read %d bytes of custom event data from offset %d.", R.Size,
+        OffsetPtr);
+
+  std::vector<uint8_t> Buffer;
+  Buffer.resize(R.Size);
+  if (E.getU8(&OffsetPtr, Buffer.data(), R.Size) != Buffer.data())
+    return createStringError(
+        std::make_error_code(std::errc::invalid_argument),
+        "Failed reading data into buffer of size %d at offset %d.", R.Size,
+        OffsetPtr);
+  R.Data.assign(Buffer.begin(), Buffer.end());
+  return Error::success();
+}
+
 Error RecordInitializer::visit(CallArgRecord &R) {
   if (!E.isValidOffsetForDataOfSize(OffsetPtr,
                                     MetadataRecord::kMetadataBodySize))
index 61a292cef85e4c6cadbf450ba3ed681f44115e5e..71ea7d0e969f0f9ef470a467871beead2b3524b4 100644 (file)
@@ -42,6 +42,21 @@ Error RecordPrinter::visit(CustomEventRecord &R) {
   return Error::success();
 }
 
+Error RecordPrinter::visit(CustomEventRecordV5 &R) {
+  OS << formatv("<Custom Event: delta = +{0}, size = {1}, data = '{2}'>",
+                R.delta(), R.size(), R.data())
+     << Delim;
+  return Error::success();
+}
+
+Error RecordPrinter::visit(TypedEventRecord &R) {
+  OS << formatv(
+            "<Typed Event: delta = +{0}, type = {1}, size = {2}, data = '{3}'",
+            R.delta(), R.eventType(), R.size(), R.data())
+     << Delim;
+  return Error::success();
+}
+
 Error RecordPrinter::visit(CallArgRecord &R) {
   OS << formatv("<Call Argument: data = {0} (hex = {0:x})>", R.arg()) << Delim;
   return Error::success();
index 37cd147078e51d6a8938d740d175ba0cdbd5c8ac..4f28f3f754c1ffaf27522e73d8759def033793c4 100644 (file)
@@ -247,6 +247,17 @@ Error loadNaiveFormatLog(StringRef Data, bool IsLittleEndian,
 /// ThreadBuffer: BufferExtents NewBuffer WallClockTime Pid NewCPUId
 ///               FunctionSequence
 /// EOB: *deprecated*
+///
+/// In Version 4, we make the following changes:
+///
+/// CustomEventRecord now includes the CPU data.
+///
+/// In Version 5, we make the following changes:
+///
+/// CustomEventRecord and TypedEventRecord now use TSC delta encoding similar to
+/// what FunctionRecord instances use, and we no longer need to include the CPU
+/// id in the CustomEventRecord.
+///
 Error loadFDRLog(StringRef Data, bool IsLittleEndian,
                  XRayFileHeader &FileHeader, std::vector<XRayRecord> &Records) {
 
@@ -435,7 +446,7 @@ Expected<Trace> llvm::xray::loadTrace(const DataExtractor &DE, bool Sort) {
     }
     break;
   case FLIGHT_DATA_RECORDER_FORMAT:
-    if (Version >= 1 && Version <= 4) {
+    if (Version >= 1 && Version <= 5) {
       if (auto E = loadFDRLog(DE.getData(), DE.isLittleEndian(), T.FileHeader,
                               T.Records))
         return std::move(E);
index 1cce1c2b2c17e01dfbdc4a347371b21ee04b420b..86b478a5a4588eabca303272de206e2844284e4d 100644 (file)
@@ -34,6 +34,8 @@ TEST(XRayFDRTest, BuilderAndBlockIndexer) {
                     .add<PIDRecord>(1)
                     .add<FunctionRecord>(RecordTypes::ENTER, 1, 1)
                     .add<FunctionRecord>(RecordTypes::EXIT, 1, 100)
+                    .add<CustomEventRecordV5>(1, 4, "XRAY")
+                    .add<TypedEventRecord>(1, 4, 2, "XRAY")
                     .consume();
   auto Block1 = LogBuilder()
                     .add<BufferExtents>(100)
@@ -42,6 +44,8 @@ TEST(XRayFDRTest, BuilderAndBlockIndexer) {
                     .add<PIDRecord>(1)
                     .add<FunctionRecord>(RecordTypes::ENTER, 1, 1)
                     .add<FunctionRecord>(RecordTypes::EXIT, 1, 100)
+                    .add<CustomEventRecordV5>(1, 4, "XRAY")
+                    .add<TypedEventRecord>(1, 4, 2, "XRAY")
                     .consume();
   auto Block2 = LogBuilder()
                     .add<BufferExtents>(100)
@@ -50,6 +54,8 @@ TEST(XRayFDRTest, BuilderAndBlockIndexer) {
                     .add<PIDRecord>(1)
                     .add<FunctionRecord>(RecordTypes::ENTER, 1, 1)
                     .add<FunctionRecord>(RecordTypes::EXIT, 1, 100)
+                    .add<CustomEventRecordV5>(1, 4, "XRAY")
+                    .add<TypedEventRecord>(1, 4, 2, "XRAY")
                     .consume();
   BlockIndexer::Index Index;
   BlockIndexer Indexer(Index);
@@ -92,6 +98,8 @@ TEST(XRayFDRTest, IndexAndVerifyBlocks) {
                     .add<NewCPUIDRecord>(1, 2)
                     .add<FunctionRecord>(RecordTypes::ENTER, 1, 1)
                     .add<FunctionRecord>(RecordTypes::EXIT, 1, 100)
+                    .add<CustomEventRecordV5>(1, 4, "XRAY")
+                    .add<TypedEventRecord>(1, 4, 2, "XRAY")
                     .consume();
   auto Block1 = LogBuilder()
                     .add<BufferExtents>(64)
@@ -101,6 +109,8 @@ TEST(XRayFDRTest, IndexAndVerifyBlocks) {
                     .add<NewCPUIDRecord>(1, 2)
                     .add<FunctionRecord>(RecordTypes::ENTER, 1, 1)
                     .add<FunctionRecord>(RecordTypes::EXIT, 1, 100)
+                    .add<CustomEventRecordV5>(1, 4, "XRAY")
+                    .add<TypedEventRecord>(1, 4, 2, "XRAY")
                     .consume();
   auto Block2 = LogBuilder()
                     .add<BufferExtents>(64)
@@ -110,6 +120,8 @@ TEST(XRayFDRTest, IndexAndVerifyBlocks) {
                     .add<NewCPUIDRecord>(1, 2)
                     .add<FunctionRecord>(RecordTypes::ENTER, 1, 1)
                     .add<FunctionRecord>(RecordTypes::EXIT, 1, 100)
+                    .add<CustomEventRecordV5>(1, 4, "XRAY")
+                    .add<TypedEventRecord>(1, 4, 2, "XRAY")
                     .consume();
 
   // First, index the records in different blocks.