Index: lib/xray/xray_fdr_logging_impl.h =================================================================== --- lib/xray/xray_fdr_logging_impl.h +++ lib/xray/xray_fdr_logging_impl.h @@ -30,6 +30,7 @@ #include "xray_buffer_queue.h" #include "xray_defs.h" #include "xray_fdr_log_records.h" +#include "xray_tsc.h" namespace __xray { @@ -106,9 +107,24 @@ //-----------------------------------------------------------------------------| namespace { + +// Hardcoded setting to skip logging simple functions that run less than 5 us. +// Will probably be customized at a later time. +constexpr const uint64_t FuncDurationThresholdMicros = 5; + 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. The first of these tail exits may be preceded +// by something other than a FunctionEntry record if +// FirstTailCallHasMatchingFunctionEntry is false. +thread_local uint8_t NumTailCalls = 0; +thread_local bool FirstTailCallHasMatchingFunctionEntry = false; + constexpr auto MetadataRecSize = sizeof(MetadataRecord); constexpr auto FunctionRecSize = sizeof(FunctionRecord); @@ -206,6 +222,8 @@ } std::memcpy(MemPtr, Records, sizeof(MetadataRecord) * InitRecordsCount); MemPtr += sizeof(MetadataRecord) * InitRecordsCount; + NumConsecutiveFnEnters = 0; + NumTailCalls = 0; } static inline void setupNewBuffer(const BufferQueue::Buffer &Buffer, @@ -218,6 +236,8 @@ // This is typically clock_gettime, but callers have injection ability. wall_clock_reader(CLOCK_MONOTONIC, &TS); writeNewBufferPreamble(Tid, TS, RecordPtr); + NumConsecutiveFnEnters = 0; + NumTailCalls = 0; } static inline void writeNewCPUIdMetadata(uint16_t CPU, uint64_t TSC, @@ -234,6 +254,8 @@ std::memcpy(&NewCPUId.Data[sizeof(CPU)], &TSC, sizeof(TSC)); std::memcpy(MemPtr, &NewCPUId, sizeof(MetadataRecord)); MemPtr += sizeof(MetadataRecord); + NumConsecutiveFnEnters = 0; + NumTailCalls = 0; } static inline void writeNewCPUIdMetadata(uint16_t CPU, @@ -248,6 +270,8 @@ // 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; } static inline void writeEOBMetadata() XRAY_NEVER_INSTRUMENT { @@ -266,6 +290,8 @@ std::memcpy(&TSCWrap.Data, &TSC, sizeof(TSC)); std::memcpy(MemPtr, &TSCWrap, sizeof(MetadataRecord)); MemPtr += sizeof(MetadataRecord); + NumConsecutiveFnEnters = 0; + NumTailCalls = 0; } static inline void writeTSCWrapMetadata(uint64_t TSC) XRAY_NEVER_INSTRUMENT { @@ -286,13 +312,37 @@ switch (EntryType) { case XRayEntryType::ENTRY: + ++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; 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; 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 (NumTailCalls == 1) { + FirstTailCallHasMatchingFunctionEntry = true; + } + } else { + NumTailCalls = 1; + FirstTailCallHasMatchingFunctionEntry = false; + NumConsecutiveFnEnters = 0; + } FuncRecord.RecordKind = uint8_t(FunctionRecord::RecordKinds::FunctionTailExit); break; @@ -319,6 +369,8 @@ // We assume that we'll support only 65536 CPUs for x86_64. thread_local uint16_t CurrentCPU = std::numeric_limits::max(); thread_local uint64_t LastTSC = 0; + thread_local uint64_t LastFunctionEntryTSC = 0; + thread_local uint64_t NumberOfTicksThreshold = 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 @@ -360,6 +412,11 @@ return; } + uint64_t CycleFrequency = getTSCFrequency(); + // Multiply by 5 microseconds to get the number of ticks that tells whether + // to log a function. + NumberOfTicksThreshold = + CycleFrequency * FuncDurationThresholdMicros / 1000000; setupNewBuffer(Buffer, wall_clock_reader); } @@ -422,6 +479,11 @@ BufferQueue::getErrorString(EC)); return; } + uint64_t CycleFrequency = getTSCFrequency(); + // Multiply by 5 microseconds to get the number of ticks that tells whether + // to log a function. + NumberOfTicksThreshold = + CycleFrequency * FuncDurationThresholdMicros / 1000000; setupNewBuffer(Buffer, wall_clock_reader); } @@ -467,11 +529,127 @@ RecordTSCDelta = Delta; } - // We then update our "LastTSC" and "CurrentCPU" thread-local variables to aid - // us in future computations of this TSC delta value. LastTSC = TSC; CurrentCPU = CPU; + using AlignedFuncStorage = + std::aligned_storage::type; + switch (Entry) { + case XRayEntryType::ENTRY: + case XRayEntryType::LOG_ARGS_ENTRY: + // Update the thread local state for the next invocation. + LastFunctionEntryTSC = TSC; + break; + case XRayEntryType::EXIT: + // We unwind functions that are too short to log by decrementing our view + // ptr into the buffer. We can erase a Function Entry record and neglect + // to log our EXIT. We have to make sure to update some state like the + // LastTSC and count of consecutive FunctionEntry records. + if (NumConsecutiveFnEnters > 0 && + (TSC - LastFunctionEntryTSC) < NumberOfTicksThreshold) { + RecordPtr -= FunctionRecSize; + AlignedFuncStorage AlignedFuncRecordBuffer; + const auto &FuncRecord = *reinterpret_cast( + std::memcpy(&AlignedFuncRecordBuffer, 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; + LastTSC -= FuncRecord.TSCDelta; + // If we've rewound the stack of all function entries, we might be + // able to rewind further by erasing tail call functions that are + // being exited from via this exit. + if (NumConsecutiveFnEnters == 0) { + LastFunctionEntryTSC = 0; + auto RewindingTSC = LastTSC; + auto RewindingRecordPtr = RecordPtr - FunctionRecSize; + while (NumTailCalls > 0) { + AlignedFuncStorage RewindingAlignedRecord; + const auto &ExpectedTailExit = *reinterpret_cast( + std::memcpy(&RewindingAlignedRecord, RewindingRecordPtr, + FunctionRecSize)); + assert(ExpectedTailExit.RecordKind == + uint8_t(FunctionRecord::RecordKinds::FunctionTailExit) && + "Expected to find tail exit when rewinding."); + auto TailExitFuncId = ExpectedTailExit.FuncId; + // If we're at the end and don't have a function entry pair, rewrite + // the childless tail exit into an absolute exit. + if (NumTailCalls == 1 && !FirstTailCallHasMatchingFunctionEntry) { + auto ReplaceTailWithExitRecordPtr = RecordPtr - FunctionRecSize; + auto ExitRecordDelta = (TSC - LastTSC) + ExpectedTailExit.TSCDelta; + if (ExitRecordDelta > (1ULL << 32) - 1) { + writeTSCWrapMetadata(TSC, ReplaceTailWithExitRecordPtr); + RecordPtr += MetadataRecSize; + ExitRecordDelta = 0; + } + writeFunctionRecord(TailExitFuncId, ExitRecordDelta, + XRayEntryType::EXIT, + ReplaceTailWithExitRecordPtr); + NumTailCalls = 0; + break; + } + RewindingRecordPtr -= FunctionRecSize; + RewindingTSC -= ExpectedTailExit.TSCDelta; + const auto &ExpectedFunctionEntry = + *reinterpret_cast( + std::memcpy(&RewindingAlignedRecord, RewindingRecordPtr, + FunctionRecSize)); + assert(ExpectedFunctionEntry.RecordKind == + uint8_t(FunctionRecord::RecordKinds::FunctionEnter) && + "Expected to find function entry when rewinding tail call."); + assert(ExpectedFunctionEntry.FuncId == TailExitFuncId && + "Expected funcids to match when rewinding tail call."); + // Rewind to point to entry before FunctionEntry in FunctionEntry, + // Function Tail Exit pair. + + if ((TSC - RewindingTSC) < NumberOfTicksThreshold) { + // We can erase a tail exit pair that we're exiting through since + // its duration is under threshold. + --NumTailCalls; + RewindingRecordPtr -= FunctionRecSize; + RewindingTSC -= ExpectedFunctionEntry.TSCDelta; + RecordPtr -= 2 * FunctionRecSize; + LastTSC = RewindingTSC; + } else { + // We found a function entry tail exit pair where the time between + // function entry and the currently exiting function exceeds the + // heuristic. Because we've erased the function entries that it + // called into, we rewrite the TAIL exit record as a normal EXIT + // so that we keep the end time of the function invocation that + // otherwise would have been deduced from child functions. + auto ReplaceTailWithExitRecordPtr = RecordPtr - FunctionRecSize; + auto ExitRecordDelta = TSC - RewindingTSC; + + // We've already checked whether there is space in the buffer for a + // TSCWrap, function record, and EOB record. We can go ahead within + // bounds because we're not going to write another Function record + // and we've rewound. + if (ExitRecordDelta > (1ULL << 32) - 1) { + writeTSCWrapMetadata(TSC, ReplaceTailWithExitRecordPtr); + RecordPtr += MetadataRecSize; + ExitRecordDelta = 0; + } + + writeFunctionRecord(TailExitFuncId, ExitRecordDelta, + XRayEntryType::EXIT, + ReplaceTailWithExitRecordPtr); + NumTailCalls = 0; + break; + } + } + } else { + LastFunctionEntryTSC = LastFunctionEntryTSC - FuncRecord.TSCDelta; + } + return; // without writing log. + } + break; + case XRayEntryType::TAIL: + break; + } + writeFunctionRecord(FuncId, RecordTSCDelta, Entry, RecordPtr); // If we've exhausted the buffer by this time, we then release the buffer to @@ -491,5 +669,4 @@ } // namespace __xray_fdr_internal } // namespace __xray - #endif // XRAY_XRAY_FDR_LOGGING_IMPL_H