[XRay] [compiler-rt] Unwriting FDR mode buffers when functions are short.

[kpw]

Summary

"short" is defined as an xray flag, and buffer rewinding happens for both exits
and tail exits.

I've made the choice to seek backwards finding pairs of FunctionEntry, TailExit
record pairs and erasing them if the FunctionEntry occurred before exit from the
currently exiting function. This is a compromise so that we don't skip logging
tail calls if the function that they call into takes longer our duration.

This works by counting the consecutive function and function entry, tail exit
pairs that proceed the current point in the buffer. The buffer is rewound to
check whether these entry points happened recently enough to be erased.

It is still possible we will omit them if they call into a child function that
is not instrumented which calls a fast grandchild that is instrumented before
doing other processing.

[kpw]

D'oh. Just realized that I need to do cycle math to convert from TSC ticks to us.

I've also got a program that I'm trying to see output from, and there may be some issues for me to iron out. I'm not seeing any records after the fdr_header.
I may be doing the setup incorrectly. I'm going to recompile compiler-rt without my change to see the difference in output.

#include <stdlib.h>
#include <xray/xray_fdr_logging.h>
#include <xray/xray_interface.h>
#include <cassert>
#include <chrono>
#include <cstdio>
#include <thread>

constexpr auto kBufferSize = 16384;
constexpr auto kBufferMax = 10;

[[clang::xray_always_instrument]] void __attribute__((noinline)) fC() {
std::printf("In fC()\n");
}

[[clang::xray_always_instrument]] void __attribute__((noinline)) fB() {
std::printf("In fB()\n");
fC();
}

[[clang::xray_always_instrument]] void __attribute__((noinline)) fA() {
std::printf("In fA()\n");
fB();
}

[[clang::xray_always_instrument]] void __attribute__((noinline)) fD() {
std::printf("In fD()\n");
std::this_thread::sleep_for(std::chrono::milliseconds(100));
}



int main(int argc, char* argv[]) {
using namespace __xray;
FDRLoggingOptions Options;
Options.ReportErrors = true;
char TmpFilename[] = "fdr-logging-test.XXXXXX";
Options.Fd = mkstemp(TmpFilename);
fdrLoggingInit(kBufferSize, kBufferMax, &Options, sizeof(FDRLoggingOptions));
__xray_set_handler(fdrLoggingHandleArg0);
printf("Patching...\n");
__xray_patch();
fA();
fC();
fC();
fD();
printf("Unpatching...\n");
__xray_unpatch();
fdrLoggingFinalize();
fdrLoggingFlush();
return 0;
}

[kpw]

I found a few problems with my test driver program.

__xray_set_handler(fdrLoggingHandleArg0) doesn't need to be called because initLogging calls it.
Also finally and flush need to be called before unpatch for there to be any chance of the handler releasing the buffer back to the buffer queue.

I made some changes, but I'm still looking into it. The handler never realizes that the buffer has been finalized, so flush doesn't have anything to work with. This is independent of my change. I think there may be a timing issue I should be paying attention to.

Once I understand the BufferQueue code a bit better, I may discover that the problem exists between the keyboard and chair.

[kpw]

I am making some headway. My understanding is that FDR logging short circuits when the log is finalizing or finalized without returning the buffer and is currently depending on the thread exit destructor to release the buffer.

This does not seem ideal, and I have a fix for that, but I'm going to iterate on it a bit to see if I can simplify the logic and make sure I account for edge cases so that nothing is logged after the EOB is written and the buffer is closed.

[dberris]

In D31345#710496, @kpw wrote:

I am making some headway. My understanding is that FDR logging short circuits when the log is finalizing or finalized without returning the buffer and is currently depending on the thread exit destructor to release the buffer.

There's two parts to this -- we should be returning the buffer as soon as we realize that the log is finalizing in the implementation. On the user-side, there should be a short grace period if you want to get more of the buffer before flushing. So there's two stages to this, there's the finalizing at the FDR level and there's the finalizing of the buffer queue.

This does not seem ideal, and I have a fix for that, but I'm going to iterate on it a bit to see if I can simplify the logic and make sure I account for edge cases so that nothing is logged after the EOB is written and the buffer is closed.

SGTM

lib/xray/xray_fdr_logging_impl.h

110–112

We should start by making this a flag right away, so we can test effectively.

509

