Index: compiler-rt/trunk/lib/xray/tests/unit/fdr_logging_test.cc =================================================================== --- compiler-rt/trunk/lib/xray/tests/unit/fdr_logging_test.cc +++ compiler-rt/trunk/lib/xray/tests/unit/fdr_logging_test.cc @@ -17,8 +17,10 @@ #include #include #include +#include #include #include +#include #include #include "xray/xray_records.h" @@ -34,14 +36,23 @@ : Fd(Fd), Filename(Filename) {} ~ScopedFileCloserAndDeleter() { + if (Map) + munmap(Map, Size); if (Fd) { close(Fd); unlink(Filename); } } + void registerMap(void *M, size_t S) { + Map = M; + Size = S; + } + int Fd; const char *Filename; + void *Map = nullptr; + size_t Size = 0; }; TEST(FDRLoggingTest, Simple) { @@ -51,7 +62,7 @@ Options.Fd = mkstemp(TmpFilename); ASSERT_NE(Options.Fd, -1); ASSERT_EQ(fdrLoggingInit(kBufferSize, kBufferMax, &Options, - sizeof(FDRLoggingOptions)), + sizeof(FDRLoggingOptions)), XRayLogInitStatus::XRAY_LOG_INITIALIZED); fdrLoggingHandleArg0(1, XRayEntryType::ENTRY); fdrLoggingHandleArg0(1, XRayEntryType::EXIT); @@ -67,20 +78,25 @@ auto Size = lseek(Fd, 0, SEEK_END); ASSERT_NE(Size, 0); // Map the file contents. - const char *Contents = static_cast( - mmap(NULL, Size, PROT_READ, MAP_PRIVATE, Fd, 0)); + void *Map = mmap(NULL, Size, PROT_READ, MAP_PRIVATE, Fd, 0); + const char *Contents = static_cast(Map); + Guard.registerMap(Map, Size); ASSERT_NE(Contents, nullptr); XRayFileHeader H; memcpy(&H, Contents, sizeof(XRayFileHeader)); - ASSERT_EQ(H.Version, 1); + ASSERT_EQ(H.Version, 2); ASSERT_EQ(H.Type, FileTypes::FDR_LOG); - // We require one buffer at least to have the "start of buffer" metadata - // record. - MetadataRecord MDR; - memcpy(&MDR, Contents + sizeof(XRayFileHeader), sizeof(MetadataRecord)); - ASSERT_EQ(MDR.RecordKind, uint8_t(MetadataRecord::RecordKinds::NewBuffer)); + // We require one buffer at least to have the "extents" metadata record, + // followed by the NewBuffer record. + MetadataRecord MDR0, MDR1; + memcpy(&MDR0, Contents + sizeof(XRayFileHeader), sizeof(MetadataRecord)); + memcpy(&MDR1, Contents + sizeof(XRayFileHeader) + sizeof(MetadataRecord), + sizeof(MetadataRecord)); + ASSERT_EQ(MDR0.RecordKind, + uint8_t(MetadataRecord::RecordKinds::BufferExtents)); + ASSERT_EQ(MDR1.RecordKind, uint8_t(MetadataRecord::RecordKinds::NewBuffer)); } TEST(FDRLoggingTest, Multiple) { @@ -89,7 +105,7 @@ Options.Fd = mkstemp(TmpFilename); ASSERT_NE(Options.Fd, -1); ASSERT_EQ(fdrLoggingInit(kBufferSize, kBufferMax, &Options, - sizeof(FDRLoggingOptions)), + sizeof(FDRLoggingOptions)), XRayLogInitStatus::XRAY_LOG_INITIALIZED); for (uint64_t I = 0; I < 100; ++I) { fdrLoggingHandleArg0(1, XRayEntryType::ENTRY); @@ -107,18 +123,77 @@ auto Size = lseek(Fd, 0, SEEK_END); ASSERT_NE(Size, 0); // Map the file contents. - const char *Contents = static_cast( - mmap(NULL, Size, PROT_READ, MAP_PRIVATE, Fd, 0)); + void *Map = mmap(NULL, Size, PROT_READ, MAP_PRIVATE, Fd, 0); + const char *Contents = static_cast(Map); + Guard.registerMap(Map, Size); + ASSERT_NE(Contents, nullptr); + + XRayFileHeader H; + memcpy(&H, Contents, sizeof(XRayFileHeader)); + ASSERT_EQ(H.Version, 2); + ASSERT_EQ(H.Type, FileTypes::FDR_LOG); + + MetadataRecord MDR0, MDR1; + memcpy(&MDR0, Contents + sizeof(XRayFileHeader), sizeof(MetadataRecord)); + memcpy(&MDR1, Contents + sizeof(XRayFileHeader) + sizeof(MetadataRecord), + sizeof(MetadataRecord)); + ASSERT_EQ(MDR0.RecordKind, + uint8_t(MetadataRecord::RecordKinds::BufferExtents)); + ASSERT_EQ(MDR1.RecordKind, uint8_t(MetadataRecord::RecordKinds::NewBuffer)); +} + +TEST(FDRLoggingTest, MultiThreadedCycling) { + FDRLoggingOptions Options; + char TmpFilename[] = "fdr-logging-test.XXXXXX"; + Options.Fd = mkstemp(TmpFilename); + ASSERT_NE(Options.Fd, -1); + ASSERT_EQ(fdrLoggingInit(kBufferSize, 1, &Options, sizeof(FDRLoggingOptions)), + XRayLogInitStatus::XRAY_LOG_INITIALIZED); + + // Now we want to create one thread, do some logging, then create another one, + // in succession and making sure that we're able to get thread records from + // the latest thread (effectively being able to recycle buffers). + std::array Threads; + for (uint64_t I = 0; I < 2; ++I) { + std::thread t{[I, &Threads] { + fdrLoggingHandleArg0(I + 1, XRayEntryType::ENTRY); + fdrLoggingHandleArg0(I + 1, XRayEntryType::EXIT); + Threads[I] = syscall(SYS_gettid); + }}; + t.join(); + } + ASSERT_EQ(fdrLoggingFinalize(), XRayLogInitStatus::XRAY_LOG_FINALIZED); + ASSERT_EQ(fdrLoggingFlush(), XRayLogFlushStatus::XRAY_LOG_FLUSHED); + + // To do this properly, we have to close the file descriptor then re-open the + // file for reading this time. + ASSERT_EQ(close(Options.Fd), 0); + int Fd = open(TmpFilename, O_RDONLY); + ASSERT_NE(-1, Fd); + ScopedFileCloserAndDeleter Guard(Fd, TmpFilename); + auto Size = lseek(Fd, 0, SEEK_END); + ASSERT_NE(Size, 0); + // Map the file contents. + void *Map = mmap(NULL, Size, PROT_READ, MAP_PRIVATE, Fd, 0); + const char *Contents = static_cast(Map); + Guard.registerMap(Map, Size); ASSERT_NE(Contents, nullptr); XRayFileHeader H; memcpy(&H, Contents, sizeof(XRayFileHeader)); - ASSERT_EQ(H.Version, 1); + ASSERT_EQ(H.Version, 2); ASSERT_EQ(H.Type, FileTypes::FDR_LOG); - MetadataRecord MDR0; + MetadataRecord MDR0, MDR1; memcpy(&MDR0, Contents + sizeof(XRayFileHeader), sizeof(MetadataRecord)); - ASSERT_EQ(MDR0.RecordKind, uint8_t(MetadataRecord::RecordKinds::NewBuffer)); + memcpy(&MDR1, Contents + sizeof(XRayFileHeader) + sizeof(MetadataRecord), + sizeof(MetadataRecord)); + ASSERT_EQ(MDR0.RecordKind, + uint8_t(MetadataRecord::RecordKinds::BufferExtents)); + ASSERT_EQ(MDR1.RecordKind, uint8_t(MetadataRecord::RecordKinds::NewBuffer)); + pid_t Latest = 0; + memcpy(&Latest, MDR1.Data, sizeof(pid_t)); + ASSERT_EQ(Latest, Threads[1]); } } // namespace Index: compiler-rt/trunk/lib/xray/xray_buffer_queue.h =================================================================== --- compiler-rt/trunk/lib/xray/xray_buffer_queue.h +++ compiler-rt/trunk/lib/xray/xray_buffer_queue.h @@ -28,9 +28,14 @@ /// trace collection. class BufferQueue { public: + struct alignas(64) BufferExtents { + __sanitizer::atomic_uint64_t Size; + }; + struct Buffer { void *Buffer = nullptr; size_t Size = 0; + BufferExtents* Extents; }; private: Index: compiler-rt/trunk/lib/xray/xray_buffer_queue.cc =================================================================== --- compiler-rt/trunk/lib/xray/xray_buffer_queue.cc +++ compiler-rt/trunk/lib/xray/xray_buffer_queue.cc @@ -21,24 +21,25 @@ using namespace __sanitizer; BufferQueue::BufferQueue(size_t B, size_t N, bool &Success) - : BufferSize(B), - Buffers(new BufferRep[N]()), - BufferCount(N), - Finalizing{0}, - OwnedBuffers(new void *[N]()), - Next(Buffers), - First(Buffers), + : BufferSize(B), Buffers(new BufferRep[N]()), BufferCount(N), Finalizing{0}, + OwnedBuffers(new void *[N]()), Next(Buffers), First(Buffers), LiveBuffers(0) { for (size_t i = 0; i < N; ++i) { auto &T = Buffers[i]; - void *Tmp = InternalAlloc(BufferSize); + void *Tmp = InternalAlloc(BufferSize, nullptr, 64); if (Tmp == nullptr) { Success = false; return; } + void *Extents = InternalAlloc(sizeof(BufferExtents), nullptr, 64); + if (Extents == nullptr) { + Success = false; + return; + } auto &Buf = T.Buff; Buf.Buffer = Tmp; Buf.Size = B; + Buf.Extents = reinterpret_cast(Extents); OwnedBuffers[i] = Tmp; } Success = true; @@ -48,14 +49,17 @@ if (__sanitizer::atomic_load(&Finalizing, __sanitizer::memory_order_acquire)) return ErrorCode::QueueFinalizing; __sanitizer::SpinMutexLock Guard(&Mutex); - if (LiveBuffers == BufferCount) return ErrorCode::NotEnoughMemory; + if (LiveBuffers == BufferCount) + return ErrorCode::NotEnoughMemory; auto &T = *Next; auto &B = T.Buff; Buf = B; + T.Used = true; ++LiveBuffers; - if (++Next == (Buffers + BufferCount)) Next = Buffers; + if (++Next == (Buffers + BufferCount)) + Next = Buffers; return ErrorCode::Ok; } @@ -69,13 +73,15 @@ break; } } - if (!Found) return ErrorCode::UnrecognizedBuffer; + if (!Found) + return ErrorCode::UnrecognizedBuffer; __sanitizer::SpinMutexLock Guard(&Mutex); // This points to a semantic bug, we really ought to not be releasing more // buffers than we actually get. - if (LiveBuffers == 0) return ErrorCode::NotEnoughMemory; + if (LiveBuffers == 0) + return ErrorCode::NotEnoughMemory; // Now that the buffer has been released, we mark it as "used". First->Buff = Buf; @@ -83,7 +89,8 @@ Buf.Buffer = nullptr; Buf.Size = 0; --LiveBuffers; - if (++First == (Buffers + BufferCount)) First = Buffers; + if (++First == (Buffers + BufferCount)) + First = Buffers; return ErrorCode::Ok; } @@ -100,6 +107,7 @@ auto &T = *I; auto &Buf = T.Buff; InternalFree(Buf.Buffer); + InternalFree(Buf.Extents); } delete[] Buffers; delete[] OwnedBuffers; Index: compiler-rt/trunk/lib/xray/xray_fdr_log_records.h =================================================================== --- compiler-rt/trunk/lib/xray/xray_fdr_log_records.h +++ compiler-rt/trunk/lib/xray/xray_fdr_log_records.h @@ -31,7 +31,9 @@ WalltimeMarker, CustomEventMarker, CallArgument, + BufferExtents, }; + // Use 7 bits to identify this record type. /* RecordKinds */ uint8_t RecordKind : 7; char Data[15]; Index: compiler-rt/trunk/lib/xray/xray_fdr_logging.cc =================================================================== --- compiler-rt/trunk/lib/xray/xray_fdr_logging.cc +++ compiler-rt/trunk/lib/xray/xray_fdr_logging.cc @@ -15,9 +15,9 @@ // //===----------------------------------------------------------------------===// #include "xray_fdr_logging.h" +#include #include #include -#include #include #include @@ -35,10 +35,7 @@ namespace __xray { // Global BufferQueue. -// NOTE: This is a pointer to avoid having to do atomic operations at -// initialization time. This is OK to leak as there will only be one bufferqueue -// for the runtime, initialized once through the fdrInit(...) sequence. -std::shared_ptr *BQ = nullptr; +BufferQueue *BQ = nullptr; __sanitizer::atomic_sint32_t LogFlushStatus = { XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING}; @@ -51,19 +48,37 @@ XRayLogFlushStatus fdrLoggingFlush() XRAY_NEVER_INSTRUMENT { if (__sanitizer::atomic_load(&LoggingStatus, __sanitizer::memory_order_acquire) != - XRayLogInitStatus::XRAY_LOG_FINALIZED) + XRayLogInitStatus::XRAY_LOG_FINALIZED) { + if (__sanitizer::Verbosity()) + Report("Not flushing log, implementation is not finalized.\n"); return XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING; + } s32 Result = XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING; if (!__sanitizer::atomic_compare_exchange_strong( &LogFlushStatus, &Result, XRayLogFlushStatus::XRAY_LOG_FLUSHING, - __sanitizer::memory_order_release)) + __sanitizer::memory_order_release)) { + + if (__sanitizer::Verbosity()) + Report("Not flushing log, implementation is still finalizing.\n"); return static_cast(Result); + } - // Make a copy of the BufferQueue pointer to prevent other threads that may be - // resetting it from blowing away the queue prematurely while we're dealing - // with it. - auto LocalBQ = *BQ; + if (BQ == nullptr) { + if (__sanitizer::Verbosity()) + Report("Cannot flush when global buffer queue is null.\n"); + return XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING; + } + + // We wait a number of microseconds to allow threads to see that we've + // finalised before attempting to flush the log. + struct timespec TS; + TS.tv_sec = flags()->xray_fdr_log_grace_period_us / 1000000; + TS.tv_nsec = (flags()->xray_fdr_log_grace_period_us % 1000000) * 1000; + struct timespec Rem; + while (clock_nanosleep(CLOCK_REALTIME, 0, &TS, &Rem) && + (Rem.tv_sec != 0 || Rem.tv_nsec != 0)) + TS = Rem; // We write out the file in the following format: // @@ -94,34 +109,44 @@ TSCSupported ? getTSCFrequency() : __xray::NanosecondsPerSecond; XRayFileHeader Header; - Header.Version = 1; + + // Version 2 of the log writes the extents of the buffer, instead of relying + // on an end-of-buffer record. + Header.Version = 2; Header.Type = FileTypes::FDR_LOG; Header.CycleFrequency = CycleFrequency; + // FIXME: Actually check whether we have 'constant_tsc' and 'nonstop_tsc' // before setting the values in the header. Header.ConstantTSC = 1; Header.NonstopTSC = 1; - Header.FdrData = FdrAdditionalHeaderData{LocalBQ->ConfiguredBufferSize()}; + Header.FdrData = FdrAdditionalHeaderData{BQ->ConfiguredBufferSize()}; retryingWriteAll(Fd, reinterpret_cast(&Header), reinterpret_cast(&Header) + sizeof(Header)); - LocalBQ->apply([&](const BufferQueue::Buffer &B) { - uint64_t BufferSize = B.Size; - if (BufferSize > 0) { + BQ->apply([&](const BufferQueue::Buffer &B) { + // Starting at version 2 of the FDR logging implementation, we only write + // the records identified by the extents of the buffer. We use the Extents + // from the Buffer and write that out as the first record in the buffer. + // We still use a Metadata record, but fill in the extents instead for the + // data. + MetadataRecord ExtentsRecord; + auto BufferExtents = __sanitizer::atomic_load( + &B.Extents->Size, __sanitizer::memory_order_acquire); + assert(BufferExtents <= B.Size); + ExtentsRecord.Type = uint8_t(RecordType::Metadata); + ExtentsRecord.RecordKind = + uint8_t(MetadataRecord::RecordKinds::BufferExtents); + std::memcpy(ExtentsRecord.Data, &BufferExtents, sizeof(BufferExtents)); + if (BufferExtents > 0) { + retryingWriteAll(Fd, reinterpret_cast(&ExtentsRecord), + reinterpret_cast(&ExtentsRecord) + + sizeof(MetadataRecord)); retryingWriteAll(Fd, reinterpret_cast(B.Buffer), - reinterpret_cast(B.Buffer) + B.Size); + reinterpret_cast(B.Buffer) + BufferExtents); } }); - // The buffer for this particular thread would have been finalised after - // we've written everything to disk, and we'd lose the thread's trace. - auto &TLD = __xray::__xray_fdr_internal::getThreadLocalData(); - if (TLD.Buffer.Buffer != nullptr) { - __xray::__xray_fdr_internal::writeEOBMetadata(); - auto Start = reinterpret_cast(TLD.Buffer.Buffer); - retryingWriteAll(Fd, Start, Start + TLD.Buffer.Size); - } - __sanitizer::atomic_store(&LogFlushStatus, XRayLogFlushStatus::XRAY_LOG_FLUSHED, __sanitizer::memory_order_release); @@ -133,12 +158,15 @@ if (!__sanitizer::atomic_compare_exchange_strong( &LoggingStatus, &CurrentStatus, XRayLogInitStatus::XRAY_LOG_FINALIZING, - __sanitizer::memory_order_release)) + __sanitizer::memory_order_release)) { + if (__sanitizer::Verbosity()) + Report("Cannot finalize log, implementation not initialized.\n"); return static_cast(CurrentStatus); + } // Do special things to make the log finalize itself, and not allow any more // operations to be performed until re-initialized. - (*BQ)->finalize(); + BQ->finalize(); __sanitizer::atomic_store(&LoggingStatus, XRayLogInitStatus::XRAY_LOG_FINALIZED, @@ -155,7 +183,8 @@ return static_cast(CurrentStatus); // Release the in-memory buffer queue. - BQ->reset(); + delete BQ; + BQ = nullptr; // Spin until the flushing status is flushed. s32 CurrentFlushingStatus = XRayLogFlushStatus::XRAY_LOG_FLUSHED; @@ -173,8 +202,8 @@ } struct TSCAndCPU { - uint64_t TSC; - unsigned char CPU; + uint64_t TSC = 0; + unsigned char CPU = 0; }; static TSCAndCPU getTimestamp() XRAY_NEVER_INSTRUMENT { @@ -205,15 +234,15 @@ void fdrLoggingHandleArg0(int32_t FuncId, XRayEntryType Entry) XRAY_NEVER_INSTRUMENT { auto TC = getTimestamp(); - __xray_fdr_internal::processFunctionHook(FuncId, Entry, TC.TSC, - TC.CPU, 0, clock_gettime, *BQ); + __xray_fdr_internal::processFunctionHook(FuncId, Entry, TC.TSC, TC.CPU, 0, + clock_gettime, BQ); } void fdrLoggingHandleArg1(int32_t FuncId, XRayEntryType Entry, uint64_t Arg) XRAY_NEVER_INSTRUMENT { auto TC = getTimestamp(); - __xray_fdr_internal::processFunctionHook( - FuncId, Entry, TC.TSC, TC.CPU, Arg, clock_gettime, *BQ); + __xray_fdr_internal::processFunctionHook(FuncId, Entry, TC.TSC, TC.CPU, Arg, + clock_gettime, BQ); } void fdrLoggingHandleCustomEvent(void *Event, @@ -223,10 +252,8 @@ auto &TSC = TC.TSC; auto &CPU = TC.CPU; RecursionGuard Guard{Running}; - if (!Guard) { - assert(Running && "RecursionGuard is buggy!"); + if (!Guard) return; - } if (EventSize > std::numeric_limits::max()) { using Empty = struct {}; static Empty Once = [&] { @@ -238,7 +265,7 @@ } int32_t ReducedEventSize = static_cast(EventSize); auto &TLD = getThreadLocalData(); - if (!isLogInitializedAndReady(TLD.LocalBQ, TSC, CPU, clock_gettime)) + if (!isLogInitializedAndReady(TLD.BQ, TSC, CPU, clock_gettime)) return; // Here we need to prepare the log to handle: @@ -246,7 +273,7 @@ // - The additional data we're going to write. Currently, that's the size of // the event we're going to dump into the log as free-form bytes. if (!prepareBuffer(TSC, CPU, clock_gettime, MetadataRecSize + EventSize)) { - TLD.LocalBQ = nullptr; + TLD.BQ = nullptr; return; } @@ -264,21 +291,29 @@ std::memcpy(TLD.RecordPtr, &CustomEvent, sizeof(CustomEvent)); TLD.RecordPtr += sizeof(CustomEvent); std::memcpy(TLD.RecordPtr, Event, ReducedEventSize); + incrementExtents(MetadataRecSize + EventSize); endBufferIfFull(); } XRayLogInitStatus fdrLoggingInit(std::size_t BufferSize, std::size_t BufferMax, void *Options, size_t OptionsSize) XRAY_NEVER_INSTRUMENT { - if (OptionsSize != sizeof(FDRLoggingOptions)) + if (OptionsSize != sizeof(FDRLoggingOptions)) { + if (__sanitizer::Verbosity()) + Report("Cannot initialize FDR logging; wrong size for options: %d\n", + OptionsSize); return static_cast(__sanitizer::atomic_load( &LoggingStatus, __sanitizer::memory_order_acquire)); + } s32 CurrentStatus = XRayLogInitStatus::XRAY_LOG_UNINITIALIZED; if (!__sanitizer::atomic_compare_exchange_strong( &LoggingStatus, &CurrentStatus, XRayLogInitStatus::XRAY_LOG_INITIALIZING, - __sanitizer::memory_order_release)) + __sanitizer::memory_order_release)) { + if (__sanitizer::Verbosity()) + Report("Cannot initialize already initialized implementation.\n"); return static_cast(CurrentStatus); + } { __sanitizer::SpinMutexLock Guard(&FDROptionsMutex); @@ -286,15 +321,37 @@ } bool Success = false; + + if (BQ != nullptr) { + delete BQ; + BQ = nullptr; + } + if (BQ == nullptr) - BQ = new std::shared_ptr(); + BQ = new BufferQueue(BufferSize, BufferMax, Success); - *BQ = std::make_shared(BufferSize, BufferMax, Success); if (!Success) { Report("BufferQueue init failed.\n"); + if (BQ != nullptr) { + delete BQ; + BQ = nullptr; + } return XRayLogInitStatus::XRAY_LOG_UNINITIALIZED; } + static bool UNUSED Once = [] { + pthread_key_create(&__xray_fdr_internal::Key, +[](void *) { + auto &TLD = __xray_fdr_internal::getThreadLocalData(); + if (TLD.BQ == nullptr) + return; + auto EC = TLD.BQ->releaseBuffer(TLD.Buffer); + if (EC != BufferQueue::ErrorCode::Ok) + Report("At thread exit, failed to release buffer at %p; error=%s\n", + TLD.Buffer.Buffer, BufferQueue::getErrorString(EC)); + }); + return false; + }(); + // Arg1 handler should go in first to avoid concurrent code accidentally // falling back to arg0 when it should have ran arg1. __xray_set_handler_arg1(fdrLoggingHandleArg1); @@ -305,7 +362,9 @@ __sanitizer::atomic_store(&LoggingStatus, XRayLogInitStatus::XRAY_LOG_INITIALIZED, __sanitizer::memory_order_release); - Report("XRay FDR init successful.\n"); + + if (__sanitizer::Verbosity()) + Report("XRay FDR init successful.\n"); return XRayLogInitStatus::XRAY_LOG_INITIALIZED; } Index: compiler-rt/trunk/lib/xray/xray_fdr_logging_impl.h =================================================================== --- compiler-rt/trunk/lib/xray/xray_fdr_logging_impl.h +++ compiler-rt/trunk/lib/xray/xray_fdr_logging_impl.h @@ -24,11 +24,9 @@ #include #include #include +#include #include -// FIXME: Implement analogues to std::shared_ptr and std::weak_ptr -#include - #include "sanitizer_common/sanitizer_common.h" #include "xray/xray_log_interface.h" #include "xray_buffer_queue.h" @@ -54,42 +52,19 @@ /// cooperation with xray_fdr_logging class, so be careful and think twice. namespace __xray_fdr_internal { -/// Writes the new buffer record and wallclock time that begin a buffer for a -/// thread to MemPtr and increments MemPtr. Bypasses the thread local state -/// machine and writes directly to memory without checks. -static void writeNewBufferPreamble(pid_t Tid, timespec TS, char *&MemPtr); - -/// Write a metadata record to switch to a new CPU to MemPtr and increments -/// MemPtr. Bypasses the thread local state machine and writes directly to -/// memory without checks. -static void writeNewCPUIdMetadata(uint16_t CPU, uint64_t TSC, char *&MemPtr); - -/// Writes an EOB metadata record to MemPtr and increments MemPtr. Bypasses the -/// thread local state machine and writes directly to memory without checks. -static void writeEOBMetadata(char *&MemPtr); - -/// Writes a TSC Wrap metadata record to MemPtr and increments MemPtr. Bypasses -/// the thread local state machine and directly writes to memory without checks. -static void writeTSCWrapMetadata(uint64_t TSC, char *&MemPtr); - -/// Writes a Function Record to MemPtr and increments MemPtr. Bypasses the -/// thread local state machine and writes the function record directly to -/// memory. +/// Writes the new buffer record and wallclock time that begin a buffer for the +/// current thread. +static void writeNewBufferPreamble(pid_t Tid, timespec TS); + +/// Writes a Function Record to the buffer associated with the current thread. static void writeFunctionRecord(int FuncId, uint32_t TSCDelta, - XRayEntryType EntryType, char *&MemPtr); + XRayEntryType EntryType); /// Sets up a new buffer in thread_local storage and writes a preamble. The /// wall_clock_reader function is used to populate the WallTimeRecord entry. static void setupNewBuffer(int (*wall_clock_reader)(clockid_t, struct timespec *)); -/// Called to record CPU time for a new CPU within the current thread. -static void writeNewCPUIdMetadata(uint16_t CPU, uint64_t TSC); - -/// Called to close the buffer when the thread exhausts the buffer or when the -/// thread exits (via a thread local variable destructor). -static void writeEOBMetadata(); - /// TSC Wrap records are written when a TSC delta encoding scheme overflows. static void writeTSCWrapMetadata(uint64_t TSC); @@ -119,15 +94,18 @@ // Make sure a thread that's ever called handleArg0 has a thread-local // live reference to the buffer queue for this particular instance of // FDRLogging, and that we're going to clean it up when the thread exits. - std::shared_ptr LocalBQ = nullptr; + BufferQueue *BQ = nullptr; }; -// Forward-declare, defined later. -static ThreadLocalData &getThreadLocalData(); +static_assert(std::is_trivially_destructible::value, + "ThreadLocalData must be trivially destructible"); static constexpr auto MetadataRecSize = sizeof(MetadataRecord); static constexpr auto FunctionRecSize = sizeof(FunctionRecord); +// Use a global pthread key to identify thread-local data for logging. +static pthread_key_t Key; + // This function will initialize the thread-local data structure used by the FDR // logging implementation and return a reference to it. The implementation // details require a bit of care to maintain. @@ -149,15 +127,9 @@ // ThreadLocalData struct. This data will be uninitialized memory by // design. // -// 2. Using pthread_once(...) to initialize the thread-local data structures -// on first use, for every thread. We don't use std::call_once so we don't -// have a reliance on the C++ runtime library. -// -// 3. Registering a cleanup function that gets run at the end of a thread's -// lifetime through pthread_create_key(...). The cleanup function would -// allow us to release the thread-local resources in a manner that would -// let the rest of the XRay runtime implementation handle the records -// written for this thread's active buffer. +// 2. Not requiring a thread exit handler/implementation, keeping the +// thread-local as purely a collection of references/data that do not +// require cleanup. // // We're doing this to avoid using a `thread_local` object that has a // non-trivial destructor, because the C++ runtime might call std::malloc(...) @@ -168,55 +140,15 @@ // critical section, calling a function that might be XRay instrumented (and // thus in turn calling into malloc by virtue of registration of the // thread_local's destructor). -// -// With the approach taken where, we attempt to avoid the potential for -// deadlocks by relying instead on pthread's memory management routines. static ThreadLocalData &getThreadLocalData() { - thread_local pthread_key_t key; - - // We need aligned, uninitialized storage for the TLS object which is - // trivially destructible. We're going to use this as raw storage and - // placement-new the ThreadLocalData object into it later. - alignas(alignof(ThreadLocalData)) thread_local unsigned char - TLSBuffer[sizeof(ThreadLocalData)]; - - // Ensure that we only actually ever do the pthread initialization once. - thread_local bool UNUSED Unused = [] { - new (&TLSBuffer) ThreadLocalData(); - auto result = pthread_key_create(&key, +[](void *) { - auto &TLD = *reinterpret_cast(&TLSBuffer); - auto &RecordPtr = TLD.RecordPtr; - auto &Buffers = TLD.LocalBQ; - auto &Buffer = TLD.Buffer; - if (RecordPtr == nullptr) - return; - - // We make sure that upon exit, a thread will write out the EOB - // MetadataRecord in the thread-local log, and also release the buffer - // to the queue. - assert((RecordPtr + MetadataRecSize) - - static_cast(Buffer.Buffer) >= - static_cast(MetadataRecSize)); - if (Buffers) { - writeEOBMetadata(); - auto EC = Buffers->releaseBuffer(Buffer); - if (EC != BufferQueue::ErrorCode::Ok) - Report("Failed to release buffer at %p; error=%s\n", Buffer.Buffer, - BufferQueue::getErrorString(EC)); - Buffers = nullptr; - return; - } - }); - if (result != 0) { - Report("Failed to allocate thread-local data through pthread; error=%d", - result); - return false; - } - pthread_setspecific(key, &TLSBuffer); - return true; + static_assert(alignof(ThreadLocalData) >= 64, + "ThreadLocalData must be cache line aligned."); + thread_local ThreadLocalData TLD; + thread_local bool UNUSED ThreadOnce = [] { + pthread_setspecific(Key, &TLD); + return false; }(); - - return *reinterpret_cast(TLSBuffer); + return TLD; } //-----------------------------------------------------------------------------| @@ -253,27 +185,27 @@ } // namespace -inline void writeNewBufferPreamble(pid_t Tid, timespec TS, - char *&MemPtr) XRAY_NEVER_INSTRUMENT { +static void writeNewBufferPreamble(pid_t Tid, + timespec TS) XRAY_NEVER_INSTRUMENT { static constexpr int InitRecordsCount = 2; - alignas(alignof(MetadataRecord)) unsigned char - Records[InitRecordsCount * MetadataRecSize]; + auto &TLD = getThreadLocalData(); + MetadataRecord Metadata[InitRecordsCount]; { // Write out a MetadataRecord to signify that this is the start of a new // buffer, associated with a particular thread, with a new CPU. For the // data, we have 15 bytes to squeeze as much information as we can. At this // point we only write down the following bytes: // - Thread ID (pid_t, 4 bytes) - auto &NewBuffer = *reinterpret_cast(Records); + auto &NewBuffer = Metadata[0]; NewBuffer.Type = uint8_t(RecordType::Metadata); NewBuffer.RecordKind = uint8_t(MetadataRecord::RecordKinds::NewBuffer); std::memcpy(&NewBuffer.Data, &Tid, sizeof(pid_t)); } + // Also write the WalltimeMarker record. { static_assert(sizeof(time_t) <= 8, "time_t needs to be at most 8 bytes"); - auto &WalltimeMarker = - *reinterpret_cast(Records + MetadataRecSize); + auto &WalltimeMarker = Metadata[1]; WalltimeMarker.Type = uint8_t(RecordType::Metadata); WalltimeMarker.RecordKind = uint8_t(MetadataRecord::RecordKinds::WalltimeMarker); @@ -286,30 +218,47 @@ std::memcpy(WalltimeMarker.Data, &Seconds, sizeof(Seconds)); std::memcpy(WalltimeMarker.Data + sizeof(Seconds), &Micros, sizeof(Micros)); } - std::memcpy(MemPtr, Records, sizeof(MetadataRecord) * InitRecordsCount); - MemPtr += sizeof(MetadataRecord) * InitRecordsCount; - auto &TLD = getThreadLocalData(); + TLD.NumConsecutiveFnEnters = 0; TLD.NumTailCalls = 0; + if (TLD.BQ == nullptr || TLD.BQ->finalizing()) + return; + std::memcpy(TLD.RecordPtr, Metadata, sizeof(Metadata)); + TLD.RecordPtr += sizeof(Metadata); + // Since we write out the extents as the first metadata record of the + // buffer, we need to write out the extents including the extents record. + __sanitizer::atomic_store(&TLD.Buffer.Extents->Size, sizeof(Metadata), + __sanitizer::memory_order_release); } inline void setupNewBuffer(int (*wall_clock_reader)( clockid_t, struct timespec *)) XRAY_NEVER_INSTRUMENT { auto &TLD = getThreadLocalData(); - auto &Buffer = TLD.Buffer; - auto &RecordPtr = TLD.RecordPtr; - RecordPtr = static_cast(Buffer.Buffer); + auto &B = TLD.Buffer; + TLD.RecordPtr = static_cast(B.Buffer); pid_t Tid = syscall(SYS_gettid); timespec TS{0, 0}; // This is typically clock_gettime, but callers have injection ability. wall_clock_reader(CLOCK_MONOTONIC, &TS); - writeNewBufferPreamble(Tid, TS, RecordPtr); + writeNewBufferPreamble(Tid, TS); TLD.NumConsecutiveFnEnters = 0; TLD.NumTailCalls = 0; } -inline void writeNewCPUIdMetadata(uint16_t CPU, uint64_t TSC, - char *&MemPtr) XRAY_NEVER_INSTRUMENT { +static void incrementExtents(size_t Add) { + auto &TLD = getThreadLocalData(); + __sanitizer::atomic_fetch_add(&TLD.Buffer.Extents->Size, Add, + __sanitizer::memory_order_acq_rel); +} + +static void decrementExtents(size_t Subtract) { + auto &TLD = getThreadLocalData(); + __sanitizer::atomic_fetch_sub(&TLD.Buffer.Extents->Size, Subtract, + __sanitizer::memory_order_acq_rel); +} + +inline void writeNewCPUIdMetadata(uint16_t CPU, + uint64_t TSC) XRAY_NEVER_INSTRUMENT { auto &TLD = getThreadLocalData(); MetadataRecord NewCPUId; NewCPUId.Type = uint8_t(RecordType::Metadata); @@ -321,35 +270,14 @@ // Total = 10 bytes. std::memcpy(&NewCPUId.Data, &CPU, sizeof(CPU)); std::memcpy(&NewCPUId.Data[sizeof(CPU)], &TSC, sizeof(TSC)); - std::memcpy(MemPtr, &NewCPUId, sizeof(MetadataRecord)); - MemPtr += sizeof(MetadataRecord); - TLD.NumConsecutiveFnEnters = 0; - TLD.NumTailCalls = 0; -} - -inline void writeNewCPUIdMetadata(uint16_t CPU, - uint64_t TSC) XRAY_NEVER_INSTRUMENT { - writeNewCPUIdMetadata(CPU, TSC, getThreadLocalData().RecordPtr); -} - -inline void writeEOBMetadata(char *&MemPtr) XRAY_NEVER_INSTRUMENT { - auto &TLD = getThreadLocalData(); - MetadataRecord EOBMeta; - EOBMeta.Type = uint8_t(RecordType::Metadata); - EOBMeta.RecordKind = uint8_t(MetadataRecord::RecordKinds::EndOfBuffer); - // For now we don't write any bytes into the Data field. - std::memcpy(MemPtr, &EOBMeta, sizeof(MetadataRecord)); - MemPtr += sizeof(MetadataRecord); + std::memcpy(TLD.RecordPtr, &NewCPUId, sizeof(MetadataRecord)); + TLD.RecordPtr += sizeof(MetadataRecord); TLD.NumConsecutiveFnEnters = 0; TLD.NumTailCalls = 0; + incrementExtents(sizeof(MetadataRecord)); } -inline void writeEOBMetadata() XRAY_NEVER_INSTRUMENT { - writeEOBMetadata(getThreadLocalData().RecordPtr); -} - -inline void writeTSCWrapMetadata(uint64_t TSC, - char *&MemPtr) XRAY_NEVER_INSTRUMENT { +inline void writeTSCWrapMetadata(uint64_t TSC) XRAY_NEVER_INSTRUMENT { auto &TLD = getThreadLocalData(); MetadataRecord TSCWrap; TSCWrap.Type = uint8_t(RecordType::Metadata); @@ -359,14 +287,11 @@ // - Full TSC (uint64_t, 8 bytes) // Total = 8 bytes. std::memcpy(&TSCWrap.Data, &TSC, sizeof(TSC)); - std::memcpy(MemPtr, &TSCWrap, sizeof(MetadataRecord)); - MemPtr += sizeof(MetadataRecord); + std::memcpy(TLD.RecordPtr, &TSCWrap, sizeof(MetadataRecord)); + TLD.RecordPtr += sizeof(MetadataRecord); TLD.NumConsecutiveFnEnters = 0; TLD.NumTailCalls = 0; -} - -inline void writeTSCWrapMetadata(uint64_t TSC) XRAY_NEVER_INSTRUMENT { - writeTSCWrapMetadata(TSC, getThreadLocalData().RecordPtr); + incrementExtents(sizeof(MetadataRecord)); } // Call Argument metadata records store the arguments to a function in the @@ -380,11 +305,12 @@ std::memcpy(CallArg.Data, &A, sizeof(A)); std::memcpy(TLD.RecordPtr, &CallArg, sizeof(MetadataRecord)); TLD.RecordPtr += sizeof(MetadataRecord); + incrementExtents(sizeof(MetadataRecord)); } -static inline void writeFunctionRecord(int FuncId, uint32_t TSCDelta, - XRayEntryType EntryType, - char *&MemPtr) XRAY_NEVER_INSTRUMENT { +static inline void +writeFunctionRecord(int FuncId, uint32_t TSCDelta, + XRayEntryType EntryType) XRAY_NEVER_INSTRUMENT { FunctionRecord FuncRecord; FuncRecord.Type = uint8_t(RecordType::Function); // Only take 28 bits of the function id. @@ -439,8 +365,9 @@ } } - std::memcpy(MemPtr, &FuncRecord, sizeof(FunctionRecord)); - MemPtr += sizeof(FunctionRecord); + std::memcpy(TLD.RecordPtr, &FuncRecord, sizeof(FunctionRecord)); + TLD.RecordPtr += sizeof(FunctionRecord); + incrementExtents(sizeof(FunctionRecord)); } static uint64_t thresholdTicks() { @@ -458,6 +385,7 @@ uint64_t &LastFunctionEntryTSC, int32_t FuncId) { auto &TLD = getThreadLocalData(); TLD.RecordPtr -= FunctionRecSize; + decrementExtents(FunctionRecSize); FunctionRecord FuncRecord; std::memcpy(&FuncRecord, TLD.RecordPtr, FunctionRecSize); assert(FuncRecord.RecordKind == @@ -511,6 +439,7 @@ RewindingTSC -= ExpectedFunctionEntry.TSCDelta; TLD.RecordPtr -= 2 * FunctionRecSize; LastTSC = RewindingTSC; + decrementExtents(2 * FunctionRecSize); } } @@ -531,12 +460,10 @@ size_t MaxSize) XRAY_NEVER_INSTRUMENT { auto &TLD = getThreadLocalData(); char *BufferStart = static_cast(TLD.Buffer.Buffer); - if ((TLD.RecordPtr + MaxSize) > - (BufferStart + TLD.Buffer.Size - MetadataRecSize)) { - writeEOBMetadata(); - if (!releaseThreadLocalBuffer(*TLD.LocalBQ)) + if ((TLD.RecordPtr + MaxSize) > (BufferStart + TLD.Buffer.Size)) { + if (!releaseThreadLocalBuffer(*TLD.BQ)) return false; - auto EC = TLD.LocalBQ->getBuffer(TLD.Buffer); + auto EC = TLD.BQ->getBuffer(TLD.Buffer); if (EC != BufferQueue::ErrorCode::Ok) { Report("Failed to acquire a buffer; error=%s\n", BufferQueue::getErrorString(EC)); @@ -550,10 +477,10 @@ return true; } -inline bool isLogInitializedAndReady( - std::shared_ptr &LBQ, uint64_t TSC, unsigned char CPU, - int (*wall_clock_reader)(clockid_t, - struct timespec *)) XRAY_NEVER_INSTRUMENT { +inline bool +isLogInitializedAndReady(BufferQueue *LBQ, uint64_t TSC, unsigned char CPU, + int (*wall_clock_reader)(clockid_t, struct timespec *)) + XRAY_NEVER_INSTRUMENT { // Bail out right away if logging is not initialized yet. // We should take the opportunity to release the buffer though. auto Status = __sanitizer::atomic_load(&LoggingStatus, @@ -563,11 +490,9 @@ if (TLD.RecordPtr != nullptr && (Status == XRayLogInitStatus::XRAY_LOG_FINALIZING || Status == XRayLogInitStatus::XRAY_LOG_FINALIZED)) { - writeEOBMetadata(); if (!releaseThreadLocalBuffer(*LBQ)) return false; TLD.RecordPtr = nullptr; - LBQ = nullptr; return false; } return false; @@ -577,7 +502,6 @@ __sanitizer::memory_order_acquire) != XRayLogInitStatus::XRAY_LOG_INITIALIZED || LBQ->finalizing()) { - writeEOBMetadata(); if (!releaseThreadLocalBuffer(*LBQ)) return false; TLD.RecordPtr = nullptr; @@ -650,9 +574,9 @@ inline void endBufferIfFull() XRAY_NEVER_INSTRUMENT { auto &TLD = getThreadLocalData(); auto BufferStart = static_cast(TLD.Buffer.Buffer); - if ((TLD.RecordPtr + MetadataRecSize) - BufferStart == MetadataRecSize) { - writeEOBMetadata(); - if (!releaseThreadLocalBuffer(*TLD.LocalBQ)) + if ((TLD.RecordPtr + MetadataRecSize) - BufferStart <= + ptrdiff_t{MetadataRecSize}) { + if (!releaseThreadLocalBuffer(*TLD.BQ)) return; TLD.RecordPtr = nullptr; } @@ -666,10 +590,11 @@ /// walk backward through its buffer and erase trivial functions to avoid /// polluting the log and may use the buffer queue to obtain or release a /// buffer. -inline void processFunctionHook( - int32_t FuncId, XRayEntryType Entry, uint64_t TSC, unsigned char CPU, - uint64_t Arg1, int (*wall_clock_reader)(clockid_t, struct timespec *), - const std::shared_ptr &BQ) XRAY_NEVER_INSTRUMENT { +inline void processFunctionHook(int32_t FuncId, XRayEntryType Entry, + uint64_t TSC, unsigned char CPU, uint64_t Arg1, + int (*wall_clock_reader)(clockid_t, + struct timespec *), + BufferQueue *BQ) XRAY_NEVER_INSTRUMENT { // Prevent signal handler recursion, so in case we're already in a log writing // mode and the signal handler comes in (and is also instrumented) then we // don't want to be clobbering potentially partial writes already happening in @@ -685,10 +610,10 @@ // In case the reference has been cleaned up before, we make sure we // initialize it to the provided BufferQueue. - if (TLD.LocalBQ == nullptr) - TLD.LocalBQ = BQ; + if (TLD.BQ == nullptr) + TLD.BQ = BQ; - if (!isLogInitializedAndReady(TLD.LocalBQ, TSC, CPU, wall_clock_reader)) + if (!isLogInitializedAndReady(TLD.BQ, TSC, CPU, wall_clock_reader)) return; // Before we go setting up writing new function entries, we need to be really @@ -720,16 +645,13 @@ // id" MetadataRecord before writing out the actual FunctionRecord. // 4. The second MetadataRecord is the optional function call argument. // - // - An End-of-Buffer (EOB) MetadataRecord is 16 bytes. - // - // So the math we need to do is to determine whether writing 24 bytes past the - // current pointer leaves us with enough bytes to write the EOB - // MetadataRecord. If we don't have enough space after writing as much as 24 - // bytes in the end of the buffer, we need to write out the EOB, get a new - // Buffer, set it up properly before doing any further writing. + // So the math we need to do is to determine whether writing 40 bytes past the + // current pointer exceeds the buffer's maximum size. If we don't have enough + // space to write 40 bytes in the buffer, we need get a new Buffer, set it up + // properly before doing any further writing. size_t MaxSize = FunctionRecSize + 2 * MetadataRecSize; if (!prepareBuffer(TSC, CPU, wall_clock_reader, MaxSize)) { - TLD.LocalBQ = nullptr; + TLD.BQ = nullptr; return; } @@ -768,7 +690,7 @@ } } - writeFunctionRecord(FuncId, RecordTSCDelta, Entry, TLD.RecordPtr); + writeFunctionRecord(FuncId, RecordTSCDelta, Entry); if (Entry == XRayEntryType::LOG_ARGS_ENTRY) writeCallArgumentMetadata(Arg1); Index: compiler-rt/trunk/lib/xray/xray_flags.inc =================================================================== --- compiler-rt/trunk/lib/xray/xray_flags.inc +++ compiler-rt/trunk/lib/xray/xray_flags.inc @@ -25,3 +25,7 @@ XRAY_FLAG(int, xray_fdr_log_func_duration_threshold_us, 5, "FDR logging will try to skip functions that execute for fewer " "microseconds than this threshold.") +XRAY_FLAG(int, xray_fdr_log_grace_period_us, 100000, + "FDR logging will wait this much time in microseconds before " + "actually flushing the log; this gives a chance for threads to " + "notice that the log has been finalized and clean up.") Index: llvm/trunk/lib/XRay/Trace.cpp =================================================================== --- llvm/trunk/lib/XRay/Trace.cpp +++ llvm/trunk/lib/XRay/Trace.cpp @@ -159,6 +159,7 @@ SCAN_TO_END_OF_THREAD_BUF, CUSTOM_EVENT_DATA, CALL_ARGUMENT, + BUFFER_EXTENTS, }; Token Expects; @@ -184,6 +185,8 @@ return "CUSTOM_EVENT_DATA"; case FDRState::Token::CALL_ARGUMENT: return "CALL_ARGUMENT"; + case FDRState::Token::BUFFER_EXTENTS: + return "BUFFER_EXTENTS"; } return "UNKNOWN"; } @@ -194,7 +197,9 @@ if (State.Expects != FDRState::Token::NEW_BUFFER_RECORD_OR_EOF) return make_error( - "Malformed log. Read New Buffer record kind out of sequence", + Twine("Malformed log. Read New Buffer record kind out of sequence; " + "expected: ") + + fdrStateToTwine(State.Expects), std::make_error_code(std::errc::executable_format_error)); uint32_t OffsetPtr = 1; // 1 byte into record. State.ThreadId = RecordExtractor.getU16(&OffsetPtr); @@ -207,7 +212,9 @@ DataExtractor &RecordExtractor) { if (State.Expects == FDRState::Token::NEW_BUFFER_RECORD_OR_EOF) return make_error( - "Malformed log. Received EOB message without current buffer.", + Twine("Malformed log. Received EOB message without current buffer; " + "expected: ") + + fdrStateToTwine(State.Expects), std::make_error_code(std::errc::executable_format_error)); State.Expects = FDRState::Token::SCAN_TO_END_OF_THREAD_BUF; return Error::success(); @@ -219,7 +226,9 @@ if (State.Expects != FDRState::Token::FUNCTION_SEQUENCE && State.Expects != FDRState::Token::NEW_CPU_ID_RECORD) return make_error( - "Malformed log. Read NewCPUId record kind out of sequence", + Twine("Malformed log. Read NewCPUId record kind out of sequence; " + "expected: ") + + fdrStateToTwine(State.Expects), std::make_error_code(std::errc::executable_format_error)); uint32_t OffsetPtr = 1; // Read starting after the first byte. State.CPUId = RecordExtractor.getU16(&OffsetPtr); @@ -233,7 +242,9 @@ DataExtractor &RecordExtractor) { if (State.Expects != FDRState::Token::FUNCTION_SEQUENCE) return make_error( - "Malformed log. Read TSCWrap record kind out of sequence", + Twine("Malformed log. Read TSCWrap record kind out of sequence; " + "expecting: ") + + fdrStateToTwine(State.Expects), std::make_error_code(std::errc::executable_format_error)); uint32_t OffsetPtr = 1; // Read starting after the first byte. State.BaseTSC = RecordExtractor.getU64(&OffsetPtr); @@ -245,10 +256,13 @@ DataExtractor &RecordExtractor) { if (State.Expects != FDRState::Token::WALLCLOCK_RECORD) return make_error( - "Malformed log. Read Wallclock record kind out of sequence", + Twine("Malformed log. Read Wallclock record kind out of sequence; " + "expecting: ") + + fdrStateToTwine(State.Expects), std::make_error_code(std::errc::executable_format_error)); - // We don't encode the wall time into any of the records. - // XRayRecords are concerned with the TSC instead. + + // TODO: Someday, reconcile the TSC ticks to wall clock time for presentation + // purposes. For now, we're ignoring these records. State.Expects = FDRState::Token::NEW_CPU_ID_RECORD; return Error::success(); } @@ -271,6 +285,20 @@ return Error::success(); } +/// State transition when an BufferExtents record is encountered. +Error processBufferExtents(FDRState &State, uint8_t RecordFirstByte, + DataExtractor &RecordExtractor) { + if (State.Expects != FDRState::Token::BUFFER_EXTENTS) + return make_error( + Twine("Malformed log. Buffer Extents unexpected; expected: ") + + fdrStateToTwine(State.Expects), + std::make_error_code(std::errc::executable_format_error)); + uint32_t OffsetPtr = 1; // Read after the first byte. + State.CurrentBufferSize = RecordExtractor.getU64(&OffsetPtr); + State.Expects = FDRState::Token::NEW_BUFFER_RECORD_OR_EOF; + return Error::success(); +} + /// State transition when a CallArgumentRecord is encountered. Error processFDRCallArgumentRecord(FDRState &State, uint8_t RecordFirstByte, DataExtractor &RecordExtractor, @@ -292,10 +320,15 @@ /// record encountered. The RecordKind is encoded in the first byte of the /// Record, which the caller should pass in because they have already read it /// to determine that this is a metadata record as opposed to a function record. +/// +/// Beginning with Version 2 of the FDR log, we do not depend on the size of the +/// buffer, but rather use the extents to determine how far to read in the log +/// for this particular buffer. Error processFDRMetadataRecord(FDRState &State, uint8_t RecordFirstByte, DataExtractor &RecordExtractor, size_t &RecordSize, - std::vector &Records) { + std::vector &Records, + uint16_t Version) { // The remaining 7 bits are the RecordKind enum. uint8_t RecordKind = RecordFirstByte >> 1; switch (RecordKind) { @@ -305,6 +338,10 @@ return E; break; case 1: // EndOfBuffer + if (Version >= 2) + return make_error( + "Since Version 2 of FDR logging, we no longer support EOB records.", + std::make_error_code(std::errc::executable_format_error)); if (auto E = processFDREndOfBufferRecord(State, RecordFirstByte, RecordExtractor)) return E; @@ -334,6 +371,10 @@ RecordExtractor, Records)) return E; break; + case 7: // BufferExtents + if (auto E = processBufferExtents(State, RecordFirstByte, RecordExtractor)) + return E; + break; default: // Widen the record type to uint16_t to prevent conversion to char. return make_error( @@ -425,7 +466,8 @@ /// convention that BitFields within a struct will first be packed into the /// least significant bits the address they belong to. /// -/// We expect a format complying with the grammar in the following pseudo-EBNF. +/// We expect a format complying with the grammar in the following pseudo-EBNF +/// in Version 1 of the FDR log. /// /// FDRLog: XRayFileHeader ThreadBuffer* /// XRayFileHeader: 32 bytes to identify the log as FDR with machine metadata. @@ -439,6 +481,15 @@ /// FunctionSequence: NewCPUId | TSCWrap | FunctionRecord /// TSCWrap: 16 byte metadata record with a full 64 bit TSC reading. /// FunctionRecord: 8 byte record with FunctionId, entry/exit, and TSC delta. +/// +/// In Version 2, we make the following changes: +/// +/// ThreadBuffer: BufferExtents NewBuffer WallClockTime NewCPUId +/// FunctionSequence +/// BufferExtents: 16 byte metdata record describing how many usable bytes are +/// in the buffer. This is measured from the start of the buffer +/// and must always be at least 48 (bytes). +/// EOB: *deprecated* Error loadFDRLog(StringRef Data, XRayFileHeader &FileHeader, std::vector &Records) { if (Data.size() < 32) @@ -464,8 +515,22 @@ uint32_t ExtraDataOffset = 0; BufferSize = ExtraDataExtractor.getU64(&ExtraDataOffset); } - FDRState State{0, 0, 0, FDRState::Token::NEW_BUFFER_RECORD_OR_EOF, - BufferSize, 0}; + + FDRState::Token InitialExpectation; + switch (FileHeader.Version) { + case 1: + InitialExpectation = FDRState::Token::NEW_BUFFER_RECORD_OR_EOF; + break; + case 2: + InitialExpectation = FDRState::Token::BUFFER_EXTENTS; + break; + default: + return make_error( + Twine("Unsupported version '") + Twine(FileHeader.Version) + "'", + std::make_error_code(std::errc::executable_format_error)); + } + FDRState State{0, 0, 0, InitialExpectation, BufferSize, 0}; + // RecordSize will tell the loop how far to seek ahead based on the record // type that we have just read. size_t RecordSize = 0; @@ -486,10 +551,13 @@ } uint8_t BitField = RecordExtractor.getU8(&OffsetPtr); bool isMetadataRecord = BitField & 0x01uL; + bool isBufferExtents = + (BitField >> 1) == 7; // BufferExtents record kind == 7 if (isMetadataRecord) { RecordSize = 16; - if (auto E = processFDRMetadataRecord(State, BitField, RecordExtractor, - RecordSize, Records)) + if (auto E = + processFDRMetadataRecord(State, BitField, RecordExtractor, + RecordSize, Records, FileHeader.Version)) return E; } else { // Process Function Record RecordSize = 8; @@ -497,14 +565,29 @@ Records)) return E; } - State.CurrentBufferConsumed += RecordSize; + + // The BufferExtents record is technically not part of the buffer, so we + // don't count the size of that record against the buffer's actual size. + if (!isBufferExtents) + State.CurrentBufferConsumed += RecordSize; + assert(State.CurrentBufferConsumed <= State.CurrentBufferSize); + if (FileHeader.Version == 2 && + State.CurrentBufferSize == State.CurrentBufferConsumed) { + // In Version 2 of the log, we don't need to scan to the end of the thread + // buffer if we've already consumed all the bytes we need to. + State.Expects = FDRState::Token::BUFFER_EXTENTS; + State.CurrentBufferSize = BufferSize; + State.CurrentBufferConsumed = 0; + } } // Having iterated over everything we've been given, we've either consumed // everything and ended up in the end state, or were told to skip the rest. bool Finished = State.Expects == FDRState::Token::SCAN_TO_END_OF_THREAD_BUF && State.CurrentBufferSize == State.CurrentBufferConsumed; - if (State.Expects != FDRState::Token::NEW_BUFFER_RECORD_OR_EOF && !Finished) + if ((State.Expects != FDRState::Token::NEW_BUFFER_RECORD_OR_EOF && + State.Expects != FDRState::Token::BUFFER_EXTENTS) && + !Finished) return make_error( Twine("Encountered EOF with unexpected state expectation ") + fdrStateToTwine(State.Expects) + @@ -579,6 +662,7 @@ // // 0x01 0x00 0x00 0x00 - version 1, "naive" format // 0x01 0x00 0x01 0x00 - version 1, "flight data recorder" format + // 0x02 0x00 0x01 0x00 - version 2, "flight data recorder" format // // YAML files don't typically have those first four bytes as valid text so we // try loading assuming YAML if we don't find these bytes. @@ -594,13 +678,29 @@ enum BinaryFormatType { NAIVE_FORMAT = 0, FLIGHT_DATA_RECORDER_FORMAT = 1 }; Trace T; - if (Type == NAIVE_FORMAT && (Version == 1 || Version == 2)) { - if (auto E = loadNaiveFormatLog(Data, T.FileHeader, T.Records)) - return std::move(E); - } else if (Version == 1 && Type == FLIGHT_DATA_RECORDER_FORMAT) { - if (auto E = loadFDRLog(Data, T.FileHeader, T.Records)) - return std::move(E); - } else { + switch (Type) { + case NAIVE_FORMAT: + if (Version == 1 || Version == 2) { + if (auto E = loadNaiveFormatLog(Data, T.FileHeader, T.Records)) + return std::move(E); + } else { + return make_error( + Twine("Unsupported version for Basic/Naive Mode logging: ") + + Twine(Version), + std::make_error_code(std::errc::executable_format_error)); + } + break; + case FLIGHT_DATA_RECORDER_FORMAT: + if (Version == 1 || Version == 2) { + if (auto E = loadFDRLog(Data, T.FileHeader, T.Records)) + return std::move(E); + } else { + return make_error( + Twine("Unsupported version for FDR Mode logging: ") + Twine(Version), + std::make_error_code(std::errc::executable_format_error)); + } + break; + default: if (auto E = loadYAMLLog(Data, T.FileHeader, T.Records)) return std::move(E); }