[XRay] Fix TSC and atomic custom/typed event accounting

Summary:
This is a follow-on change to D53858 which turns out to have had a TSC
accounting bug when writing out function exit records in FDR mode.

This change adds a number of tests to ensure that:

- We are handling the delta between the exit TSC and the last TSC we've
  seen.

- We are writing the custom event and typed event records as a single
  update to the buffer extents.

- We are able to catch boundary conditions when loading FDR logs.

We introduce a TSC matcher to the test helpers, which we use in the
testing/verification of the TSC accounting change.

Reviewers: mboerger

Subscribers: mgorny, hiraditya, jfb, llvm-commits

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

llvm-svn: 345905

4 files changed, 105 insertions, 2 deletions

diff --git a/compiler-rt/lib/xray/tests/CMakeLists.txt b/compiler-rt/lib/xray/tests/CMakeLists.txt
index 2f167e3aeb7..16fb129d3b2 100644
--- a/compiler-rt/lib/xray/tests/CMakeLists.txt
+++ b/compiler-rt/lib/xray/tests/CMakeLists.txt
@@ -93,6 +93,7 @@ macro(add_xray_unittest testname)
         # the build/test cycle.
         COMPILE_DEPS ${TEST_SOURCES} ${COMPILER_RT_GTEST_SOURCE}
         ${XRAY_HEADERS} ${XRAY_ALL_SOURCE_FILES_ABS_PATHS}
+        "test_helpers.h"
         RUNTIME "${XRAY_RUNTIME_LIBS}"
         DEPS gtest xray llvm-xray LLVMXRay LLVMTestingSupport
         CFLAGS ${XRAY_UNITTEST_CFLAGS}
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 30276c61f56..84850c182ff 100644
--- a/compiler-rt/lib/xray/tests/unit/fdr_controller_test.cc
+++ b/compiler-rt/lib/xray/tests/unit/fdr_controller_test.cc
@@ -33,10 +33,12 @@ using ::llvm::HasValue;
 using ::llvm::xray::testing::FuncId;
 using ::llvm::xray::testing::HasArg;
 using ::llvm::xray::testing::RecordType;
+using ::llvm::xray::testing::TSCIs;
 using ::testing::AllOf;
 using ::testing::ElementsAre;
 using ::testing::Eq;
 using ::testing::Field;
+using ::testing::Gt;
 using ::testing::IsEmpty;
 using ::testing::SizeIs;
 
@@ -110,6 +112,31 @@ TEST_F(FunctionSequenceTest, ArgsAreHandledAndKept) {
           AllOf(FuncId(1), RecordType(llvm::xray::RecordTypes::EXIT)))));
 }
 
+TEST_F(FunctionSequenceTest, PreservedCallsHaveCorrectTSC) {
+  C = llvm::make_unique<FDRController<>>(BQ.get(), B, *W, clock_gettime, 1000);
+  uint64_t TSC = 1;
+  uint16_t CPU = 0;
+  ASSERT_TRUE(C->functionEnter(1, TSC++, CPU));
+  ASSERT_TRUE(C->functionEnter(2, TSC++, CPU));
+  ASSERT_TRUE(C->functionExit(2, TSC++, CPU));
+  ASSERT_TRUE(C->functionExit(1, TSC += 1000, CPU));
+  ASSERT_TRUE(C->flush());
+  ASSERT_EQ(BQ->finalize(), BufferQueue::ErrorCode::Ok);
+
+  // Serialize the buffers then test to see if we find the remaining records,
+  // because the function entry-exit comes under the cycle threshold.
+  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(1000uL))))));
+}
+
 TEST_F(FunctionSequenceTest, RewindingMultipleCalls) {
   C = llvm::make_unique<FDRController<>>(BQ.get(), B, *W, clock_gettime, 1000);
 
@@ -211,6 +238,24 @@ TEST_F(BufferManagementTest, HandlesOverflow) {
   EXPECT_THAT_EXPECTED(TraceOrErr, HasValue(SizeIs(kBuffers * 2)));
 }
 
+TEST_F(BufferManagementTest, HandlesOverflowWithCustomEvents) {
+  uint64_t TSC = 1;
+  uint16_t CPU = 1;
+  int32_t D = 0x9009;
+  for (size_t I = 0; I < kBuffers; ++I) {
+    ASSERT_TRUE(C->functionEnter(1, TSC++, CPU));
+    ASSERT_TRUE(C->functionExit(1, TSC++, CPU));
+    ASSERT_TRUE(C->customEvent(TSC++, CPU, &D, sizeof(D)));
+  }
+  ASSERT_TRUE(C->flush());
+  ASSERT_THAT(BQ->finalize(), Eq(BufferQueue::ErrorCode::Ok));
+
+  std::string Serialized = serialize(*BQ, 3);
+  llvm::DataExtractor DE(Serialized, true, 8);
+  auto TraceOrErr = llvm::xray::loadTrace(DE);
+  EXPECT_THAT_EXPECTED(TraceOrErr, HasValue(SizeIs(kBuffers)));
+}
+
 TEST_F(BufferManagementTest, HandlesFinalizedBufferQueue) {
   uint64_t TSC = 1;
   uint16_t CPU = 1;
diff --git a/compiler-rt/lib/xray/tests/unit/fdr_log_writer_test.cc b/compiler-rt/lib/xray/tests/unit/fdr_log_writer_test.cc
index 1aeaf099d32..f2e7a5cba5d 100644
--- a/compiler-rt/lib/xray/tests/unit/fdr_log_writer_test.cc
+++ b/compiler-rt/lib/xray/tests/unit/fdr_log_writer_test.cc
@@ -29,10 +29,11 @@ static constexpr size_t kSize = 4096;
 using ::llvm::HasValue;
 using ::llvm::xray::testing::FuncId;
 using ::llvm::xray::testing::RecordType;
-using ::testing::Eq;
 using ::testing::AllOf;
-using ::testing::IsEmpty;
 using ::testing::ElementsAre;
+using ::testing::Eq;
+using ::testing::IsEmpty;
+using ::testing::IsNull;
 
 // Exercise the common code path where we initialize a buffer and are able to
 // write some records successfully.
@@ -73,6 +74,57 @@ TEST(FdrLogWriterTest, WriteSomeRecords) {
           AllOf(FuncId(1), RecordType(llvm::xray::RecordTypes::EXIT)))));
 }
 
