[XRay] Update delta computations in runtime

Summary:
Fix some issues discovered from mostly manual inspection of outputs from
the `llvm-xray fdr-dump` tool.

It turns out we haven't been writing the deltas properly, and have been
writing down zeros for deltas of some records. This change fixes this
oversight born by the recent refactoring.

Reviewers: mboerger

Subscribers: llvm-commits, hiraditya

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

llvm-svn: 345954

3 files changed, 43 insertions, 9 deletions

diff --git a/compiler-rt/lib/xray/tests/unit/fdr_controller_test.cc b/compiler-rt/lib/xray/tests/unit/fdr_controller_test.cc
index 84850c182ff..7199c5c97fa 100644
--- a/compiler-rt/lib/xray/tests/unit/fdr_controller_test.cc
+++ b/compiler-rt/lib/xray/tests/unit/fdr_controller_test.cc
@@ -137,6 +137,30 @@ TEST_F(FunctionSequenceTest, PreservedCallsHaveCorrectTSC) {
                 TSCIs(Gt(1000uL))))));
 }
 
+TEST_F(FunctionSequenceTest, PreservedCallsSupportLargeDeltas) {
+  C = llvm::make_unique<FDRController<>>(BQ.get(), B, *W, clock_gettime, 1000);
+  uint64_t TSC = 1;
+  uint16_t CPU = 0;
+  const auto LargeDelta = uint64_t{std::numeric_limits<int32_t>::max()};
+  ASSERT_TRUE(C->functionEnter(1, TSC++, CPU));
+  ASSERT_TRUE(C->functionExit(1, TSC += LargeDelta, CPU));
+  ASSERT_TRUE(C->flush());
+  ASSERT_EQ(BQ->finalize(), BufferQueue::ErrorCode::Ok);
+
+  // Serialize the buffer then test to see if we find the right TSC with a large
+  // delta.
+  std::string Serialized = serialize(*BQ, 3);
+  llvm::DataExtractor DE(Serialized, true, 8);
+  auto TraceOrErr = llvm::xray::loadTrace(DE);
+  EXPECT_THAT_EXPECTED(
+      TraceOrErr,
+      HasValue(ElementsAre(
+          AllOf(FuncId(1), RecordType(llvm::xray::RecordTypes::ENTER),
+                TSCIs(Eq(1uL))),
+          AllOf(FuncId(1), RecordType(llvm::xray::RecordTypes::EXIT),
+                TSCIs(Gt(LargeDelta))))));
+}
+
 TEST_F(FunctionSequenceTest, RewindingMultipleCalls) {
   C = llvm::make_unique<FDRController<>>(BQ.get(), B, *W, clock_gettime, 1000);
 
diff --git a/compiler-rt/lib/xray/xray_fdr_controller.h b/compiler-rt/lib/xray/xray_fdr_controller.h
index 81006a3d957..a0bad520627 100644
--- a/compiler-rt/lib/xray/xray_fdr_controller.h
+++ b/compiler-rt/lib/xray/xray_fdr_controller.h
@@ -13,6 +13,7 @@
 #ifndef COMPILER_RT_LIB_XRAY_XRAY_FDR_CONTROLLER_H_
 #define COMPILER_RT_LIB_XRAY_XRAY_FDR_CONTROLLER_H_
 
+#include <limits>
 #include <time.h>
 
 #include "xray/xray_interface.h"
@@ -158,8 +159,14 @@ template <size_t Version = 3> class FDRController {
       return PreambleResult::WroteMetadata;
     }
 
-    if (UNLIKELY(LatestCPU == LatestCPU && LatestTSC > TSC)) {
-      // The TSC has wrapped around, from the last TSC we've seen.
+    DCHECK_EQ(LatestCPU, CPU);
+
+    if (UNLIKELY(LatestTSC > TSC ||
+                 TSC - LatestTSC >
+                     uint64_t{std::numeric_limits<int32_t>::max()})) {
+      // Either the TSC has wrapped around from the last TSC we've seen or the
+      // delta is too large to fit in a 32-bit signed integer, so we write a
+      // wrap-around record.
       LatestTSC = TSC;
 
       if (B.Generation != BQ->generation())
@@ -248,10 +255,11 @@ public:
     UndoableFunctionEnters = (PreambleStatus == PreambleResult::WroteMetadata)
                                  ? 1
                                  : UndoableFunctionEnters + 1;
+    auto Delta = TSC - LatestTSC;
     LastFunctionEntryTSC = TSC;
     LatestTSC = TSC;
     return W.writeFunction(FDRLogWriter::FunctionRecordKind::Enter,
-                           mask(FuncId), TSC - LatestTSC);
+                           mask(FuncId), Delta);
   }
 
   bool functionTailExit(int32_t FuncId, uint64_t TSC,
@@ -273,9 +281,10 @@ public:
 
     UndoableTailExits = UndoableFunctionEnters ? UndoableTailExits + 1 : 0;
     UndoableFunctionEnters = 0;
+    auto Delta = TSC - LatestTSC;
     LatestTSC = TSC;
     return W.writeFunction(FDRLogWriter::FunctionRecordKind::TailExit,
-                           mask(FuncId), TSC - LatestTSC);
+                           mask(FuncId), Delta);
   }
 
   bool functionEnterArg(int32_t FuncId, uint64_t TSC, uint16_t CPU,
@@ -285,13 +294,14 @@ public:
         functionPreamble(TSC, CPU) == PreambleResult::InvalidBuffer)
       return returnBuffer();
 
+    auto Delta = TSC - LatestTSC;
     LatestTSC = TSC;
     LastFunctionEntryTSC = 0;
     UndoableFunctionEnters = 0;
     UndoableTailExits = 0;
 
     W.writeFunction(FDRLogWriter::FunctionRecordKind::EnterArg, mask(FuncId),
-                    TSC - LatestTSC);
+                    Delta);
     return W.writeMetadata<MetadataRecord::RecordKinds::CallArgument>(Arg);
   }
 
diff --git a/llvm/lib/XRay/RecordPrinter.cpp b/llvm/lib/XRay/RecordPrinter.cpp
index 81d77f67cc1..0d5ee2de83d 100644
--- a/llvm/lib/XRay/RecordPrinter.cpp
+++ b/llvm/lib/XRay/RecordPrinter.cpp
@@ -66,19 +66,19 @@ Error RecordPrinter::visit(FunctionRecord &R) {
   // FIXME: Support symbolization here?
   switch (R.recordType()) {
   case RecordTypes::ENTER:
-    OS << formatv("<Function Enter: #{0} delta = +{0}>", R.functionId(),
+    OS << formatv("<Function Enter: #{0} delta = +{1}>", R.functionId(),
                   R.delta());
     break;
   case RecordTypes::ENTER_ARG:
-    OS << formatv("<Function Enter With Arg: #{0} delta = +{0}>",
+    OS << formatv("<Function Enter With Arg: #{0} delta = +{1}>",
                   R.functionId(), R.delta());
     break;
   case RecordTypes::EXIT:
-    OS << formatv("<Function Exit: #{0} delta = +{0}>", R.functionId(),
+    OS << formatv("<Function Exit: #{0} delta = +{1}>", R.functionId(),
                   R.delta());
     break;
   case RecordTypes::TAIL_EXIT:
-    OS << formatv("<Function Tail Exit: #{0} delta = +{0}>", R.functionId(),
+    OS << formatv("<Function Tail Exit: #{0} delta = +{1}>", R.functionId(),
                   R.delta());
     break;
   }