[XRay] Update delta computations in runtime

[dberris]

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.

[mboerger]

LGTM

compiler-rt/trunk/lib/xray/tests/unit/fdr_controller_test.cc

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(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);
 
   // First we construct an arbitrarily deep function enter/call stack.
   // We also ensure that we are in the same CPU.
   uint64_t TSC = 1;
   uint16_t CPU = 1;
   ASSERT_TRUE(C->functionEnter(1, TSC++, CPU));

compiler-rt/trunk/lib/xray/xray_fdr_controller.h

 //===-- xray_fdr_controller.h ---------------------------------------------===//
 //
 //                     The LLVM Compiler Infrastructure
 //
 // This file is distributed under the University of Illinois Open Source
 // License. See LICENSE.TXT for details.
 //
 //===----------------------------------------------------------------------===//
 //
 // This file is a part of XRay, a function call tracing system.
 //
 //===----------------------------------------------------------------------===//
 #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"
 #include "xray/xray_records.h"
 #include "xray_buffer_queue.h"
 #include "xray_fdr_log_writer.h"
 
 namespace __xray {
if (UNLIKELY(LatestCPU != CPU || LatestTSC == 0)) {
 
       if (B.Generation != BQ->generation())
         return PreambleResult::InvalidBuffer;
 
       W.writeMetadata<MetadataRecord::RecordKinds::NewCPUId>(CPU, TSC);
       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())
         return PreambleResult::InvalidBuffer;
 
       W.writeMetadata<MetadataRecord::RecordKinds::TSCWrap>(TSC);
       return PreambleResult::WroteMetadata;
     }
bool functionEnter(int32_t FuncId, uint64_t TSC,
 
     auto PreambleStatus = functionPreamble(TSC, CPU);
     if (PreambleStatus == PreambleResult::InvalidBuffer)
       return returnBuffer();
 
     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,
                         uint16_t CPU) XRAY_NEVER_INSTRUMENT {
     if (finalized())
       return returnBuffer();
 
     if (!prepareBuffer(sizeof(MetadataRecord) + sizeof(FunctionRecord)))
       return returnBuffer();
 
     auto PreambleStatus = functionPreamble(TSC, CPU);
     if (PreambleStatus == PreambleResult::InvalidBuffer)
       return returnBuffer();
 
     if (PreambleStatus == PreambleResult::NoChange &&
         UndoableFunctionEnters != 0 &&
         TSC - LastFunctionEntryTSC < CycleThreshold)
       return rewindRecords(FuncId, TSC, CPU);
 
     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,
                         uint64_t Arg) XRAY_NEVER_INSTRUMENT {
     if (finalized() ||
         !prepareBuffer((2 * sizeof(MetadataRecord)) + sizeof(FunctionRecord)) ||
         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);
   }
 
   bool functionExit(int32_t FuncId, uint64_t TSC,
                     uint16_t CPU) XRAY_NEVER_INSTRUMENT {
     if (finalized() ||
         !prepareBuffer(sizeof(MetadataRecord) + sizeof(FunctionRecord)))
       return returnBuffer();

llvm/trunk/lib/XRay/RecordPrinter.cpp

Error RecordPrinter::visit(EndBufferRecord &R) {
   OS << "<End of Buffer>" << Delim;
   return Error::success();
 }
 
 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;
   }
   OS << Delim;
   return Error::success();
 }
 
 } // namespace xray
 } // namespace llvm