+// Ensure that we can handle buffer re-use.
+TEST(FdrLogWriterTest, ReuseBuffers) {
+  bool Success = false;
+  BufferQueue Buffers(kSize, 1, Success);
+  BufferQueue::Buffer B;
+  ASSERT_EQ(Buffers.getBuffer(B), BufferQueue::ErrorCode::Ok);
+
+  FDRLogWriter Writer(B);
+  MetadataRecord Preamble[] = {
+      createMetadataRecord<MetadataRecord::RecordKinds::NewBuffer>(int32_t{1}),
+      createMetadataRecord<MetadataRecord::RecordKinds::WalltimeMarker>(
+          int64_t{1}, int32_t{2}),
+      createMetadataRecord<MetadataRecord::RecordKinds::Pid>(int32_t{1}),
+  };
+
+  // First we write the first set of records into the single buffer in the
+  // queue which includes one enter and one exit record.
+  ASSERT_THAT(Writer.writeMetadataRecords(Preamble),
+              Eq(sizeof(MetadataRecord) * 3));
+  ASSERT_TRUE(Writer.writeMetadata<MetadataRecord::RecordKinds::NewCPUId>(
+      uint16_t{1}, uint64_t{1}));
+  uint64_t TSC = 1;
+  ASSERT_TRUE(
+      Writer.writeFunction(FDRLogWriter::FunctionRecordKind::Enter, 1, TSC++));
+  ASSERT_TRUE(
+      Writer.writeFunction(FDRLogWriter::FunctionRecordKind::Exit, 1, TSC++));
+  ASSERT_EQ(Buffers.releaseBuffer(B), BufferQueue::ErrorCode::Ok);
+  ASSERT_THAT(B.Data, IsNull());
+
+  // Then we re-use the buffer, but only write one record.
+  ASSERT_EQ(Buffers.getBuffer(B), BufferQueue::ErrorCode::Ok);
+  Writer.resetRecord();
+  ASSERT_THAT(Writer.writeMetadataRecords(Preamble),
+              Eq(sizeof(MetadataRecord) * 3));
+  ASSERT_TRUE(Writer.writeMetadata<MetadataRecord::RecordKinds::NewCPUId>(
+      uint16_t{1}, uint64_t{1}));
+  ASSERT_TRUE(
+      Writer.writeFunction(FDRLogWriter::FunctionRecordKind::Enter, 1, TSC++));
+  ASSERT_EQ(Buffers.releaseBuffer(B), BufferQueue::ErrorCode::Ok);
+  ASSERT_THAT(B.Data, IsNull());
+  ASSERT_EQ(Buffers.finalize(), BufferQueue::ErrorCode::Ok);
+
+  // Then we validate that we only see the single enter record.
+  std::string Serialized = serialize(Buffers, 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)))));
+}
+
 TEST(FdrLogWriterTest, UnwriteRecords) {
   bool Success = false;
   BufferQueue Buffers(kSize, 1, Success);
diff --git a/compiler-rt/lib/xray/tests/unit/test_helpers.h b/compiler-rt/lib/xray/tests/unit/test_helpers.h
index 6c23ce413b9..ff0311e9bd3 100644
--- a/compiler-rt/lib/xray/tests/unit/test_helpers.h
+++ b/compiler-rt/lib/xray/tests/unit/test_helpers.h
@@ -47,6 +47,11 @@ MATCHER_P(HasArg, A, "") {
                      [this](decltype(A) V) { return V == A; });
 }
 
+MATCHER_P(TSCIs, M, std::string("TSC is ") + ::testing::PrintToString(M)) {
+  return ::testing::Matcher<decltype(arg.TSC)>(M).MatchAndExplain(
+      arg.TSC, result_listener);
+}
+
 } // namespace testing
 } // namespace xray
 } // namespace llvm