Index: compiler-rt/trunk/lib/xray/tests/CMakeLists.txt =================================================================== --- compiler-rt/trunk/lib/xray/tests/CMakeLists.txt +++ compiler-rt/trunk/lib/xray/tests/CMakeLists.txt @@ -93,6 +93,7 @@ # 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} Index: compiler-rt/trunk/lib/xray/tests/unit/fdr_controller_test.cc =================================================================== --- compiler-rt/trunk/lib/xray/tests/unit/fdr_controller_test.cc +++ compiler-rt/trunk/lib/xray/tests/unit/fdr_controller_test.cc @@ -33,10 +33,12 @@ 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 @@ AllOf(FuncId(1), RecordType(llvm::xray::RecordTypes::EXIT))))); } +TEST_F(FunctionSequenceTest, PreservedCallsHaveCorrectTSC) { + C = llvm::make_unique>(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>(BQ.get(), B, *W, clock_gettime, 1000); @@ -211,6 +238,24 @@ 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; Index: compiler-rt/trunk/lib/xray/tests/unit/fdr_log_writer_test.cc =================================================================== --- compiler-rt/trunk/lib/xray/tests/unit/fdr_log_writer_test.cc +++ compiler-rt/trunk/lib/xray/tests/unit/fdr_log_writer_test.cc @@ -29,10 +29,11 @@ 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 @@ 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(int32_t{1}), + createMetadataRecord( + int64_t{1}, int32_t{2}), + createMetadataRecord(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( + 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( + 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); Index: compiler-rt/trunk/lib/xray/tests/unit/test_helpers.h =================================================================== --- compiler-rt/trunk/lib/xray/tests/unit/test_helpers.h +++ compiler-rt/trunk/lib/xray/tests/unit/test_helpers.h @@ -47,6 +47,11 @@ [this](decltype(A) V) { return V == A; }); } +MATCHER_P(TSCIs, M, std::string("TSC is ") + ::testing::PrintToString(M)) { + return ::testing::Matcher(M).MatchAndExplain( + arg.TSC, result_listener); +} + } // namespace testing } // namespace xray } // namespace llvm Index: compiler-rt/trunk/lib/xray/xray_fdr_controller.h =================================================================== --- compiler-rt/trunk/lib/xray/xray_fdr_controller.h +++ compiler-rt/trunk/lib/xray/xray_fdr_controller.h @@ -310,11 +310,12 @@ 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, Index: compiler-rt/trunk/lib/xray/xray_fdr_log_writer.h =================================================================== --- compiler-rt/trunk/lib/xray/xray_fdr_log_writer.h +++ compiler-rt/trunk/lib/xray/xray_fdr_log_writer.h @@ -112,20 +112,38 @@ bool writeCustomEvent(uint64_t TSC, uint16_t CPU, const void *Event, int32_t EventSize) { - writeMetadata(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( + EventSize, TSC, CPU); + NextRecord = reinterpret_cast(internal_memcpy( + NextRecord, reinterpret_cast(&R), sizeof(R))) + + sizeof(R); + NextRecord = reinterpret_cast( + 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(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( + EventSize, TSC, EventType); + NextRecord = reinterpret_cast(internal_memcpy( + NextRecord, reinterpret_cast(&R), sizeof(R))) + + sizeof(R); + NextRecord = reinterpret_cast( + internal_memcpy(NextRecord, Event, EventSize)) + + EventSize; atomic_fetch_add(&Buffer.Extents, EventSize, memory_order_acq_rel); return true; } Index: llvm/trunk/lib/XRay/FDRRecordProducer.cpp =================================================================== --- llvm/trunk/lib/XRay/FDRRecordProducer.cpp +++ llvm/trunk/lib/XRay/FDRRecordProducer.cpp @@ -84,6 +84,12 @@ // the rest of the bytes. auto PreReadOffset = OffsetPtr; uint8_t FirstByte = E.getU8(&OffsetPtr); + if (OffsetPtr == PreReadOffset) + return createStringError( + std::make_error_code(std::errc::executable_format_error), + "Failed reading one byte from offset %d.", OffsetPtr); + + // Set up our result record. std::unique_ptr R; // For metadata records, handle especially here.