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

   1 //===-- xray_fdr_logging_impl.h ---------------------------------*- C++ -*-===//
   2 //
   3 //                     The LLVM Compiler Infrastructure
   4 //
   5 // This file is distributed under the University of Illinois Open Source
   6 // License. See LICENSE.TXT for details.
   7 //
   8 //===----------------------------------------------------------------------===//
   9 //
  10 // This file is a part of XRay, a dynamic runtime instrumentation system.
  11 //
  12 // Here we implement the thread local state management and record i/o for Flight
  13 // Data Recorder mode for XRay, where we use compact structures to store records
  14 // in memory as well as when writing out the data to files.
  15 //
  16 //===----------------------------------------------------------------------===//
  17 #ifndef XRAY_XRAY_FDR_LOGGING_IMPL_H
  18 #define XRAY_XRAY_FDR_LOGGING_IMPL_H
  19
  20 #include <cassert>
  21 #include <cstdint>
  22 #include <cstring>
  23 #include <limits>
  24 #include <memory>
  25 #include <string>
  26 #include <sys/syscall.h>
  27 #include <time.h>
  28 #include <unistd.h>
  29
  30 #include "sanitizer_common/sanitizer_common.h"
  31 #include "xray/xray_log_interface.h"
  32 #include "xray_buffer_queue.h"
  33 #include "xray_defs.h"
  34 #include "xray_fdr_log_records.h"
  35 #include "xray_flags.h"
  36 #include "xray_tsc.h"
  37
  38 namespace __xray {
  39
  40 __sanitizer::atomic_sint32_t LoggingStatus = {
  41     XRayLogInitStatus::XRAY_LOG_UNINITIALIZED};
  42
  43 /// We expose some of the state transitions when FDR logging mode is operating
  44 /// such that we can simulate a series of log events that may occur without
  45 /// and test with determinism without worrying about the real CPU time.
  46 ///
  47 /// Because the code uses thread_local allocation extensively as part of its
  48 /// design, callers that wish to test events occuring on different threads
  49 /// will actually have to run them on different threads.
  50 ///
  51 /// This also means that it is possible to break invariants maintained by
  52 /// cooperation with xray_fdr_logging class, so be careful and think twice.
  53 namespace __xray_fdr_internal {
  54
  55 /// Writes the new buffer record and wallclock time that begin a buffer for a
  56 /// thread to MemPtr and increments MemPtr. Bypasses the thread local state
  57 /// machine and writes directly to memory without checks.
  58 static void writeNewBufferPreamble(pid_t Tid, timespec TS, char *&MemPtr);
  59
  60 /// Write a metadata record to switch to a new CPU to MemPtr and increments
  61 /// MemPtr. Bypasses the thread local state machine and writes directly to
  62 /// memory without checks.
  63 static void writeNewCPUIdMetadata(uint16_t CPU, uint64_t TSC, char *&MemPtr);
  64
  65 /// Writes an EOB metadata record to MemPtr and increments MemPtr. Bypasses the
  66 /// thread local state machine and writes directly to memory without checks.
  67 static void writeEOBMetadata(char *&MemPtr);
  68
  69 /// Writes a TSC Wrap metadata record to MemPtr and increments MemPtr. Bypasses
  70 /// the thread local state machine and directly writes to memory without checks.
  71 static void writeTSCWrapMetadata(uint64_t TSC, char *&MemPtr);
  72
  73 /// Writes a Function Record to MemPtr and increments MemPtr. Bypasses the
  74 /// thread local state machine and writes the function record directly to
  75 /// memory.
  76 static void writeFunctionRecord(int FuncId, uint32_t TSCDelta,
  77                                 XRayEntryType EntryType, char *&MemPtr);
  78
  79 /// Sets up a new buffer in thread_local storage and writes a preamble. The
  80 /// wall_clock_reader function is used to populate the WallTimeRecord entry.
  81 static void setupNewBuffer(int (*wall_clock_reader)(clockid_t,
  82                                                     struct timespec *));
  83
  84 /// Called to record CPU time for a new CPU within the current thread.
  85 static void writeNewCPUIdMetadata(uint16_t CPU, uint64_t TSC);
  86
  87 /// Called to close the buffer when the thread exhausts the buffer or when the
  88 /// thread exits (via a thread local variable destructor).
  89 static void writeEOBMetadata();
  90
  91 /// TSC Wrap records are written when a TSC delta encoding scheme overflows.
  92 static void writeTSCWrapMetadata(uint64_t TSC);
  93
  94 /// Here's where the meat of the processing happens. The writer captures
  95 /// function entry, exit and tail exit points with a time and will create
  96 /// TSCWrap, NewCPUId and Function records as necessary. The writer might
  97 /// walk backward through its buffer and erase trivial functions to avoid
  98 /// polluting the log and may use the buffer queue to obtain or release a
  99 /// buffer.
 100 static void processFunctionHook(int32_t FuncId, XRayEntryType Entry,
 101                                 uint64_t TSC, unsigned char CPU,
 102                                 int (*wall_clock_reader)(clockid_t,
 103                                                          struct timespec *),
 104                                 __sanitizer::atomic_sint32_t &LoggingStatus,
 105                                 const std::shared_ptr<BufferQueue> &BQ);
 106
 107 //-----------------------------------------------------------------------------|
 108 // The rest of the file is implementation.                                     |
 109 //-----------------------------------------------------------------------------|
 110 // Functions are implemented in the header for inlining since we don't want    |
 111 // to grow the stack when we've hijacked the binary for logging.               |
 112 //-----------------------------------------------------------------------------|
 113
 114 namespace {
 115
 116 thread_local BufferQueue::Buffer Buffer;
 117 thread_local char *RecordPtr = nullptr;
 118
 119 // The number of FunctionEntry records immediately preceding RecordPtr.
 120 thread_local uint8_t NumConsecutiveFnEnters = 0;
 121
 122 // The number of adjacent, consecutive pairs of FunctionEntry, Tail Exit
 123 // records preceding RecordPtr.
 124 thread_local uint8_t NumTailCalls = 0;
 125
 126 constexpr auto MetadataRecSize = sizeof(MetadataRecord);
 127 constexpr auto FunctionRecSize = sizeof(FunctionRecord);
 128
 129 // We use a thread_local variable to keep track of which CPUs we've already
 130 // run, and the TSC times for these CPUs. This allows us to stop repeating the
 131 // CPU field in the function records.
 132 //
 133 // We assume that we'll support only 65536 CPUs for x86_64.
 134 thread_local uint16_t CurrentCPU = std::numeric_limits<uint16_t>::max();
 135 thread_local uint64_t LastTSC = 0;
 136 thread_local uint64_t LastFunctionEntryTSC = 0;
 137
 138 class ThreadExitBufferCleanup {
 139   std::shared_ptr<BufferQueue> &Buffers;
 140   BufferQueue::Buffer &Buffer;
 141
 142 public:
 143   explicit ThreadExitBufferCleanup(std::shared_ptr<BufferQueue> &BQ,
 144                                    BufferQueue::Buffer &Buffer)
 145       XRAY_NEVER_INSTRUMENT : Buffers(BQ),
 146                               Buffer(Buffer) {}
 147
 148   ~ThreadExitBufferCleanup() noexcept XRAY_NEVER_INSTRUMENT {
 149     if (RecordPtr == nullptr)
 150       return;
 151
 152     // We make sure that upon exit, a thread will write out the EOB
 153     // MetadataRecord in the thread-local log, and also release the buffer to
 154     // the queue.
 155     assert((RecordPtr + MetadataRecSize) - static_cast<char *>(Buffer.Buffer) >=
 156            static_cast<ptrdiff_t>(MetadataRecSize));
 157     if (Buffers) {
 158       writeEOBMetadata();
 159       auto EC = Buffers->releaseBuffer(Buffer);
 160       if (EC != BufferQueue::ErrorCode::Ok)
 161         Report("Failed to release buffer at %p; error=%s\n", Buffer.Buffer,
 162                BufferQueue::getErrorString(EC));
 163       Buffers = nullptr;
 164       return;
 165     }
 166   }
 167 };
 168
 169 // Make sure a thread that's ever called handleArg0 has a thread-local
 170 // live reference to the buffer queue for this particular instance of
 171 // FDRLogging, and that we're going to clean it up when the thread exits.
 172 thread_local std::shared_ptr<BufferQueue> LocalBQ = nullptr;
 173 thread_local ThreadExitBufferCleanup Cleanup(LocalBQ, Buffer);
 174
 175 class RecursionGuard {
 176   bool &Running;
 177   const bool Valid;
 178
 179 public:
 180   explicit RecursionGuard(bool &R) : Running(R), Valid(!R) {
 181     if (Valid)
 182       Running = true;
 183   }
 184
 185   RecursionGuard(const RecursionGuard &) = delete;
 186   RecursionGuard(RecursionGuard &&) = delete;
 187   RecursionGuard &operator=(const RecursionGuard &) = delete;
 188   RecursionGuard &operator=(RecursionGuard &&) = delete;
 189
 190   explicit operator bool() const { return Valid; }
 191
 192   ~RecursionGuard() noexcept {
 193     if (Valid)
 194       Running = false;
 195   }
 196 };
 197
 198 inline bool loggingInitialized(
 199     const __sanitizer::atomic_sint32_t &LoggingStatus) XRAY_NEVER_INSTRUMENT {
 200   return __sanitizer::atomic_load(&LoggingStatus,
 201                                   __sanitizer::memory_order_acquire) ==
 202          XRayLogInitStatus::XRAY_LOG_INITIALIZED;
 203 }
 204
 205 } // namespace
 206
 207 inline void writeNewBufferPreamble(pid_t Tid, timespec TS,
 208                                    char *&MemPtr) XRAY_NEVER_INSTRUMENT {
 209   static constexpr int InitRecordsCount = 2;
 210   std::aligned_storage<sizeof(MetadataRecord)>::type Records[InitRecordsCount];
 211   {
 212     // Write out a MetadataRecord to signify that this is the start of a new
 213     // buffer, associated with a particular thread, with a new CPU.  For the
 214     // data, we have 15 bytes to squeeze as much information as we can.  At this
 215     // point we only write down the following bytes:
 216     //   - Thread ID (pid_t, 4 bytes)
 217     auto &NewBuffer = *reinterpret_cast<MetadataRecord *>(&Records[0]);
 218     NewBuffer.Type = uint8_t(RecordType::Metadata);
 219     NewBuffer.RecordKind = uint8_t(MetadataRecord::RecordKinds::NewBuffer);
 220     std::memcpy(&NewBuffer.Data, &Tid, sizeof(pid_t));
 221   }
 222   // Also write the WalltimeMarker record.
 223   {
 224     static_assert(sizeof(time_t) <= 8, "time_t needs to be at most 8 bytes");
 225     auto &WalltimeMarker = *reinterpret_cast<MetadataRecord *>(&Records[1]);
 226     WalltimeMarker.Type = uint8_t(RecordType::Metadata);
 227     WalltimeMarker.RecordKind =
 228         uint8_t(MetadataRecord::RecordKinds::WalltimeMarker);
 229
 230     // We only really need microsecond precision here, and enforce across
 231     // platforms that we need 64-bit seconds and 32-bit microseconds encoded in
 232     // the Metadata record.
 233     int32_t Micros = TS.tv_nsec / 1000;
 234     int64_t Seconds = TS.tv_sec;
 235     std::memcpy(WalltimeMarker.Data, &Seconds, sizeof(Seconds));
 236     std::memcpy(WalltimeMarker.Data + sizeof(Seconds), &Micros, sizeof(Micros));
 237   }
 238   std::memcpy(MemPtr, Records, sizeof(MetadataRecord) * InitRecordsCount);
 239   MemPtr += sizeof(MetadataRecord) * InitRecordsCount;
 240   NumConsecutiveFnEnters = 0;
 241   NumTailCalls = 0;
 242 }
 243
 244 inline void setupNewBuffer(int (*wall_clock_reader)(
 245     clockid_t, struct timespec *)) XRAY_NEVER_INSTRUMENT {
 246   RecordPtr = static_cast<char *>(Buffer.Buffer);
 247   pid_t Tid = syscall(SYS_gettid);
 248   timespec TS{0, 0};
 249   // This is typically clock_gettime, but callers have injection ability.
 250   wall_clock_reader(CLOCK_MONOTONIC, &TS);
 251   writeNewBufferPreamble(Tid, TS, RecordPtr);
 252   NumConsecutiveFnEnters = 0;
 253   NumTailCalls = 0;
 254 }
 255
 256 inline void writeNewCPUIdMetadata(uint16_t CPU, uint64_t TSC,
 257                                   char *&MemPtr) XRAY_NEVER_INSTRUMENT {
 258   MetadataRecord NewCPUId;
 259   NewCPUId.Type = uint8_t(RecordType::Metadata);
 260   NewCPUId.RecordKind = uint8_t(MetadataRecord::RecordKinds::NewCPUId);
 261
 262   // The data for the New CPU will contain the following bytes:
 263   //   - CPU ID (uint16_t, 2 bytes)
 264   //   - Full TSC (uint64_t, 8 bytes)
 265   // Total = 10 bytes.
 266   std::memcpy(&NewCPUId.Data, &CPU, sizeof(CPU));
 267   std::memcpy(&NewCPUId.Data[sizeof(CPU)], &TSC, sizeof(TSC));
 268   std::memcpy(MemPtr, &NewCPUId, sizeof(MetadataRecord));
 269   MemPtr += sizeof(MetadataRecord);
 270   NumConsecutiveFnEnters = 0;
 271   NumTailCalls = 0;
 272 }
 273
 274 inline void writeNewCPUIdMetadata(uint16_t CPU,
 275                                   uint64_t TSC) XRAY_NEVER_INSTRUMENT {
 276   writeNewCPUIdMetadata(CPU, TSC, RecordPtr);
 277 }
 278
 279 inline void writeEOBMetadata(char *&MemPtr) XRAY_NEVER_INSTRUMENT {
 280   MetadataRecord EOBMeta;
 281   EOBMeta.Type = uint8_t(RecordType::Metadata);
 282   EOBMeta.RecordKind = uint8_t(MetadataRecord::RecordKinds::EndOfBuffer);
 283   // For now we don't write any bytes into the Data field.
 284   std::memcpy(MemPtr, &EOBMeta, sizeof(MetadataRecord));
 285   MemPtr += sizeof(MetadataRecord);
 286   NumConsecutiveFnEnters = 0;
 287   NumTailCalls = 0;
 288 }
 289
 290 inline void writeEOBMetadata() XRAY_NEVER_INSTRUMENT {
 291   writeEOBMetadata(RecordPtr);
 292 }
 293
 294 inline void writeTSCWrapMetadata(uint64_t TSC,
 295                                  char *&MemPtr) XRAY_NEVER_INSTRUMENT {
 296   MetadataRecord TSCWrap;
 297   TSCWrap.Type = uint8_t(RecordType::Metadata);
 298   TSCWrap.RecordKind = uint8_t(MetadataRecord::RecordKinds::TSCWrap);
 299
 300   // The data for the TSCWrap record contains the following bytes:
 301   //   - Full TSC (uint64_t, 8 bytes)
 302   // Total = 8 bytes.
 303   std::memcpy(&TSCWrap.Data, &TSC, sizeof(TSC));
 304   std::memcpy(MemPtr, &TSCWrap, sizeof(MetadataRecord));
 305   MemPtr += sizeof(MetadataRecord);
 306   NumConsecutiveFnEnters = 0;
 307   NumTailCalls = 0;
 308 }
 309
 310 inline void writeTSCWrapMetadata(uint64_t TSC) XRAY_NEVER_INSTRUMENT {
 311   writeTSCWrapMetadata(TSC, RecordPtr);
 312 }
 313
 314 inline void writeFunctionRecord(int FuncId, uint32_t TSCDelta,
 315                                 XRayEntryType EntryType,
 316                                 char *&MemPtr) XRAY_NEVER_INSTRUMENT {
 317   std::aligned_storage<sizeof(FunctionRecord), alignof(FunctionRecord)>::type
 318       AlignedFuncRecordBuffer;
 319   auto &FuncRecord =
 320       *reinterpret_cast<FunctionRecord *>(&AlignedFuncRecordBuffer);
 321   FuncRecord.Type = uint8_t(RecordType::Function);
 322   // Only take 28 bits of the function id.
 323   FuncRecord.FuncId = FuncId & ~(0x0F << 28);
 324   FuncRecord.TSCDelta = TSCDelta;
 325
 326   switch (EntryType) {
 327   case XRayEntryType::ENTRY:
 328     ++NumConsecutiveFnEnters;
 329     FuncRecord.RecordKind = uint8_t(FunctionRecord::RecordKinds::FunctionEnter);
 330     break;
 331   case XRayEntryType::LOG_ARGS_ENTRY:
 332     // We should not rewind functions with logged args.
 333     NumConsecutiveFnEnters = 0;
 334     NumTailCalls = 0;
 335     FuncRecord.RecordKind = uint8_t(FunctionRecord::RecordKinds::FunctionEnter);
 336     break;
 337   case XRayEntryType::EXIT:
 338     // If we've decided to log the function exit, we will never erase the log
 339     // before it.
 340     NumConsecutiveFnEnters = 0;
 341     NumTailCalls = 0;
 342     FuncRecord.RecordKind = uint8_t(FunctionRecord::RecordKinds::FunctionExit);
 343     break;
 344   case XRayEntryType::TAIL:
 345     // If we just entered the function we're tail exiting from or erased every
 346     // invocation since then, this function entry tail pair is a candidate to
 347     // be erased when the child function exits.
 348     if (NumConsecutiveFnEnters > 0) {
 349       ++NumTailCalls;
 350       NumConsecutiveFnEnters = 0;
 351     } else {
 352       // We will never be able to erase this tail call since we have logged
 353       // something in between the function entry and tail exit.
 354       NumTailCalls = 0;
 355       NumConsecutiveFnEnters = 0;
 356     }
 357     FuncRecord.RecordKind =
 358         uint8_t(FunctionRecord::RecordKinds::FunctionTailExit);
 359     break;
 360   case XRayEntryType::CUSTOM_EVENT: {
 361     // This is a bug in patching, so we'll report it once and move on.
 362     static bool Once = [&] {
 363       Report("Internal error: patched an XRay custom event call as a function; "
 364              "func id = %d\n",
 365              FuncId);
 366       return true;
 367     }();
 368     (void)Once;
 369     return;
 370   }
 371   }
 372
 373   std::memcpy(MemPtr, &AlignedFuncRecordBuffer, sizeof(FunctionRecord));
 374   MemPtr += sizeof(FunctionRecord);
 375 }
 376
 377 static uint64_t thresholdTicks() {
 378   static uint64_t TicksPerSec = probeRequiredCPUFeatures()
 379                                     ? getTSCFrequency()
 380                                     : __xray::NanosecondsPerSecond;
 381   static const uint64_t ThresholdTicks =
 382       TicksPerSec * flags()->xray_fdr_log_func_duration_threshold_us / 1000000;
 383   return ThresholdTicks;
 384 }
 385
 386 // Re-point the thread local pointer into this thread's Buffer before the recent
 387 // "Function Entry" record and any "Tail Call Exit" records after that.
 388 static void rewindRecentCall(uint64_t TSC, uint64_t &LastTSC,
 389                              uint64_t &LastFunctionEntryTSC, int32_t FuncId) {
 390   using AlignedFuncStorage =
 391       std::aligned_storage<sizeof(FunctionRecord),
 392                            alignof(FunctionRecord)>::type;
 393   RecordPtr -= FunctionRecSize;
 394   AlignedFuncStorage AlignedFuncRecordBuffer;
 395   const auto &FuncRecord = *reinterpret_cast<FunctionRecord *>(
 396       std::memcpy(&AlignedFuncRecordBuffer, RecordPtr, FunctionRecSize));
 397   assert(FuncRecord.RecordKind ==
 398              uint8_t(FunctionRecord::RecordKinds::FunctionEnter) &&
 399          "Expected to find function entry recording when rewinding.");
 400   assert(FuncRecord.FuncId == (FuncId & ~(0x0F << 28)) &&
 401          "Expected matching function id when rewinding Exit");
 402   --NumConsecutiveFnEnters;
 403   LastTSC -= FuncRecord.TSCDelta;
 404
 405   // We unwound one call. Update the state and return without writing a log.
 406   if (NumConsecutiveFnEnters != 0) {
 407     LastFunctionEntryTSC -= FuncRecord.TSCDelta;
 408     return;
 409   }
 410
 411   // Otherwise we've rewound the stack of all function entries, we might be
 412   // able to rewind further by erasing tail call functions that are being
 413   // exited from via this exit.
 414   LastFunctionEntryTSC = 0;
 415   auto RewindingTSC = LastTSC;
 416   auto RewindingRecordPtr = RecordPtr - FunctionRecSize;
 417   while (NumTailCalls > 0) {
 418     AlignedFuncStorage TailExitRecordBuffer;
 419     // Rewind the TSC back over the TAIL EXIT record.
 420     const auto &ExpectedTailExit =
 421         *reinterpret_cast<FunctionRecord *>(std::memcpy(
 422             &TailExitRecordBuffer, RewindingRecordPtr, FunctionRecSize));
 423
 424     assert(ExpectedTailExit.RecordKind ==
 425                uint8_t(FunctionRecord::RecordKinds::FunctionTailExit) &&
 426            "Expected to find tail exit when rewinding.");
 427     RewindingRecordPtr -= FunctionRecSize;
 428     RewindingTSC -= ExpectedTailExit.TSCDelta;
 429     AlignedFuncStorage FunctionEntryBuffer;
 430     const auto &ExpectedFunctionEntry = *reinterpret_cast<FunctionRecord *>(
 431         std::memcpy(&FunctionEntryBuffer, RewindingRecordPtr, FunctionRecSize));
 432     assert(ExpectedFunctionEntry.RecordKind ==
 433                uint8_t(FunctionRecord::RecordKinds::FunctionEnter) &&
 434            "Expected to find function entry when rewinding tail call.");
 435     assert(ExpectedFunctionEntry.FuncId == ExpectedTailExit.FuncId &&
 436            "Expected funcids to match when rewinding tail call.");
 437
 438     // This tail call exceeded the threshold duration. It will not be erased.
 439     if ((TSC - RewindingTSC) >= thresholdTicks()) {
 440       NumTailCalls = 0;
 441       return;
 442     }
 443
 444     // We can erase a tail exit pair that we're exiting through since
 445     // its duration is under threshold.
 446     --NumTailCalls;
 447     RewindingRecordPtr -= FunctionRecSize;
 448     RewindingTSC -= ExpectedFunctionEntry.TSCDelta;
 449     RecordPtr -= 2 * FunctionRecSize;
 450     LastTSC = RewindingTSC;
 451   }
 452 }
 453
 454 inline bool releaseThreadLocalBuffer(BufferQueue *BQ) {
 455   auto EC = BQ->releaseBuffer(Buffer);
 456   if (EC != BufferQueue::ErrorCode::Ok) {
 457     Report("Failed to release buffer at %p; error=%s\n", Buffer.Buffer,
 458            BufferQueue::getErrorString(EC));
 459     return false;
 460   }
 461   return true;
 462 }
 463
 464 inline bool prepareBuffer(int (*wall_clock_reader)(clockid_t,
 465                                                    struct timespec *),
 466                           size_t MaxSize) XRAY_NEVER_INSTRUMENT {
 467   char *BufferStart = static_cast<char *>(Buffer.Buffer);
 468   if ((RecordPtr + MaxSize) > (BufferStart + Buffer.Size - MetadataRecSize)) {
 469     writeEOBMetadata();
 470     if (!releaseThreadLocalBuffer(LocalBQ.get()))
 471       return false;
 472     auto EC = LocalBQ->getBuffer(Buffer);
 473     if (EC != BufferQueue::ErrorCode::Ok) {
 474       Report("Failed to acquire a buffer; error=%s\n",
 475              BufferQueue::getErrorString(EC));
 476       return false;
 477     }
 478     setupNewBuffer(wall_clock_reader);
 479   }
 480   return true;
 481 }
 482
 483 inline bool isLogInitializedAndReady(
 484     std::shared_ptr<BufferQueue> &LocalBQ, uint64_t TSC, unsigned char CPU,
 485     int (*wall_clock_reader)(clockid_t,
 486                              struct timespec *)) XRAY_NEVER_INSTRUMENT {
 487   // Bail out right away if logging is not initialized yet.
 488   // We should take the opportunity to release the buffer though.
 489   auto Status = __sanitizer::atomic_load(&LoggingStatus,
 490                                          __sanitizer::memory_order_acquire);
 491   if (Status != XRayLogInitStatus::XRAY_LOG_INITIALIZED) {
 492     if (RecordPtr != nullptr &&
 493         (Status == XRayLogInitStatus::XRAY_LOG_FINALIZING ||
 494          Status == XRayLogInitStatus::XRAY_LOG_FINALIZED)) {
 495       writeEOBMetadata();
 496       if (!releaseThreadLocalBuffer(LocalBQ.get()))
 497         return false;
 498       RecordPtr = nullptr;
 499       LocalBQ = nullptr;
 500       return false;
 501     }
 502     return false;
 503   }
 504
 505   if (!loggingInitialized(LoggingStatus) || LocalBQ->finalizing()) {
 506     writeEOBMetadata();
 507     if (!releaseThreadLocalBuffer(LocalBQ.get()))
 508       return false;
 509     RecordPtr = nullptr;
 510   }
 511
 512   if (Buffer.Buffer == nullptr) {
 513     auto EC = LocalBQ->getBuffer(Buffer);
 514     if (EC != BufferQueue::ErrorCode::Ok) {
 515       auto LS = __sanitizer::atomic_load(&LoggingStatus,
 516                                          __sanitizer::memory_order_acquire);
 517       if (LS != XRayLogInitStatus::XRAY_LOG_FINALIZING &&
 518           LS != XRayLogInitStatus::XRAY_LOG_FINALIZED)
 519         Report("Failed to acquire a buffer; error=%s\n",
 520                BufferQueue::getErrorString(EC));
 521       return false;
 522     }
 523
 524     setupNewBuffer(wall_clock_reader);
 525   }
 526
 527   if (CurrentCPU == std::numeric_limits<uint16_t>::max()) {
 528     // This means this is the first CPU this thread has ever run on. We set
 529     // the current CPU and record this as the first TSC we've seen.
 530     CurrentCPU = CPU;
 531     writeNewCPUIdMetadata(CPU, TSC);
 532   }
 533
 534   return true;
 535 } // namespace __xray_fdr_internal
 536
 537 inline void endBufferIfFull() XRAY_NEVER_INSTRUMENT {
 538   auto BufferStart = static_cast<char *>(Buffer.Buffer);
 539   if ((RecordPtr + MetadataRecSize) - BufferStart == MetadataRecSize) {
 540     writeEOBMetadata();
 541     if (!releaseThreadLocalBuffer(LocalBQ.get()))
 542       return;
 543     RecordPtr = nullptr;
 544   }
 545 }
 546
 547 inline void processFunctionHook(
 548     int32_t FuncId, XRayEntryType Entry, uint64_t TSC, unsigned char CPU,
 549     int (*wall_clock_reader)(clockid_t, struct timespec *),
 550     __sanitizer::atomic_sint32_t &LoggingStatus,
 551     const std::shared_ptr<BufferQueue> &BQ) XRAY_NEVER_INSTRUMENT {
 552   // Prevent signal handler recursion, so in case we're already in a log writing
 553   // mode and the signal handler comes in (and is also instrumented) then we
 554   // don't want to be clobbering potentially partial writes already happening in
 555   // the thread. We use a simple thread_local latch to only allow one on-going
 556   // handleArg0 to happen at any given time.
 557   thread_local bool Running = false;
 558   RecursionGuard Guard{Running};
 559   if (!Guard) {
 560     assert(Running == true && "RecursionGuard is buggy!");
 561     return;
 562   }
 563
 564   // In case the reference has been cleaned up before, we make sure we
 565   // initialize it to the provided BufferQueue.
 566   if (LocalBQ == nullptr)
 567     LocalBQ = BQ;
 568
 569   if (!isLogInitializedAndReady(LocalBQ, TSC, CPU, wall_clock_reader))
 570     return;
 571
 572   // Before we go setting up writing new function entries, we need to be really
 573   // careful about the pointer math we're doing. This means we need to ensure
 574   // that the record we are about to write is going to fit into the buffer,
 575   // without overflowing the buffer.
 576   //
 577   // To do this properly, we use the following assumptions:
 578   //
 579   //   - The least number of bytes we will ever write is 8
 580   //     (sizeof(FunctionRecord)) only if the delta between the previous entry
 581   //     and this entry is within 32 bits.
 582   //   - The most number of bytes we will ever write is 8 + 16 = 24. This is
 583   //     computed by:
 584   //
 585   //       sizeof(FunctionRecord) + sizeof(MetadataRecord)
 586   //
 587   //     These arise in the following cases:
 588   //
 589   //       1. When the delta between the TSC we get and the previous TSC for the
 590   //          same CPU is outside of the uint32_t range, we end up having to
 591   //          write a MetadataRecord to indicate a "tsc wrap" before the actual
 592   //          FunctionRecord.
 593   //       2. When we learn that we've moved CPUs, we need to write a
 594   //          MetadataRecord to indicate a "cpu change", and thus write out the
 595   //          current TSC for that CPU before writing out the actual
 596   //          FunctionRecord.
 597   //       3. When we learn about a new CPU ID, we need to write down a "new cpu
 598   //          id" MetadataRecord before writing out the actual FunctionRecord.
 599   //
 600   //   - An End-of-Buffer (EOB) MetadataRecord is 16 bytes.
 601   //
 602   // So the math we need to do is to determine whether writing 24 bytes past the
 603   // current pointer leaves us with enough bytes to write the EOB
 604   // MetadataRecord. If we don't have enough space after writing as much as 24
 605   // bytes in the end of the buffer, we need to write out the EOB, get a new
 606   // Buffer, set it up properly before doing any further writing.
 607   //
 608   if (!prepareBuffer(wall_clock_reader, FunctionRecSize + MetadataRecSize)) {
 609     LocalBQ = nullptr;
 610     return;
 611   }
 612
 613   // By this point, we are now ready to write at most 24 bytes (one metadata
 614   // record and one function record).
 615   assert((RecordPtr + (MetadataRecSize + FunctionRecSize)) -
 616                  static_cast<char *>(Buffer.Buffer) >=
 617              static_cast<ptrdiff_t>(MetadataRecSize) &&
 618          "Misconfigured BufferQueue provided; Buffer size not large enough.");
 619
 620   // Here we compute the TSC Delta. There are a few interesting situations we
 621   // need to account for:
 622   //
 623   //   - The thread has migrated to a different CPU. If this is the case, then
 624   //     we write down the following records:
 625   //
 626   //       1. A 'NewCPUId' Metadata record.
 627   //       2. A FunctionRecord with a 0 for the TSCDelta field.
 628   //
 629   //   - The TSC delta is greater than the 32 bits we can store in a
 630   //     FunctionRecord. In this case we write down the following records:
 631   //
 632   //       1. A 'TSCWrap' Metadata record.
 633   //       2. A FunctionRecord with a 0 for the TSCDelta field.
 634   //
 635   //   - The TSC delta is representable within the 32 bits we can store in a
 636   //     FunctionRecord. In this case we write down just a FunctionRecord with
 637   //     the correct TSC delta.
 638   //
 639   uint32_t RecordTSCDelta = 0;
 640   if (CPU != CurrentCPU) {
 641     // We've moved to a new CPU.
 642     writeNewCPUIdMetadata(CPU, TSC);
 643   } else {
 644     // If the delta is greater than the range for a uint32_t, then we write out
 645     // the TSC wrap metadata entry with the full TSC, and the TSC for the
 646     // function record be 0.
 647     auto Delta = TSC - LastTSC;
 648     if (Delta > (1ULL << 32) - 1)
 649       writeTSCWrapMetadata(TSC);
 650     else
 651       RecordTSCDelta = Delta;
 652   }
 653
 654   LastTSC = TSC;
 655   CurrentCPU = CPU;
 656   switch (Entry) {
 657   case XRayEntryType::ENTRY:
 658   case XRayEntryType::LOG_ARGS_ENTRY:
 659     // Update the thread local state for the next invocation.
 660     LastFunctionEntryTSC = TSC;
 661     break;
 662   case XRayEntryType::TAIL:
 663     break;
 664   case XRayEntryType::EXIT:
 665     // Break out and write the exit record if we can't erase any functions.
 666     if (NumConsecutiveFnEnters == 0 ||
 667         (TSC - LastFunctionEntryTSC) >= thresholdTicks())
 668       break;
 669     rewindRecentCall(TSC, LastTSC, LastFunctionEntryTSC, FuncId);
 670     return; // without writing log.
 671   case XRayEntryType::CUSTOM_EVENT: {
 672     // This is a bug in patching, so we'll report it once and move on.
 673     static bool Once = [&] {
 674       Report("Internal error: patched an XRay custom event call as a function; "
 675              "func id = %d",
 676              FuncId);
 677       return true;
 678     }();
 679     (void)Once;
 680     return;
 681   }
 682   }
 683
 684   writeFunctionRecord(FuncId, RecordTSCDelta, Entry, RecordPtr);
 685
 686   // If we've exhausted the buffer by this time, we then release the buffer to
 687   // make sure that other threads may start using this buffer.
 688   endBufferIfFull();
 689 }
 690
 691 } // namespace __xray_fdr_internal
 692 } // namespace __xray
 693
 694 #endif // XRAY_XRAY_FDR_LOGGING_IMPL_H