[XRay] [compiler-rt] Simplify FDR logging handler. [NFC]

[pelikan]

Summary

Not repeating screamy failure paths makes the 300+ line function a bit shorter.
There's no need to overload the variable name "Buffer" if it only works on the
thread local buffer. Fix some comments while there.

I plan to move the rewinding logic into a separate function too, but in this
diff it would be too much of a mess to comprehend. This is trivially NFC.

[dberris]

LGTM

Just FYI: I and @kpw thought the current state would be a good compromise to being able to start writing more granular unit tests. I think we can think about alternative ways of doing testing involving more end-to-end tests now that we can do FDR tests with the lit infrastructure, so the original motivation for this is no longer as important.

[pelikan]

Ack. I don't mean this from the "easy to test" perspective. I want the code to be easier to read. I don't mind tall functions as long as they're simple, and this one has quite a lot of detail on several (distinct) topics. It deals with both types of entries, TSCs, rewinding, buffer shortages and tail call handling all at once. It's not very pleasant for me to keep scrolling such a large amount of code on the screen, that's all.

Motivation for what exactly is no longer as important?

[dberris]

Finer grained testing (unit-testing individual / combinations of internal implementations) isn't as important now compared to doing end-to-end testing. So while the status quo allows us to test the individual functions (i.e. passing a buffer queue that wasn't the thread-local buffer queue), your change makes it harder to test in a controlled environment.

I'm saying that since we don't need to actually have finer grained testing because we can do it with end-to-end testing, this change should be fine.

[kpw]

I think we'll probably want to explore tests with very specific call sequences in the future, and that's why the Buffer was passed around.

No point in over constraining what we have now for a nebulous future though. LGTM.

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

 /// will actually have to run them on different threads.
 ///
 /// This also means that it is possible to break invariants maintained by
 /// 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.
+/// machine and writes directly to memory without checks.
 static void writeNewBufferPreamble(pid_t Tid, timespec TS, char *&MemPtr);
 
 /// Write a metadata record to switch to a new CPU to MemPtr and increments
 /// MemPtr. Bypasses the thread local state machine and writes directly to
 /// memory without checks.
 static void writeNewCPUIdMetadata(uint16_t CPU, uint64_t TSC, char *&MemPtr);
 
 /// Writes an EOB metadata record to MemPtr and increments MemPtr. Bypasses the
 /// thread local state machine and writes directly to memory without checks.
 static void writeEOBMetadata(char *&MemPtr);
 
 /// Writes a TSC Wrap metadata record to MemPtr and increments MemPtr. Bypasses
 /// the thread local state machine and directly writes to memory without checks.
 static void writeTSCWrapMetadata(uint64_t TSC, char *&MemPtr);
 
 /// Writes a Function Record to MemPtr and increments MemPtr. Bypasses the
 /// thread local state machine and writes the function record directly to
 /// memory.
 static void writeFunctionRecord(int FuncId, uint32_t TSCDelta,
                                 XRayEntryType EntryType, char *&MemPtr);
 
 /// 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(const BufferQueue::Buffer &Buffer,
-                           int (*wall_clock_reader)(clockid_t,
+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();
// Also write the WalltimeMarker record.
     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,
+static inline void setupNewBuffer(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.
+  // 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;
 }
 
FuncRecord.RecordKind =
         uint8_t(FunctionRecord::RecordKinds::FunctionTailExit);
     break;
   }
 
   std::memcpy(MemPtr, &AlignedFuncRecordBuffer, sizeof(FunctionRecord));
   MemPtr += sizeof(FunctionRecord);
 }
 
+static inline bool releaseThreadLocalBuffer(BufferQueue *BQ) {
+  auto EC = BQ->releaseBuffer(Buffer);
+  if (EC != BufferQueue::ErrorCode::Ok) {
+    Report("Failed to release buffer at %p; error=%s\n", Buffer.Buffer,
+           BufferQueue::getErrorString(EC));
+    return false;
+  }
+  return true;
+}
+
 static 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 {
   // 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);
   if (Status != XRayLogInitStatus::XRAY_LOG_INITIALIZED) {
     if (RecordPtr != nullptr &&
         (Status == XRayLogInitStatus::XRAY_LOG_FINALIZING ||
          Status == XRayLogInitStatus::XRAY_LOG_FINALIZED)) {
       writeEOBMetadata();
-      auto EC = BQ->releaseBuffer(Buffer);
-      if (EC != BufferQueue::ErrorCode::Ok) {
-        Report("Failed to release buffer at %p; error=%s\n", Buffer.Buffer,
-               BufferQueue::getErrorString(EC));
+      if (!releaseThreadLocalBuffer(BQ.get()))
         return;
-      }
       RecordPtr = nullptr;
     }
     return;
   }
 
   // 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.
static inline void processFunctionHook(
   RecursionGuard Guard{Running};
   if (!Guard) {
     assert(Running == true && "RecursionGuard is buggy!");
     return;
   }
 
   if (!loggingInitialized(LoggingStatus) || LocalBQ->finalizing()) {
     writeEOBMetadata();
-    auto EC = BQ->releaseBuffer(Buffer);
-    if (EC != BufferQueue::ErrorCode::Ok) {
-      Report("Failed to release buffer at %p; error=%s\n", Buffer.Buffer,
-             BufferQueue::getErrorString(EC));
+    if (!releaseThreadLocalBuffer(BQ.get()))
       return;
-    }
     RecordPtr = nullptr;
   }
 
   if (Buffer.Buffer == nullptr) {
     auto EC = LocalBQ->getBuffer(Buffer);
     if (EC != BufferQueue::ErrorCode::Ok) {
       auto LS = __sanitizer::atomic_load(&LoggingStatus,
                                          __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 = probeRequiredCPUFeatures()
                               ? getTSCFrequency()
                               : __xray::NanosecondsPerSecond;
     NumberOfTicksThreshold = CycleFrequency *
                              flags()->xray_fdr_log_func_duration_threshold_us /
                              1000000;
-    setupNewBuffer(Buffer, wall_clock_reader);
+    setupNewBuffer(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);
   }
static inline void processFunctionHook(
   // 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.
   //
   char *BufferStart = static_cast<char *>(Buffer.Buffer);
   if ((RecordPtr + (MetadataRecSize + FunctionRecSize)) - BufferStart <
       static_cast<ptrdiff_t>(MetadataRecSize)) {
     writeEOBMetadata();
-    auto EC = LocalBQ->releaseBuffer(Buffer);
-    if (EC != BufferQueue::ErrorCode::Ok) {
-      Report("Failed to release buffer at %p; error=%s\n", Buffer.Buffer,
-             BufferQueue::getErrorString(EC));
+    if (!releaseThreadLocalBuffer(LocalBQ.get()))
       return;
-    }
-    EC = LocalBQ->getBuffer(Buffer);
+    auto 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);
+    setupNewBuffer(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) &&
          "Misconfigured BufferQueue provided; Buffer size not large enough.");
static inline void processFunctionHook(
   }
 
   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));
+    if (!releaseThreadLocalBuffer(LocalBQ.get()))
       return;
-    }
     RecordPtr = nullptr;
   }
 }
 
 } // namespace __xray_fdr_internal
 
 } // namespace __xray
 #endif // XRAY_XRAY_FDR_LOGGING_IMPL_H