I think this is what you meant that you need to do some math with. When do you so, consider not having to use floating point math -- if we can get away with approximations and division/masking with power of twos instead, that would really help with the efficiency. Something to keep in mind but probably not worth worrying about at this point.

511–513

Why are we copying from the log buffer into the local aligned record buffer? This seems unused now.

[kpw]

This doesn't handle Tail calls correctly. I made a bad assumption about the trampoline sequence.

with fA() calling fB() calling fC() the records will be
Enter fA()
Tail Exit fA()
Enter fB()
Tail Exit fB()
Enter fC()
Exit fC()

I was expecting records to come out
Enter fA()
Enter fB()
Enter fC()
Tail Exit fA()

I'm changing my code to handle the truth. Hold off on review until I post an update.

[kpw]

Changed handling of Tail call records, which I've exercised by modifying the trampoline
assembly to emit them.

Now the threshold is computed for a new buffer based on the cpu frequency and tail calls
calling into instrumented functions can be unwritten. The topmost tail exit can be replaced
with a normal exit record that records the time that the child returns multiple levels up the
stack. I think I may revert this logic because it seems better to potentially lose track of
a short amount of time in analysis of when the tail calling function is finished than perhaps
incorrectly link the tail call to information from the wrong function if its child is
uninstrumented.

[kpw]

lib/xray/xray_fdr_logging_impl.h

110–112

Is there a typical style of writing flags in compiler-rt I should follow or by flag do you just mean a global that can be set via a call to a header?

511–513

I should probably reinterpret cast directly from the buffer. I can make that fix easily enough.

[kpw]

Saw xray-flags.h and added a flag for the fdr function time threshold.

[kpw]

I've taken Dean's suggestion to use a flag and work directly with the buffer. Seeing expected behavior when setting the flag in a test program.

I've also made the change to read directly from the buffer instead of creating new aligned storage.

Considering non-instrumented functions, I think I should remove the code that rewrites childless tail exits into normal exits. I'll post that in another revision.

[kpw]

Removing rewrite of TailExit to Exit functions. This doesn't make sense if the children are
not instrumented and by definition, any removed instrumented child functions must have been
faster than the profiling threshold.

[dberris]

LGTM -- but please see one important comment on correctness.

lib/xray/xray_fdr_logging_impl.h

511–513

Actually, now that I understand what you were doing, I think it's actually better that you copy to a local aligned buffer. This incarnation is actually running into undefined behaviour, since it's technically unsafe to alias a void* as something other than a char*. For correctness and efficiency, I recommend going back to the aligned buffer local.

