[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

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 84850c1..7199c5c 100644 (file)
--- 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 81006a3..a0bad52 100644 (file)
--- 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 81d77f6..0d5ee2d 100644 (file)
--- 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;
   }