summaryrefslogtreecommitdiff
path: root/lib/xray/xray_fdr_logging_impl.h
diff options
context:
space:
mode:
authorDimitry Andric <dim@FreeBSD.org>2017-12-18 20:11:54 +0000
committerDimitry Andric <dim@FreeBSD.org>2017-12-18 20:11:54 +0000
commitcdf4f3055e964bb585f294cf77cb549ead82783f (patch)
tree7bceeca766b3fbe491245bc926a083f78c35d1de /lib/xray/xray_fdr_logging_impl.h
parent625108084a3ec7c19c7745004c5af0ed7aa417a9 (diff)
Notes
Diffstat (limited to 'lib/xray/xray_fdr_logging_impl.h')
-rw-r--r--lib/xray/xray_fdr_logging_impl.h605
1 files changed, 308 insertions, 297 deletions
diff --git a/lib/xray/xray_fdr_logging_impl.h b/lib/xray/xray_fdr_logging_impl.h
index 4a1d80fd0ebae..59eab55b2573c 100644
--- a/lib/xray/xray_fdr_logging_impl.h
+++ b/lib/xray/xray_fdr_logging_impl.h
@@ -18,13 +18,13 @@
#define XRAY_XRAY_FDR_LOGGING_IMPL_H
#include <cassert>
-#include <cstdint>
+#include <cstddef>
#include <cstring>
#include <limits>
-#include <memory>
-#include <string>
+#include <pthread.h>
#include <sys/syscall.h>
#include <time.h>
+#include <type_traits>
#include <unistd.h>
#include "sanitizer_common/sanitizer_common.h"
@@ -52,57 +52,104 @@ __sanitizer::atomic_sint32_t LoggingStatus = {
/// 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);
+/// Writes the new buffer record and wallclock time that begin a buffer for the
+/// current thread.
+static void writeNewBufferPreamble(pid_t Tid, timespec TS);
-/// 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 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);
-/// Here's where the meat of the processing happens. The writer captures
-/// function entry, exit and tail exit points with a time and will create
-/// TSCWrap, NewCPUId and Function records as necessary. The writer might
-/// 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.
-static void processFunctionHook(int32_t FuncId, XRayEntryType Entry,
- uint64_t TSC, unsigned char CPU,
- int (*wall_clock_reader)(clockid_t,
- struct timespec *),
- __sanitizer::atomic_sint32_t &LoggingStatus,
- const std::shared_ptr<BufferQueue> &BQ);
+// Group together thread-local-data in a struct, then hide it behind a function
+// call so that it can be initialized on first use instead of as a global. We
+// force the alignment to 64-bytes for x86 cache line alignment, as this
+// structure is used in the hot path of implementation.
+struct alignas(64) ThreadLocalData {
+ BufferQueue::Buffer Buffer;
+ char *RecordPtr = nullptr;
+ // The number of FunctionEntry records immediately preceding RecordPtr.
+ uint8_t NumConsecutiveFnEnters = 0;
+
+ // The number of adjacent, consecutive pairs of FunctionEntry, Tail Exit
+ // records preceding RecordPtr.
+ uint8_t NumTailCalls = 0;
+
+ // We use a thread_local variable to keep track of which CPUs we've already
+ // run, and the TSC times for these CPUs. This allows us to stop repeating the
+ // CPU field in the function records.
+ //
+ // We assume that we'll support only 65536 CPUs for x86_64.
+ uint16_t CurrentCPU = std::numeric_limits<uint16_t>::max();
+ uint64_t LastTSC = 0;
+ uint64_t LastFunctionEntryTSC = 0;
+
+ // 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.
+ BufferQueue *BQ = nullptr;
+};
+
+static_assert(std::is_trivially_destructible<ThreadLocalData>::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.
+//
+// First, some requirements on the implementation in general:
+//
+// - XRay handlers should not call any memory allocation routines that may
+// delegate to an instrumented implementation. This means functions like
+// malloc() and free() should not be called while instrumenting.
+//
+// - We would like to use some thread-local data initialized on first-use of
+// the XRay instrumentation. These allow us to implement unsynchronized
+// routines that access resources associated with the thread.
+//
+// The implementation here uses a few mechanisms that allow us to provide both
+// the requirements listed above. We do this by:
+//
+// 1. Using a thread-local aligned storage buffer for representing the
+// ThreadLocalData struct. This data will be uninitialized memory by
+// design.
+//
+// 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(...)
+// to register calls to destructors. Deadlocks may arise when, for example, an
+// externally provided malloc implementation is XRay instrumented, and
+// initializing the thread-locals involves calling into malloc. A malloc
+// implementation that does global synchronization might be holding a lock for a
+// 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).
+static ThreadLocalData &getThreadLocalData() {
+ 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 TLD;
+}
//-----------------------------------------------------------------------------|
// The rest of the file is implementation. |
@@ -113,71 +160,12 @@ static void processFunctionHook(int32_t FuncId, XRayEntryType Entry,
namespace {
-thread_local BufferQueue::Buffer Buffer;
-thread_local char *RecordPtr = nullptr;
-
-// The number of FunctionEntry records immediately preceding RecordPtr.
-thread_local uint8_t NumConsecutiveFnEnters = 0;
-
-// The number of adjacent, consecutive pairs of FunctionEntry, Tail Exit
-// records preceding RecordPtr.
-thread_local uint8_t NumTailCalls = 0;
-
-constexpr auto MetadataRecSize = sizeof(MetadataRecord);
-constexpr auto FunctionRecSize = sizeof(FunctionRecord);
-
-// We use a thread_local variable to keep track of which CPUs we've already
-// run, and the TSC times for these CPUs. This allows us to stop repeating the
-// CPU field in the function records.
-//
-// We assume that we'll support only 65536 CPUs for x86_64.
-thread_local uint16_t CurrentCPU = std::numeric_limits<uint16_t>::max();
-thread_local uint64_t LastTSC = 0;
-thread_local uint64_t LastFunctionEntryTSC = 0;
-
-class ThreadExitBufferCleanup {
- std::shared_ptr<BufferQueue> &Buffers;
- BufferQueue::Buffer &Buffer;
-
-public:
- explicit ThreadExitBufferCleanup(std::shared_ptr<BufferQueue> &BQ,
- BufferQueue::Buffer &Buffer)
- XRAY_NEVER_INSTRUMENT : Buffers(BQ),
- Buffer(Buffer) {}
-
- ~ThreadExitBufferCleanup() noexcept XRAY_NEVER_INSTRUMENT {
- 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<char *>(Buffer.Buffer) >=
- static_cast<ptrdiff_t>(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;
- }
- }
-};
-
-// 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.
-thread_local std::shared_ptr<BufferQueue> LocalBQ = nullptr;
-thread_local ThreadExitBufferCleanup Cleanup(LocalBQ, Buffer);
-
class RecursionGuard {
- bool &Running;
+ volatile bool &Running;
const bool Valid;
public:
- explicit RecursionGuard(bool &R) : Running(R), Valid(!R) {
+ explicit RecursionGuard(volatile bool &R) : Running(R), Valid(!R) {
if (Valid)
Running = true;
}
@@ -195,34 +183,29 @@ public:
}
};
-inline bool loggingInitialized(
- const __sanitizer::atomic_sint32_t &LoggingStatus) XRAY_NEVER_INSTRUMENT {
- return __sanitizer::atomic_load(&LoggingStatus,
- __sanitizer::memory_order_acquire) ==
- XRayLogInitStatus::XRAY_LOG_INITIALIZED;
-}
-
} // 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;
- std::aligned_storage<sizeof(MetadataRecord)>::type Records[InitRecordsCount];
+ 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<MetadataRecord *>(&Records[0]);
+ 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<MetadataRecord *>(&Records[1]);
+ auto &WalltimeMarker = Metadata[1];
WalltimeMarker.Type = uint8_t(RecordType::Metadata);
WalltimeMarker.RecordKind =
uint8_t(MetadataRecord::RecordKinds::WalltimeMarker);
@@ -235,26 +218,48 @@ inline void writeNewBufferPreamble(pid_t Tid, timespec TS,
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;
- NumConsecutiveFnEnters = 0;
- NumTailCalls = 0;
+
+ 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 {
- RecordPtr = static_cast<char *>(Buffer.Buffer);
+ auto &TLD = getThreadLocalData();
+ auto &B = TLD.Buffer;
+ TLD.RecordPtr = static_cast<char *>(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);
- NumConsecutiveFnEnters = 0;
- NumTailCalls = 0;
+ writeNewBufferPreamble(Tid, TS);
+ TLD.NumConsecutiveFnEnters = 0;
+ TLD.NumTailCalls = 0;
+}
+
+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,
- char *&MemPtr) XRAY_NEVER_INSTRUMENT {
+inline void writeNewCPUIdMetadata(uint16_t CPU,
+ uint64_t TSC) XRAY_NEVER_INSTRUMENT {
+ auto &TLD = getThreadLocalData();
MetadataRecord NewCPUId;
NewCPUId.Type = uint8_t(RecordType::Metadata);
NewCPUId.RecordKind = uint8_t(MetadataRecord::RecordKinds::NewCPUId);
@@ -265,34 +270,15 @@ inline void writeNewCPUIdMetadata(uint16_t CPU, uint64_t TSC,
// 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);
- NumConsecutiveFnEnters = 0;
- NumTailCalls = 0;
-}
-
-inline void writeNewCPUIdMetadata(uint16_t CPU,
- uint64_t TSC) XRAY_NEVER_INSTRUMENT {
- writeNewCPUIdMetadata(CPU, TSC, RecordPtr);
-}
-
-inline void writeEOBMetadata(char *&MemPtr) XRAY_NEVER_INSTRUMENT {
- 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);
- NumConsecutiveFnEnters = 0;
- NumTailCalls = 0;
-}
-
-inline void writeEOBMetadata() XRAY_NEVER_INSTRUMENT {
- writeEOBMetadata(RecordPtr);
+ std::memcpy(TLD.RecordPtr, &NewCPUId, sizeof(MetadataRecord));
+ TLD.RecordPtr += sizeof(MetadataRecord);
+ TLD.NumConsecutiveFnEnters = 0;
+ TLD.NumTailCalls = 0;
+ incrementExtents(sizeof(MetadataRecord));
}
-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);
TSCWrap.RecordKind = uint8_t(MetadataRecord::RecordKinds::TSCWrap);
@@ -301,58 +287,67 @@ inline void writeTSCWrapMetadata(uint64_t TSC,
// - 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);
- NumConsecutiveFnEnters = 0;
- NumTailCalls = 0;
+ std::memcpy(TLD.RecordPtr, &TSCWrap, sizeof(MetadataRecord));
+ TLD.RecordPtr += sizeof(MetadataRecord);
+ TLD.NumConsecutiveFnEnters = 0;
+ TLD.NumTailCalls = 0;
+ incrementExtents(sizeof(MetadataRecord));
}
-inline void writeTSCWrapMetadata(uint64_t TSC) XRAY_NEVER_INSTRUMENT {
- writeTSCWrapMetadata(TSC, RecordPtr);
+// Call Argument metadata records store the arguments to a function in the
+// order of their appearance; holes are not supported by the buffer format.
+static inline void writeCallArgumentMetadata(uint64_t A) XRAY_NEVER_INSTRUMENT {
+ auto &TLD = getThreadLocalData();
+ MetadataRecord CallArg;
+ CallArg.Type = uint8_t(RecordType::Metadata);
+ CallArg.RecordKind = uint8_t(MetadataRecord::RecordKinds::CallArgument);
+
+ std::memcpy(CallArg.Data, &A, sizeof(A));
+ std::memcpy(TLD.RecordPtr, &CallArg, sizeof(MetadataRecord));
+ TLD.RecordPtr += sizeof(MetadataRecord);
+ incrementExtents(sizeof(MetadataRecord));
}
-inline void writeFunctionRecord(int FuncId, uint32_t TSCDelta,
- XRayEntryType EntryType,
- char *&MemPtr) XRAY_NEVER_INSTRUMENT {
- std::aligned_storage<sizeof(FunctionRecord), alignof(FunctionRecord)>::type
- AlignedFuncRecordBuffer;
- auto &FuncRecord =
- *reinterpret_cast<FunctionRecord *>(&AlignedFuncRecordBuffer);
+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.
FuncRecord.FuncId = FuncId & ~(0x0F << 28);
FuncRecord.TSCDelta = TSCDelta;
+ auto &TLD = getThreadLocalData();
switch (EntryType) {
case XRayEntryType::ENTRY:
- ++NumConsecutiveFnEnters;
+ ++TLD.NumConsecutiveFnEnters;
FuncRecord.RecordKind = uint8_t(FunctionRecord::RecordKinds::FunctionEnter);
break;
case XRayEntryType::LOG_ARGS_ENTRY:
// We should not rewind functions with logged args.
- NumConsecutiveFnEnters = 0;
- NumTailCalls = 0;
+ TLD.NumConsecutiveFnEnters = 0;
+ TLD.NumTailCalls = 0;
FuncRecord.RecordKind = uint8_t(FunctionRecord::RecordKinds::FunctionEnter);
break;
case XRayEntryType::EXIT:
// If we've decided to log the function exit, we will never erase the log
// before it.
- NumConsecutiveFnEnters = 0;
- NumTailCalls = 0;
+ TLD.NumConsecutiveFnEnters = 0;
+ TLD.NumTailCalls = 0;
FuncRecord.RecordKind = uint8_t(FunctionRecord::RecordKinds::FunctionExit);
break;
case XRayEntryType::TAIL:
// If we just entered the function we're tail exiting from or erased every
// invocation since then, this function entry tail pair is a candidate to
// be erased when the child function exits.
- if (NumConsecutiveFnEnters > 0) {
- ++NumTailCalls;
- NumConsecutiveFnEnters = 0;
+ if (TLD.NumConsecutiveFnEnters > 0) {
+ ++TLD.NumTailCalls;
+ TLD.NumConsecutiveFnEnters = 0;
} else {
// We will never be able to erase this tail call since we have logged
// something in between the function entry and tail exit.
- NumTailCalls = 0;
- NumConsecutiveFnEnters = 0;
+ TLD.NumTailCalls = 0;
+ TLD.NumConsecutiveFnEnters = 0;
}
FuncRecord.RecordKind =
uint8_t(FunctionRecord::RecordKinds::FunctionTailExit);
@@ -370,8 +365,9 @@ inline void writeFunctionRecord(int FuncId, uint32_t TSCDelta,
}
}
- std::memcpy(MemPtr, &AlignedFuncRecordBuffer, sizeof(FunctionRecord));
- MemPtr += sizeof(FunctionRecord);
+ std::memcpy(TLD.RecordPtr, &FuncRecord, sizeof(FunctionRecord));
+ TLD.RecordPtr += sizeof(FunctionRecord);
+ incrementExtents(sizeof(FunctionRecord));
}
static uint64_t thresholdTicks() {
@@ -387,23 +383,21 @@ static uint64_t thresholdTicks() {
// "Function Entry" record and any "Tail Call Exit" records after that.
static void rewindRecentCall(uint64_t TSC, uint64_t &LastTSC,
uint64_t &LastFunctionEntryTSC, int32_t FuncId) {
- using AlignedFuncStorage =
- std::aligned_storage<sizeof(FunctionRecord),
- alignof(FunctionRecord)>::type;
- RecordPtr -= FunctionRecSize;
- AlignedFuncStorage AlignedFuncRecordBuffer;
- const auto &FuncRecord = *reinterpret_cast<FunctionRecord *>(
- std::memcpy(&AlignedFuncRecordBuffer, RecordPtr, FunctionRecSize));
+ auto &TLD = getThreadLocalData();
+ TLD.RecordPtr -= FunctionRecSize;
+ decrementExtents(FunctionRecSize);
+ FunctionRecord FuncRecord;
+ std::memcpy(&FuncRecord, TLD.RecordPtr, FunctionRecSize);
assert(FuncRecord.RecordKind ==
uint8_t(FunctionRecord::RecordKinds::FunctionEnter) &&
"Expected to find function entry recording when rewinding.");
assert(FuncRecord.FuncId == (FuncId & ~(0x0F << 28)) &&
"Expected matching function id when rewinding Exit");
- --NumConsecutiveFnEnters;
+ --TLD.NumConsecutiveFnEnters;
LastTSC -= FuncRecord.TSCDelta;
// We unwound one call. Update the state and return without writing a log.
- if (NumConsecutiveFnEnters != 0) {
+ if (TLD.NumConsecutiveFnEnters != 0) {
LastFunctionEntryTSC -= FuncRecord.TSCDelta;
return;
}
@@ -413,22 +407,19 @@ static void rewindRecentCall(uint64_t TSC, uint64_t &LastTSC,
// exited from via this exit.
LastFunctionEntryTSC = 0;
auto RewindingTSC = LastTSC;
- auto RewindingRecordPtr = RecordPtr - FunctionRecSize;
- while (NumTailCalls > 0) {
- AlignedFuncStorage TailExitRecordBuffer;
+ auto RewindingRecordPtr = TLD.RecordPtr - FunctionRecSize;
+ while (TLD.NumTailCalls > 0) {
// Rewind the TSC back over the TAIL EXIT record.
- const auto &ExpectedTailExit =
- *reinterpret_cast<FunctionRecord *>(std::memcpy(
- &TailExitRecordBuffer, RewindingRecordPtr, FunctionRecSize));
+ FunctionRecord ExpectedTailExit;
+ std::memcpy(&ExpectedTailExit, RewindingRecordPtr, FunctionRecSize);
assert(ExpectedTailExit.RecordKind ==
uint8_t(FunctionRecord::RecordKinds::FunctionTailExit) &&
"Expected to find tail exit when rewinding.");
RewindingRecordPtr -= FunctionRecSize;
RewindingTSC -= ExpectedTailExit.TSCDelta;
- AlignedFuncStorage FunctionEntryBuffer;
- const auto &ExpectedFunctionEntry = *reinterpret_cast<FunctionRecord *>(
- std::memcpy(&FunctionEntryBuffer, RewindingRecordPtr, FunctionRecSize));
+ FunctionRecord ExpectedFunctionEntry;
+ std::memcpy(&ExpectedFunctionEntry, RewindingRecordPtr, FunctionRecSize);
assert(ExpectedFunctionEntry.RecordKind ==
uint8_t(FunctionRecord::RecordKinds::FunctionEnter) &&
"Expected to find function entry when rewinding tail call.");
@@ -437,80 +428,87 @@ static void rewindRecentCall(uint64_t TSC, uint64_t &LastTSC,
// This tail call exceeded the threshold duration. It will not be erased.
if ((TSC - RewindingTSC) >= thresholdTicks()) {
- NumTailCalls = 0;
+ TLD.NumTailCalls = 0;
return;
}
// We can erase a tail exit pair that we're exiting through since
// its duration is under threshold.
- --NumTailCalls;
+ --TLD.NumTailCalls;
RewindingRecordPtr -= FunctionRecSize;
RewindingTSC -= ExpectedFunctionEntry.TSCDelta;
- RecordPtr -= 2 * FunctionRecSize;
+ TLD.RecordPtr -= 2 * FunctionRecSize;
LastTSC = RewindingTSC;
+ decrementExtents(2 * FunctionRecSize);
}
}
-inline bool releaseThreadLocalBuffer(BufferQueue *BQ) {
- auto EC = BQ->releaseBuffer(Buffer);
+inline bool releaseThreadLocalBuffer(BufferQueue &BQArg) {
+ auto &TLD = getThreadLocalData();
+ auto EC = BQArg.releaseBuffer(TLD.Buffer);
if (EC != BufferQueue::ErrorCode::Ok) {
- Report("Failed to release buffer at %p; error=%s\n", Buffer.Buffer,
+ Report("Failed to release buffer at %p; error=%s\n", TLD.Buffer.Buffer,
BufferQueue::getErrorString(EC));
return false;
}
return true;
}
-inline bool prepareBuffer(int (*wall_clock_reader)(clockid_t,
+inline bool prepareBuffer(uint64_t TSC, unsigned char CPU,
+ int (*wall_clock_reader)(clockid_t,
struct timespec *),
size_t MaxSize) XRAY_NEVER_INSTRUMENT {
- char *BufferStart = static_cast<char *>(Buffer.Buffer);
- if ((RecordPtr + MaxSize) > (BufferStart + Buffer.Size - MetadataRecSize)) {
- writeEOBMetadata();
- if (!releaseThreadLocalBuffer(LocalBQ.get()))
+ auto &TLD = getThreadLocalData();
+ char *BufferStart = static_cast<char *>(TLD.Buffer.Buffer);
+ if ((TLD.RecordPtr + MaxSize) > (BufferStart + TLD.Buffer.Size)) {
+ if (!releaseThreadLocalBuffer(*TLD.BQ))
return false;
- auto EC = LocalBQ->getBuffer(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));
return false;
}
setupNewBuffer(wall_clock_reader);
+
+ // Always write the CPU metadata as the first record in the buffer.
+ writeNewCPUIdMetadata(CPU, TSC);
}
return true;
}
-inline bool isLogInitializedAndReady(
- std::shared_ptr<BufferQueue> &LocalBQ, 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,
__sanitizer::memory_order_acquire);
+ auto &TLD = getThreadLocalData();
if (Status != XRayLogInitStatus::XRAY_LOG_INITIALIZED) {
- if (RecordPtr != nullptr &&
+ if (TLD.RecordPtr != nullptr &&
(Status == XRayLogInitStatus::XRAY_LOG_FINALIZING ||
Status == XRayLogInitStatus::XRAY_LOG_FINALIZED)) {
- writeEOBMetadata();
- if (!releaseThreadLocalBuffer(LocalBQ.get()))
+ if (!releaseThreadLocalBuffer(*LBQ))
return false;
- RecordPtr = nullptr;
- LocalBQ = nullptr;
+ TLD.RecordPtr = nullptr;
return false;
}
return false;
}
- if (!loggingInitialized(LoggingStatus) || LocalBQ->finalizing()) {
- writeEOBMetadata();
- if (!releaseThreadLocalBuffer(LocalBQ.get()))
+ if (__sanitizer::atomic_load(&LoggingStatus,
+ __sanitizer::memory_order_acquire) !=
+ XRayLogInitStatus::XRAY_LOG_INITIALIZED ||
+ LBQ->finalizing()) {
+ if (!releaseThreadLocalBuffer(*LBQ))
return false;
- RecordPtr = nullptr;
+ TLD.RecordPtr = nullptr;
}
- if (Buffer.Buffer == nullptr) {
- auto EC = LocalBQ->getBuffer(Buffer);
+ if (TLD.Buffer.Buffer == nullptr) {
+ auto EC = LBQ->getBuffer(TLD.Buffer);
if (EC != BufferQueue::ErrorCode::Ok) {
auto LS = __sanitizer::atomic_load(&LoggingStatus,
__sanitizer::memory_order_acquire);
@@ -522,51 +520,100 @@ inline bool isLogInitializedAndReady(
}
setupNewBuffer(wall_clock_reader);
+
+ // Always write the CPU metadata as the first record in the buffer.
+ writeNewCPUIdMetadata(CPU, TSC);
}
- if (CurrentCPU == std::numeric_limits<uint16_t>::max()) {
+ if (TLD.CurrentCPU == std::numeric_limits<uint16_t>::max()) {
// This means this is the first CPU this thread has ever run on. We set
// the current CPU and record this as the first TSC we've seen.
- CurrentCPU = CPU;
+ TLD.CurrentCPU = CPU;
writeNewCPUIdMetadata(CPU, TSC);
}
return true;
} // namespace __xray_fdr_internal
+// Compute the TSC difference between the time of measurement and the previous
+// event. There are a few interesting situations we need to account for:
+//
+// - The thread has migrated to a different CPU. If this is the case, then
+// we write down the following records:
+//
+// 1. A 'NewCPUId' Metadata record.
+// 2. A FunctionRecord with a 0 for the TSCDelta field.
+//
+// - The TSC delta is greater than the 32 bits we can store in a
+// FunctionRecord. In this case we write down the following records:
+//
+// 1. A 'TSCWrap' Metadata record.
+// 2. A FunctionRecord with a 0 for the TSCDelta field.
+//
+// - The TSC delta is representable within the 32 bits we can store in a
+// FunctionRecord. In this case we write down just a FunctionRecord with
+// the correct TSC delta.
+inline uint32_t writeCurrentCPUTSC(ThreadLocalData &TLD, uint64_t TSC,
+ uint8_t CPU) {
+ if (CPU != TLD.CurrentCPU) {
+ // We've moved to a new CPU.
+ writeNewCPUIdMetadata(CPU, TSC);
+ return 0;
+ }
+ // If the delta is greater than the range for a uint32_t, then we write out
+ // the TSC wrap metadata entry with the full TSC, and the TSC for the
+ // function record be 0.
+ uint64_t Delta = TSC - TLD.LastTSC;
+ if (Delta <= std::numeric_limits<uint32_t>::max())
+ return Delta;
+
+ writeTSCWrapMetadata(TSC);
+ return 0;
+}
+
inline void endBufferIfFull() XRAY_NEVER_INSTRUMENT {
- auto BufferStart = static_cast<char *>(Buffer.Buffer);
- if ((RecordPtr + MetadataRecSize) - BufferStart == MetadataRecSize) {
- writeEOBMetadata();
- if (!releaseThreadLocalBuffer(LocalBQ.get()))
+ auto &TLD = getThreadLocalData();
+ auto BufferStart = static_cast<char *>(TLD.Buffer.Buffer);
+ if ((TLD.RecordPtr + MetadataRecSize) - BufferStart <=
+ ptrdiff_t{MetadataRecSize}) {
+ if (!releaseThreadLocalBuffer(*TLD.BQ))
return;
- RecordPtr = nullptr;
+ TLD.RecordPtr = nullptr;
}
}
-inline void processFunctionHook(
- int32_t FuncId, XRayEntryType Entry, uint64_t TSC, unsigned char CPU,
- int (*wall_clock_reader)(clockid_t, struct timespec *),
- __sanitizer::atomic_sint32_t &LoggingStatus,
- const std::shared_ptr<BufferQueue> &BQ) XRAY_NEVER_INSTRUMENT {
+thread_local volatile bool Running = false;
+
+/// Here's where the meat of the processing happens. The writer captures
+/// function entry, exit and tail exit points with a time and will create
+/// TSCWrap, NewCPUId and Function records as necessary. The writer might
+/// 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 *),
+ 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
// the thread. We use a simple thread_local latch to only allow one on-going
// handleArg0 to happen at any given time.
- thread_local bool Running = false;
RecursionGuard Guard{Running};
if (!Guard) {
assert(Running == true && "RecursionGuard is buggy!");
return;
}
+ auto &TLD = getThreadLocalData();
+
// In case the reference has been cleaned up before, we make sure we
// initialize it to the provided BufferQueue.
- if (LocalBQ == nullptr)
- LocalBQ = BQ;
+ if (TLD.BQ == nullptr)
+ TLD.BQ = BQ;
- if (!isLogInitializedAndReady(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
@@ -579,10 +626,10 @@ inline void processFunctionHook(
// - The least number of bytes we will ever write is 8
// (sizeof(FunctionRecord)) only if the delta between the previous entry
// and this entry is within 32 bits.
- // - The most number of bytes we will ever write is 8 + 16 = 24. This is
- // computed by:
+ // - The most number of bytes we will ever write is 8 + 16 + 16 = 40.
+ // This is computed by:
//
- // sizeof(FunctionRecord) + sizeof(MetadataRecord)
+ // MaxSize = sizeof(FunctionRecord) + 2 * sizeof(MetadataRecord)
//
// These arise in the following cases:
//
@@ -596,77 +643,39 @@ inline void processFunctionHook(
// FunctionRecord.
// 3. When we learn about a new CPU ID, we need to write down a "new cpu
// 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.
- //
- if (!prepareBuffer(wall_clock_reader, FunctionRecSize + MetadataRecSize)) {
- LocalBQ = nullptr;
+ // 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.BQ = nullptr;
return;
}
- // By this point, we are now ready to write at most 24 bytes (one metadata
- // record and one function record).
- assert((RecordPtr + (MetadataRecSize + FunctionRecSize)) -
- static_cast<char *>(Buffer.Buffer) >=
+ // By this point, we are now ready to write up to 40 bytes (explained above).
+ assert((TLD.RecordPtr + MaxSize) - static_cast<char *>(TLD.Buffer.Buffer) >=
static_cast<ptrdiff_t>(MetadataRecSize) &&
"Misconfigured BufferQueue provided; Buffer size not large enough.");
- // Here we compute the TSC Delta. There are a few interesting situations we
- // need to account for:
- //
- // - The thread has migrated to a different CPU. If this is the case, then
- // we write down the following records:
- //
- // 1. A 'NewCPUId' Metadata record.
- // 2. A FunctionRecord with a 0 for the TSCDelta field.
- //
- // - The TSC delta is greater than the 32 bits we can store in a
- // FunctionRecord. In this case we write down the following records:
- //
- // 1. A 'TSCWrap' Metadata record.
- // 2. A FunctionRecord with a 0 for the TSCDelta field.
- //
- // - The TSC delta is representable within the 32 bits we can store in a
- // FunctionRecord. In this case we write down just a FunctionRecord with
- // the correct TSC delta.
- //
- uint32_t RecordTSCDelta = 0;
- if (CPU != CurrentCPU) {
- // We've moved to a new CPU.
- writeNewCPUIdMetadata(CPU, TSC);
- } else {
- // If the delta is greater than the range for a uint32_t, then we write out
- // the TSC wrap metadata entry with the full TSC, and the TSC for the
- // function record be 0.
- auto Delta = TSC - LastTSC;
- if (Delta > (1ULL << 32) - 1)
- writeTSCWrapMetadata(TSC);
- else
- RecordTSCDelta = Delta;
- }
-
- LastTSC = TSC;
- CurrentCPU = CPU;
+ auto RecordTSCDelta = writeCurrentCPUTSC(TLD, TSC, CPU);
+ TLD.LastTSC = TSC;
+ TLD.CurrentCPU = CPU;
switch (Entry) {
case XRayEntryType::ENTRY:
case XRayEntryType::LOG_ARGS_ENTRY:
// Update the thread local state for the next invocation.
- LastFunctionEntryTSC = TSC;
+ TLD.LastFunctionEntryTSC = TSC;
break;
case XRayEntryType::TAIL:
- break;
case XRayEntryType::EXIT:
// Break out and write the exit record if we can't erase any functions.
- if (NumConsecutiveFnEnters == 0 ||
- (TSC - LastFunctionEntryTSC) >= thresholdTicks())
+ if (TLD.NumConsecutiveFnEnters == 0 ||
+ (TSC - TLD.LastFunctionEntryTSC) >= thresholdTicks())
break;
- rewindRecentCall(TSC, LastTSC, LastFunctionEntryTSC, FuncId);
+ rewindRecentCall(TSC, TLD.LastTSC, TLD.LastFunctionEntryTSC, FuncId);
return; // without writing log.
case XRayEntryType::CUSTOM_EVENT: {
// This is a bug in patching, so we'll report it once and move on.
@@ -681,7 +690,9 @@ inline void processFunctionHook(
}
}
- writeFunctionRecord(FuncId, RecordTSCDelta, Entry, RecordPtr);
+ writeFunctionRecord(FuncId, RecordTSCDelta, Entry);
+ if (Entry == XRayEntryType::LOG_ARGS_ENTRY)
+ writeCallArgumentMetadata(Arg1);
// If we've exhausted the buffer by this time, we then release the buffer to
// make sure that other threads may start using this buffer.