Index: compiler-rt/lib/xray/tests/unit/fdr_logging_test.cc =================================================================== --- compiler-rt/lib/xray/tests/unit/fdr_logging_test.cc +++ compiler-rt/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" @@ -51,7 +53,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); @@ -73,7 +75,7 @@ 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 @@ -89,7 +91,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); @@ -113,7 +115,7 @@ 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; @@ -121,5 +123,54 @@ ASSERT_EQ(MDR0.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. + const char *Contents = static_cast( + mmap(NULL, Size, PROT_READ, MAP_PRIVATE, Fd, 0)); + 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; + memcpy(&MDR0, Contents + sizeof(XRayFileHeader), sizeof(MetadataRecord)); + ASSERT_EQ(MDR0.RecordKind, uint8_t(MetadataRecord::RecordKinds::NewBuffer)); + pid_t Latest = 0; + memcpy(&Latest, MDR0.Data, sizeof(pid_t)); + ASSERT_EQ(Latest, Threads[1]); +} + } // namespace } // namespace __xray Index: compiler-rt/lib/xray/xray_buffer_queue.cc =================================================================== --- compiler-rt/lib/xray/xray_buffer_queue.cc +++ compiler-rt/lib/xray/xray_buffer_queue.cc @@ -53,6 +53,7 @@ auto &T = *Next; auto &B = T.Buff; Buf = B; + T.Used = true; ++LiveBuffers; if (++Next == (Buffers + BufferCount)) Next = Buffers; Index: compiler-rt/lib/xray/xray_fdr_log_records.h =================================================================== --- compiler-rt/lib/xray/xray_fdr_log_records.h +++ compiler-rt/lib/xray/xray_fdr_log_records.h @@ -31,6 +31,7 @@ WalltimeMarker, CustomEventMarker, CallArgument, + BufferExtents, }; // Use 7 bits to identify this record type. /* RecordKinds */ uint8_t RecordKind : 7; Index: compiler-rt/lib/xray/xray_fdr_logging.cc =================================================================== --- compiler-rt/lib/xray/xray_fdr_logging.cc +++ compiler-rt/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,27 @@ 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 write out the file in the following format: // @@ -94,34 +99,37 @@ 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 know that the + // third metadata record for every buffer must be a MetadataRecord + // identifying how many bytes from the start of the buffer should be + // recorded, so we read that record and use that as the number of bytes we + // ought to write. + auto &ExtentsRecord = reinterpret_cast(B.Buffer)[2]; + size_t BufferSize = 0; + std::memcpy(&BufferSize, ExtentsRecord.Data, sizeof(size_t)); + assert(BufferSize <= B.Size); + if (BufferSize > 0) retryingWriteAll(Fd, reinterpret_cast(B.Buffer), - reinterpret_cast(B.Buffer) + B.Size); - } + reinterpret_cast(B.Buffer) + BufferSize); }); - // 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 +141,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 +166,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 +185,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 +217,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 +235,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 +248,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 +256,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 +274,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,12 +304,21 @@ } 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; } @@ -305,7 +332,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/lib/xray/xray_fdr_logging_impl.h =================================================================== --- compiler-rt/lib/xray/xray_fdr_logging_impl.h +++ compiler-rt/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" @@ -57,39 +55,19 @@ /// 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); +static void writeNewBufferPreamble(pid_t Tid, timespec TS); /// Writes a Function Record to MemPtr and increments MemPtr. Bypasses the /// thread local state machine and writes the function record directly to /// memory. 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,11 +97,19 @@ // 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; + + // The number of bytes that have been written to the buffer. + size_t Extents = 0; + + // This points to the Extents record we've written at the beginning of the + // buffer, which should give us a way of tracking the number of *bytes* we've + // written to this particular buffer. + MetadataRecord *ExtentsRecord = 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); @@ -149,15 +135,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 +148,27 @@ // 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); + static_assert(alignof(ThreadLocalData) >= 64, + "ThreadLocalData must be cache line aligned."); + thread_local ThreadLocalData TLD; + static pthread_key_t Key; + static bool UNUSED Once = [] { + pthread_key_create(&Key, +[](void *) { + if (TLD.BQ != nullptr) { + auto EC = TLD.BQ->releaseBuffer(TLD.Buffer); if (EC != BufferQueue::ErrorCode::Ok) - Report("Failed to release buffer at %p; error=%s\n", Buffer.Buffer, - BufferQueue::getErrorString(EC)); - Buffers = nullptr; - return; + Report("At thread exit, failed to release buffer at %p; error=%s\n", + TLD.Buffer.Buffer, BufferQueue::getErrorString(EC)); } }); - if (result != 0) { - Report("Failed to allocate thread-local data through pthread; error=%d", - result); - return false; - } - pthread_setspecific(key, &TLSBuffer); - return true; + return false; }(); - - return *reinterpret_cast(TLSBuffer); + thread_local bool UNUSED ThreadOnce = [] { + pthread_setspecific(Key, &TLD); + return false; + }(); + return TLD; } //-----------------------------------------------------------------------------| @@ -253,27 +205,27 @@ } // namespace -inline void writeNewBufferPreamble(pid_t Tid, timespec TS, - char *&MemPtr) XRAY_NEVER_INSTRUMENT { - static constexpr int InitRecordsCount = 2; - alignas(alignof(MetadataRecord)) unsigned char - Records[InitRecordsCount * MetadataRecSize]; +static void writeNewBufferPreamble(pid_t Tid, + timespec TS) XRAY_NEVER_INSTRUMENT { + static constexpr int InitRecordsCount = 3; + auto &TLD = getThreadLocalData(); + MetadataRecord Records[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 = Records[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 = Records[1]; WalltimeMarker.Type = uint8_t(RecordType::Metadata); WalltimeMarker.RecordKind = uint8_t(MetadataRecord::RecordKinds::WalltimeMarker); @@ -286,30 +238,64 @@ 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(); + + // As of version 2 of the FDR log, we use a metadata record to also keep track + // of the extents of the log. + { + auto &ExtentsRecord = Records[2]; + ExtentsRecord.Type = uint8_t(RecordType::Metadata); + ExtentsRecord.RecordKind = + uint8_t(MetadataRecord::RecordKinds::BufferExtents); + + // For now we assume we're going to write the size of the three records + // (including this record) as the extent of this buffer. + constexpr size_t Extent = sizeof(MetadataRecord) * 3; + std::memcpy(ExtentsRecord.Data, &Extent, sizeof(Extent)); + } + TLD.NumConsecutiveFnEnters = 0; TLD.NumTailCalls = 0; + + // We need to keep track of the record holding the extents, because we're + // going to be updating that regularly, everytime we write new records. + TLD.Extents = sizeof(MetadataRecord) * 3; + if (TLD.BQ && !TLD.BQ->finalizing()) { + std::memcpy(TLD.RecordPtr, Records, + sizeof(MetadataRecord) * InitRecordsCount); + TLD.ExtentsRecord = reinterpret_cast(TLD.RecordPtr) + 2; + TLD.RecordPtr += sizeof(MetadataRecord) * InitRecordsCount; + } } 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(); + TLD.Extents += Add; + std::memcpy(TLD.ExtentsRecord->Data, &TLD.Extents, sizeof(TLD.Extents)); +} + +static void decrementExtents(size_t Subtract) { + auto &TLD = getThreadLocalData(); + assert(TLD.Extents > Subtract); + TLD.Extents -= Subtract; + std::memcpy(TLD.ExtentsRecord->Data, &TLD.Extents, sizeof(TLD.Extents)); +} + +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 +307,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 +324,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 +342,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 +402,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 +422,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 +476,7 @@ RewindingTSC -= ExpectedFunctionEntry.TSCDelta; TLD.RecordPtr -= 2 * FunctionRecSize; LastTSC = RewindingTSC; + decrementExtents(2 * FunctionRecSize); } } @@ -531,12 +497,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 +514,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 +527,11 @@ 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; + TLD.Extents = 0; + TLD.ExtentsRecord = 0; return false; } return false; @@ -577,7 +541,6 @@ __sanitizer::memory_order_acquire) != XRayLogInitStatus::XRAY_LOG_INITIALIZED || LBQ->finalizing()) { - writeEOBMetadata(); if (!releaseThreadLocalBuffer(*LBQ)) return false; TLD.RecordPtr = nullptr; @@ -650,11 +613,13 @@ 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; + TLD.Extents = 0; + TLD.ExtentsRecord = nullptr; } } @@ -666,10 +631,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 +651,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 +686,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 +731,7 @@ } } - writeFunctionRecord(FuncId, RecordTSCDelta, Entry, TLD.RecordPtr); + writeFunctionRecord(FuncId, RecordTSCDelta, Entry); if (Entry == XRayEntryType::LOG_ARGS_ENTRY) writeCallArgumentMetadata(Arg1); Index: llvm/lib/XRay/Trace.cpp =================================================================== --- llvm/lib/XRay/Trace.cpp +++ llvm/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"; } @@ -242,14 +245,27 @@ /// State transition when a WallTimeMarkerRecord is encountered. Error processFDRWallTimeRecord(FDRState &State, uint8_t RecordFirstByte, - DataExtractor &RecordExtractor) { + DataExtractor &RecordExtractor, + uint16_t Version) { if (State.Expects != FDRState::Token::WALLCLOCK_RECORD) return make_error( "Malformed log. Read Wallclock record kind out of sequence", 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. - State.Expects = FDRState::Token::NEW_CPU_ID_RECORD; + + // TODO: Someday, reconcile the TSC ticks to wall clock time for presentation + // purposes. For now, we're ignoring these records. + switch (Version) { + case 1: + State.Expects = FDRState::Token::NEW_CPU_ID_RECORD; + break; + case 2: + State.Expects = FDRState::Token::BUFFER_EXTENTS; + break; + default: + return make_error( + Twine("Malformed log; provided version unsupported: ") + Twine(Version), + std::make_error_code(std::errc::executable_format_error)); + } return Error::success(); } @@ -271,6 +287,17 @@ return Error::success(); } +/// State transition when an BufferExtents record is encountered. +Error processBufferExtents(FDRState &State, uint8_t RecordFirstByte, + DataExtractor &RecordExtractor, size_t &RecordSize, + size_t &BufferSize) { + uint32_t OffsetPtr = 1; // Read after the first byte. + BufferSize = RecordExtractor.getU64(&OffsetPtr); + RecordSize = 16; + State.Expects = FDRState::Token::NEW_CPU_ID_RECORD; + return Error::success(); +} + /// State transition when a CallArgumentRecord is encountered. Error processFDRCallArgumentRecord(FDRState &State, uint8_t RecordFirstByte, DataExtractor &RecordExtractor, @@ -292,10 +319,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, size_t &BufferSize) { // The remaining 7 bits are the RecordKind enum. uint8_t RecordKind = RecordFirstByte >> 1; switch (RecordKind) { @@ -305,6 +337,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; @@ -320,8 +356,8 @@ return E; break; case 4: // WallTimeMarker - if (auto E = - processFDRWallTimeRecord(State, RecordFirstByte, RecordExtractor)) + if (auto E = processFDRWallTimeRecord(State, RecordFirstByte, + RecordExtractor, Version)) return E; break; case 5: // CustomEventMarker @@ -334,6 +370,11 @@ RecordExtractor, Records)) return E; break; + case 7: // BufferExtents + if (auto E = processBufferExtents(State, RecordFirstByte, RecordExtractor, + RecordSize, BufferSize)) + 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: NewBuffer WallClockTime BufferExtents 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) @@ -488,8 +539,9 @@ bool isMetadataRecord = BitField & 0x01uL; if (isMetadataRecord) { RecordSize = 16; - if (auto E = processFDRMetadataRecord(State, BitField, RecordExtractor, - RecordSize, Records)) + if (auto E = processFDRMetadataRecord( + State, BitField, RecordExtractor, RecordSize, Records, + FileHeader.Version, State.CurrentBufferSize)) return E; } else { // Process Function Record RecordSize = 8; @@ -498,6 +550,15 @@ return E; } 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::NEW_BUFFER_RECORD_OR_EOF; + State.CurrentBufferSize = BufferSize; + State.CurrentBufferConsumed = 0; + } } // Having iterated over everything we've been given, we've either consumed @@ -579,6 +640,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 +656,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); }