[compiler-rt] r345905 - [XRay] Fix TSC and atomic custom/typed event accounting
Dean Michael Berris via llvm-commits
llvm-commits at lists.llvm.org
Thu Nov 1 15:57:51 PDT 2018
Author: dberris
Date: Thu Nov 1 15:57:50 2018
New Revision: 345905
URL: http://llvm.org/viewvc/llvm-project?rev=345905&view=rev
Log:
[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
Modified:
compiler-rt/trunk/lib/xray/tests/CMakeLists.txt
compiler-rt/trunk/lib/xray/tests/unit/fdr_controller_test.cc
compiler-rt/trunk/lib/xray/tests/unit/fdr_log_writer_test.cc
compiler-rt/trunk/lib/xray/tests/unit/test_helpers.h
compiler-rt/trunk/lib/xray/xray_fdr_controller.h
compiler-rt/trunk/lib/xray/xray_fdr_log_writer.h
Modified: compiler-rt/trunk/lib/xray/tests/CMakeLists.txt
URL: http://llvm.org/viewvc/llvm-project/compiler-rt/trunk/lib/xray/tests/CMakeLists.txt?rev=345905&r1=345904&r2=345905&view=diff
==============================================================================
--- compiler-rt/trunk/lib/xray/tests/CMakeLists.txt (original)
+++ compiler-rt/trunk/lib/xray/tests/CMakeLists.txt Thu Nov 1 15:57:50 2018
@@ -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}
Modified: compiler-rt/trunk/lib/xray/tests/unit/fdr_controller_test.cc
URL: http://llvm.org/viewvc/llvm-project/compiler-rt/trunk/lib/xray/tests/unit/fdr_controller_test.cc?rev=345905&r1=345904&r2=345905&view=diff
==============================================================================
--- compiler-rt/trunk/lib/xray/tests/unit/fdr_controller_test.cc (original)
+++ compiler-rt/trunk/lib/xray/tests/unit/fdr_controller_test.cc Thu Nov 1 15:57:50 2018
@@ -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, ArgsAreHand
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, HandlesOver
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;
Modified: compiler-rt/trunk/lib/xray/tests/unit/fdr_log_writer_test.cc
URL: http://llvm.org/viewvc/llvm-project/compiler-rt/trunk/lib/xray/tests/unit/fdr_log_writer_test.cc?rev=345905&r1=345904&r2=345905&view=diff
==============================================================================
--- compiler-rt/trunk/lib/xray/tests/unit/fdr_log_writer_test.cc (original)
+++ compiler-rt/trunk/lib/xray/tests/unit/fdr_log_writer_test.cc Thu Nov 1 15:57:50 2018
@@ -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);
Modified: compiler-rt/trunk/lib/xray/tests/unit/test_helpers.h
URL: http://llvm.org/viewvc/llvm-project/compiler-rt/trunk/lib/xray/tests/unit/test_helpers.h?rev=345905&r1=345904&r2=345905&view=diff
==============================================================================
--- compiler-rt/trunk/lib/xray/tests/unit/test_helpers.h (original)
+++ compiler-rt/trunk/lib/xray/tests/unit/test_helpers.h Thu Nov 1 15:57:50 2018
@@ -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
Modified: compiler-rt/trunk/lib/xray/xray_fdr_controller.h
URL: http://llvm.org/viewvc/llvm-project/compiler-rt/trunk/lib/xray/xray_fdr_controller.h?rev=345905&r1=345904&r2=345905&view=diff
==============================================================================
--- compiler-rt/trunk/lib/xray/xray_fdr_controller.h (original)
+++ compiler-rt/trunk/lib/xray/xray_fdr_controller.h Thu Nov 1 15:57:50 2018
@@ -310,11 +310,12 @@ public:
TSC - LastFunctionEntryTSC < CycleThreshold)
return rewindRecords(FuncId, TSC, CPU);
+ auto Delta = TSC - LatestTSC;
LatestTSC = TSC;
UndoableFunctionEnters = 0;
UndoableTailExits = 0;
return W.writeFunction(FDRLogWriter::FunctionRecordKind::Exit, mask(FuncId),
- TSC - LatestTSC);
+ Delta);
}
bool customEvent(uint64_t TSC, uint16_t CPU, const void *Event,
Modified: compiler-rt/trunk/lib/xray/xray_fdr_log_writer.h
URL: http://llvm.org/viewvc/llvm-project/compiler-rt/trunk/lib/xray/xray_fdr_log_writer.h?rev=345905&r1=345904&r2=345905&view=diff
==============================================================================
--- compiler-rt/trunk/lib/xray/xray_fdr_log_writer.h (original)
+++ compiler-rt/trunk/lib/xray/xray_fdr_log_writer.h Thu Nov 1 15:57:50 2018
@@ -112,20 +112,38 @@ public:
bool writeCustomEvent(uint64_t TSC, uint16_t CPU, const void *Event,
int32_t EventSize) {
- writeMetadata<MetadataRecord::RecordKinds::CustomEventMarker>(EventSize,
- TSC, CPU);
- internal_memcpy(NextRecord, Event, EventSize);
- NextRecord += EventSize;
- atomic_fetch_add(&Buffer.Extents, EventSize, memory_order_acq_rel);
+ // 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
+ // will only ever see the full metadata and custom event payload accounted
+ // (no partial writes accounted).
+ MetadataRecord R =
+ createMetadataRecord<MetadataRecord::RecordKinds::CustomEventMarker>(
+ EventSize, TSC, CPU);
+ NextRecord = reinterpret_cast<char *>(internal_memcpy(
+ NextRecord, reinterpret_cast<char *>(&R), sizeof(R))) +
+ sizeof(R);
+ NextRecord = reinterpret_cast<char *>(
+ internal_memcpy(NextRecord, Event, EventSize)) +
+ EventSize;
+ atomic_fetch_add(&Buffer.Extents, sizeof(R) + EventSize,
+ memory_order_acq_rel);
return true;
}
bool writeTypedEvent(uint64_t TSC, uint16_t EventType, const void *Event,
int32_t EventSize) {
- writeMetadata<MetadataRecord::RecordKinds::TypedEventMarker>(EventSize, TSC,
- EventType);
- internal_memcpy(NextRecord, Event, EventSize);
- NextRecord += EventSize;
+ // We do something similar when writing out typed events, see
+ // writeCustomEvent(...) above for details.
+ MetadataRecord R =
+ createMetadataRecord<MetadataRecord::RecordKinds::TypedEventMarker>(
+ EventSize, TSC, EventType);
+ NextRecord = reinterpret_cast<char *>(internal_memcpy(
+ NextRecord, reinterpret_cast<char *>(&R), sizeof(R))) +
+ sizeof(R);
+ NextRecord = reinterpret_cast<char *>(
+ internal_memcpy(NextRecord, Event, EventSize)) +
+ EventSize;
atomic_fetch_add(&Buffer.Extents, EventSize, memory_order_acq_rel);
return true;
}
More information about the llvm-commits
mailing list