Sorry I missed the intent the first time around. :(

[dberris]

Oh, also, please update the description with the details of this current implementation.

[kpw]

Is the undefined behavior you mention a strict aliasing violation?

I will use the copy to aligned storage to stay legal, but for the sake of argument and/or education, I'm curious whether to optimize for efficiency, we could sidestep the rule with language lawyer loopholes.

According to the standard[1], aliased access is explicitly undefined for glvalues, but the output of "*reinterpret_cast<...>()" is a temporary prvalue. I wonder if there is another clause to clarify what would happen if
instead of defining a name, the code just invoked reinterpret cast to get a temporary each time a value needed to be accessed.

1 - Standard quote:
If a program attempts to access the stored value of an object through a glvalue of other than one of the following types the behavior is undefined:

the dynamic type of the object,
a cv-qualified version of the dynamic type of the object,
a type similar (as defined in 4.4) to the dynamic type of the object,
a type that is the signed or unsigned type corresponding to the dynamic type of the object,
a type that is the signed or unsigned type corresponding to a cv-qualified version of the dynamic type of the object,
an aggregate or union type that includes one of the aforementioned types among its elements or non-static data members (including, recursively, an element or non-static data member of a subaggregate or contained union),
a type that is a (possibly cv-qualified) base class type of the dynamic type of the object,
a char or unsigned char type.

[kpw]

Using separate AlignedStorage<FunctionRecord> buffers when rewinding over records.

This doesn't violate the strict aliasing rule and since there are separate buffers for
the FunctionEntry and TailExit records, the compiler should be free to optimize for parallelism.

[dberris]

Still LGTM, just a couple more nits.

Can you clarify the order of when these changes can/should be landed? Are there dependencies amongst the changes?

lib/xray/xray_fdr_logging_impl.h

507–508

This one you can also probably invert and early return.

565

I think I understand what this means, but it might look better if you invert the test case and early return. So:

if (NumConsecutiveFnEnters > 0) {
  LastFunctionEntryTSC = LastFunctionEntryTSC - FuncRecord.TSCDelta;
  return;
}
// If we've rewound the stack of all function entries, ...

[dberris]

Now that we have ways to test this, it would be a good idea to rebase and then see that it's actually omitting records.

[kpw]

Adding test cases for end to end FDR and unwinding FDR.

[dberris]

test/xray/TestCases/Linux/fdr-mode.cc

3 ↗

(On Diff #93440)

Did you need to do this after a rebase? I've landed the change that already makes this line actually work, I think?

62–63 ↗

(On Diff #93440)

The change upstream improves this a bit so that we're actually checking that the stuff is showing up in different threads and matching enters/exits. Consider a rebase?

[kpw]

Rebased onto the lit test changes from Dean. Thanks Dean!

lib/xray/xray_fdr_logging_impl.h

 //-----------------------------------------------------------------------------|
 // The rest of the file is implementation.                                     |
 //-----------------------------------------------------------------------------|
 // Functions are implemented in the header for inlining since we don't want    |
 // to grow the stack when we've hijacked the binary for logging.               |
 //-----------------------------------------------------------------------------|
 
 namespace {
+
+// Hardcoded setting to skip logging simple functions that run less than 5 us.
+// Will probably be customized at a later time.
+const uint64_t FuncDurationThresholdMicros = 5;
+
 thread_local BufferQueue::Buffer Buffer;
 thread_local char *RecordPtr = nullptr;
 
+// NumConsecutiveFnEnters is used to safely rewind the buffer with functions too
+// fast to waste log space on.
+thread_local size_t NumConsecutiveFnEnters = 0;
+
 constexpr auto MetadataRecSize = sizeof(MetadataRecord);
 constexpr auto FunctionRecSize = sizeof(FunctionRecord);
 
 class ThreadExitBufferCleanup {
   std::weak_ptr<BufferQueue> Buffers;
   BufferQueue::Buffer &Buffer;
 
 public:
static inline void setupNewBuffer(const BufferQueue::Buffer &Buffer,
                                                            struct timespec *))
     XRAY_NEVER_INSTRUMENT {
   RecordPtr = static_cast<char *>(Buffer.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;
 }
 
 static inline void writeNewCPUIdMetadata(uint16_t CPU, uint64_t TSC,
                                          char *&MemPtr) XRAY_NEVER_INSTRUMENT {
   MetadataRecord NewCPUId;
   NewCPUId.Type = uint8_t(RecordType::Metadata);
   NewCPUId.RecordKind = uint8_t(MetadataRecord::RecordKinds::NewCPUId);
 
   // The data for the New CPU will contain the following bytes:
   //   - CPU ID (uint16_t, 2 bytes)
   //   - Full TSC (uint64_t, 8 bytes)
   // Total = 12 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);
 }
 
 static inline void writeNewCPUIdMetadata(uint16_t CPU,
                                          uint64_t TSC) XRAY_NEVER_INSTRUMENT {
+  NumConsecutiveFnEnters = 0;
   writeNewCPUIdMetadata(CPU, TSC, RecordPtr);
 }
 
 static 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);
 }
 
 static inline void writeEOBMetadata() XRAY_NEVER_INSTRUMENT {
+  NumConsecutiveFnEnters = 0;
   writeEOBMetadata(RecordPtr);
 }
 
 static inline void writeTSCWrapMetadata(uint64_t TSC,
                                         char *&MemPtr) XRAY_NEVER_INSTRUMENT {
   MetadataRecord TSCWrap;
   TSCWrap.Type = uint8_t(RecordType::Metadata);
   TSCWrap.RecordKind = uint8_t(MetadataRecord::RecordKinds::TSCWrap);
 
   // The data for the TSCWrap record contains the following bytes:
   //   - 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);
 }
 
 static inline void writeTSCWrapMetadata(uint64_t TSC) XRAY_NEVER_INSTRUMENT {
+  NumConsecutiveFnEnters = 0;
   writeTSCWrapMetadata(TSC, RecordPtr);
 }
 
 static 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);
   FuncRecord.Type = uint8_t(RecordType::Function);
   // Only take 28 bits of the function id.
   FuncRecord.FuncId = FuncId & ~(0x0F << 28);
   FuncRecord.TSCDelta = TSCDelta;
 
   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;
     FuncRecord.RecordKind = uint8_t(FunctionRecord::RecordKinds::FunctionEnter);
     break;
   case XRayEntryType::EXIT:
+    NumConsecutiveFnEnters = 0;
     FuncRecord.RecordKind = uint8_t(FunctionRecord::RecordKinds::FunctionExit);
     break;
   case XRayEntryType::TAIL:
+    NumConsecutiveFnEnters = 0;
     FuncRecord.RecordKind =
         uint8_t(FunctionRecord::RecordKinds::FunctionTailExit);
     break;
   }
 
   std::memcpy(MemPtr, &AlignedFuncRecordBuffer, sizeof(FunctionRecord));
   MemPtr += sizeof(FunctionRecord);
 }
