[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 ↗

(On Diff #92984)

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

509 ↗

(On Diff #92984)

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 ↗

(On Diff #92984)

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 ↗

(On Diff #92984)

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 ↗

(On Diff #92984)

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 ↗

(On Diff #92984)

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

538–539 ↗

(On Diff #93304)

This one you can also probably invert and early return.

596 ↗

(On Diff #93304)

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!

compiler-rt/trunk/lib/xray/xray_fdr_logging_impl.h

 #include <time.h>
 #include <unistd.h>
 
 #include "sanitizer_common/sanitizer_common.h"
 #include "xray/xray_log_interface.h"
 #include "xray_buffer_queue.h"
 #include "xray_defs.h"
 #include "xray_fdr_log_records.h"
+#include "xray_flags.h"
+#include "xray_tsc.h"
 
 namespace __xray {
 
 /// We expose some of the state transitions when FDR logging mode is operating
 /// such that we can simulate a series of log events that may occur without
 /// and test with determinism without worrying about the real CPU time.
 ///
 /// Because the code uses thread_local allocation extensively as part of its

 //-----------------------------------------------------------------------------|
 // 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 {
+
 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);
 
 class ThreadExitBufferCleanup {
   std::weak_ptr<BufferQueue> Buffers;
   BufferQueue::Buffer &Buffer;
 
 public:
// Also write the WalltimeMarker record.
     // the Metadata record.
     int32_t Micros = TS.tv_nsec / 1000;
     int64_t Seconds = TS.tv_sec;
     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;
 }
 
 static inline void setupNewBuffer(const BufferQueue::Buffer &Buffer,
                                   int (*wall_clock_reader)(clockid_t,
                                                            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;
+  NumTailCalls = 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);
+  NumConsecutiveFnEnters = 0;
+  NumTailCalls = 0;
 }
 
 static inline void writeNewCPUIdMetadata(uint16_t CPU,
                                          uint64_t TSC) XRAY_NEVER_INSTRUMENT {
   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);
+  NumConsecutiveFnEnters = 0;
+  NumTailCalls = 0;
 }
 
 static inline void writeEOBMetadata() XRAY_NEVER_INSTRUMENT {
   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);
+  NumConsecutiveFnEnters = 0;
+  NumTailCalls = 0;
 }
 
 static inline void writeTSCWrapMetadata(uint64_t TSC) XRAY_NEVER_INSTRUMENT {
   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;
+    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;
+    } 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;
+    }
     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;
+  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
   // 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 (EC != BufferQueue::ErrorCode::Ok) {
                                          __sanitizer::memory_order_acquire);
       if (LS != XRayLogInitStatus::XRAY_LOG_FINALIZING &&
           LS != XRayLogInitStatus::XRAY_LOG_FINALIZED)
         Report("Failed to acquire a buffer; error=%s\n",
                BufferQueue::getErrorString(EC));
       return;
     }
 
+    uint64_t CycleFrequency = getTSCFrequency();
+    NumberOfTicksThreshold = CycleFrequency *
+                             flags()->xray_fdr_log_func_duration_threshold_us /
+                             1000000;
     setupNewBuffer(Buffer, wall_clock_reader);
   }
 
   if (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;
     writeNewCPUIdMetadata(CPU, TSC);
if (EC != BufferQueue::ErrorCode::Ok) {
       return;
     }
     EC = LocalBQ->getBuffer(Buffer);
     if (EC != BufferQueue::ErrorCode::Ok) {
       Report("Failed to acquire a buffer; error=%s\n",
              BufferQueue::getErrorString(EC));
       return;
     }
+    uint64_t CycleFrequency = getTSCFrequency();
+    NumberOfTicksThreshold = CycleFrequency *
+                             flags()->xray_fdr_log_func_duration_threshold_us /
+                             1000000;
     setupNewBuffer(Buffer, wall_clock_reader);
   }
 
   // By this point, we are now ready to write at most 24 bytes (one metadata
   // record and one function record).
   BufferStart = static_cast<char *>(Buffer.Buffer);
   assert((RecordPtr + (MetadataRecSize + FunctionRecSize)) - BufferStart >=
              static_cast<ptrdiff_t>(MetadataRecSize) &&
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::TAIL:
+    break;
+  case XRayEntryType::EXIT:
+    // Break out and write the exit record if we can't erase any functions.
+    if (NumConsecutiveFnEnters == 0 ||
+        (TSC - LastFunctionEntryTSC) >= NumberOfTicksThreshold)
+      break;
+    // Otherwise 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.
+    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;
+
+    // We unwound one call. Update the state and return without writing a log.
+    if (NumConsecutiveFnEnters != 0) {
+      LastFunctionEntryTSC = LastFunctionEntryTSC - FuncRecord.TSCDelta;
+      return;
+    }
+
+    // Otherwise 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.
+    LastFunctionEntryTSC = 0;
+    auto RewindingTSC = LastTSC;
+    auto RewindingRecordPtr = RecordPtr - FunctionRecSize;
+    while (NumTailCalls > 0) {
+      AlignedFuncStorage TailExitRecordBuffer;
+      // Rewind the TSC back over the TAIL EXIT record.
+      const auto &ExpectedTailExit =
+          *reinterpret_cast<FunctionRecord *>(std::memcpy(
+              &TailExitRecordBuffer, RewindingRecordPtr, FunctionRecSize));
+
+      assert(ExpectedTailExit.RecordKind ==
+                 uint8_t(FunctionRecord::RecordKinds::FunctionTailExit) &&
+             "Expected to find tail exit when rewinding.");
+      auto TailExitFuncId = ExpectedTailExit.FuncId;
+      RewindingRecordPtr -= FunctionRecSize;
+      RewindingTSC -= ExpectedTailExit.TSCDelta;
+      AlignedFuncStorage FunctionEntryBuffer;
+      const auto &ExpectedFunctionEntry =
+          *reinterpret_cast<FunctionRecord *>(std::memcpy(
+              &FunctionEntryBuffer, 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.");
+
+      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 {
+        // This tail call exceeded the threshold duration. It will not
+        // be erased.
+        NumTailCalls = 0;
+        return;
+      }
+    }
+    return; // without writing log.
+  }
 
   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

compiler-rt/trunk/lib/xray/xray_flags.inc

 XRAY_FLAG(bool, patch_premain, false,
           "Whether to patch instrumentation points before main.")
 XRAY_FLAG(bool, xray_naive_log, true,
           "Whether to install the naive log implementation.")
 XRAY_FLAG(const char *, xray_logfile_base, "xray-log.",
           "Filename base for the xray logfile.")
 XRAY_FLAG(bool, xray_fdr_log, false,
           "Whether to install the flight data recorder logging implementation.")
+XRAY_FLAG(int, xray_fdr_log_func_duration_threshold_us, 5,
+          "FDR logging will try to skip functions that execute for fewer "
+          "microseconds than this threshold.")

compiler-rt/trunk/test/xray/TestCases/Linux/fdr-mode.cc

 // RUN: %clangxx_xray -g -std=c++11 %s -o %t
-// RUN: XRAY_OPTIONS="patch_premain=false xray_naive_log=false xray_logfile_base=fdr-logging-test- xray_fdr_log=true verbosity=1" %run %t 2>&1 | FileCheck %s
-// RUN: %llvm_xray convert --symbolize --output-format=yaml -instr_map=%t "`ls fdr-logging-test-* | head -1`" | FileCheck %s --check-prefix TRACE
+// RUN: XRAY_OPTIONS="patch_premain=false xray_naive_log=false xray_logfile_base=fdr-logging-test- xray_fdr_log=true verbosity=1 xray_fdr_log_func_duration_threshold_us=0" %run %t 2>&1 | FileCheck %s
+// RUN: XRAY_OPTIONS="patch_premain=false xray_naive_log=false xray_logfile_base=fdr-unwrite-test- xray_fdr_log=true verbosity=1 xray_fdr_log_func_duration_threshold_us=5000" %run %t 2>&1 | FileCheck %s
+// RUN: %llvm_xray convert --symbolize --output-format=yaml -instr_map=%t "`ls fdr-logging-test-* | head -1`" | FileCheck %s --check-prefix=TRACE
+// RUN: %llvm_xray convert --symbolize --output-format=yaml -instr_map=%t "`ls fdr-unwrite-test-* | head -1`" | FileCheck %s --check-prefix=UNWRITE
 // RUN: rm fdr-logging-test-*
+// RUN: rm fdr-unwrite-test-*
 // FIXME: Make llvm-xray work on non-x86_64 as well.
 // REQUIRES: x86_64-linux
 
 #include "xray/xray_log_interface.h"
 #include <cassert>
 #include <chrono>
 #include <cstdio>
 #include <iostream>
int main(int argc, char *argv[]) {
   std::cout << "Main execution var = " << var << std::endl;
   // CHECK: Main execution var = 6
   std::cout << "Flush status " << __xray_log_flushLog() << std::endl;
   // CHECK: Flush status {{.*}}
   __xray_unpatch();
   return 0;
 }
 
-
-
 // Check that we're able to see two threads, each entering and exiting fA().
 // TRACE-DAG: - { type: 0, func-id: [[FIDA:[0-9]+]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} }
 // TRACE:     - { type: 0, func-id: [[FIDA]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD1]], kind: function-exit, tsc: {{[0-9]+}} }
 // TRACE-DAG: - { type: 0, func-id: [[FIDA]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} }
 // TRACE:     - { type: 0, func-id: [[FIDA]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD2]], kind: function-exit, tsc: {{[0-9]+}} }
 //
 // Do the same as above for fC()
 // TRACE-DAG: - { type: 0, func-id: [[FIDC:[0-9]+]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} }
 // TRACE:     - { type: 0, func-id: [[FIDC]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD1]], kind: function-exit, tsc: {{[0-9]+}} }
 // TRACE-DAG: - { type: 0, func-id: [[FIDC]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} }
 // TRACE:     - { type: 0, func-id: [[FIDC]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD2]], kind: function-exit, tsc: {{[0-9]+}} }
 
 // Do the same as above for fB()
 // TRACE-DAG: - { type: 0, func-id: [[FIDB:[0-9]+]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} }
 // TRACE:     - { type: 0, func-id: [[FIDB]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD1]], kind: function-exit, tsc: {{[0-9]+}} }
 // TRACE-DAG: - { type: 0, func-id: [[FIDB]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} }
 // TRACE:     - { type: 0, func-id: [[FIDB]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD2]], kind: function-exit, tsc: {{[0-9]+}} }
+
+// Assert that when unwriting is enabled with a high threshold time, all the function records are erased. A CPU switch could erroneously fail this test, but
+// is unlikely given the test program.
+// UNWRITE: header
+// UNWRITE-NOT: function-enter
+// UNWRITE-NOT: function-exit