static inline void processFunctionHook(
 
   // 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;
 
   // 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 auto LocalBQ = BQ;
   thread_local ThreadExitBufferCleanup Cleanup(LocalBQ, Buffer);
 
   // Prevent signal handler recursion, so in case we're already in a log writing
if (CPU != CurrentCPU) {
     // function record be 0.
     auto Delta = TSC - LastTSC;
     if (Delta > (1ULL << 32) - 1)
       writeTSCWrapMetadata(TSC);
     else
       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<sizeof(FunctionRecord),
+                           alignof(FunctionRecord)>::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) < FuncDurationThresholdMicros) {
+      RecordPtr -= FunctionRecSize;
+      AlignedFuncStorage AlignedFuncRecordBuffer;
+      const auto &FuncRecord = *reinterpret_cast<FunctionRecord *>(
+          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;
+      LastFunctionEntryTSC = NumConsecutiveFnEnters == 0
+                                 ? 0
+                                 : LastFunctionEntryTSC - FuncRecord.TSCDelta;
+      return; // without writing log.
+    }
+    break;
+  case XRayEntryType::TAIL:
+    // If we fail the loop condition, one of two things have occurred.
+    // a. We've rewound over all of the function entries that are part of the
+    // tail exit call stack and were invoked recently enough for our heuristic
+    // to say not to log them.
+    // b. We've encountered an interruption in the stream of function entry
+    // records and we won't try to rewind the stream further.
+    //
+    // Either way, we have not found the function matching our tail exit, but
+    // we'll write a tail exit record for the analysis layer to know that
+    // control travels up the stack and returns from the given function id.
+    //
+    // If we do find the matching function entry by rewinding, we will short
+    // circuit and avoid writing a tail exit record.
+    for (auto PrevFuncPtr = RecordPtr - FunctionRecSize;
+         NumConsecutiveFnEnters > 0 &&
+         (TSC - LastFunctionEntryTSC) < FuncDurationThresholdMicros;
+         PrevFuncPtr -= FunctionRecSize) {
+      AlignedFuncStorage AlignedFuncRecordBuffer;
+      const auto &FuncRecord = *reinterpret_cast<FunctionRecord *>(
+          std::memcpy(&AlignedFuncRecordBuffer, PrevFuncPtr, FunctionRecSize));
+      assert(FuncRecord.RecordKind ==
+                 uint8_t(FunctionRecord::RecordKinds::FunctionEnter) &&
+             "Expected to find function entry when rewinding from TAIL");
+      --NumConsecutiveFnEnters;
+      RecordPtr = PrevFuncPtr;
+      LastTSC -= FuncRecord.TSCDelta;
+      LastFunctionEntryTSC = NumConsecutiveFnEnters == 0
+                                 ? 0
+                                 : LastFunctionEntryTSC - FuncRecord.TSCDelta;
+      if (FuncRecord.FuncId == (FuncId & ~(0x0F << 28))) {
+        // We rewound the whole call stack up to the matching entry.
+        return; // without writing log.
+      }
+    }
+    break;
+  } // switch
+
   writeFunctionRecord(FuncId, RecordTSCDelta, Entry, RecordPtr);
 
   // 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.
   if ((RecordPtr + MetadataRecSize) - BufferStart == MetadataRecSize) {
     writeEOBMetadata();
     auto EC = LocalBQ->releaseBuffer(Buffer);
     if (EC != BufferQueue::ErrorCode::Ok) {
       Report("Failed releasing buffer at %p; error=%s\n", Buffer.Buffer,
              BufferQueue::getErrorString(EC));
       return;
     }
     RecordPtr = nullptr;
   }
 }
 
 } // namespace __xray_fdr_internal
 
 } // namespace __xray
-
 #endif // XRAY_XRAY_FDR_LOGGING_IMPL_H