contrib/compiler-rt/lib/xray/xray_inmemory_log.cc

   1 //===-- xray_inmemory_log.cc ------------------------------------*- 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 // Implementation of a simple in-memory log of XRay events. This defines a
  13 // logging function that's compatible with the XRay handler interface, and
  14 // routines for exporting data to files.
  15 //
  16 //===----------------------------------------------------------------------===//
  17
  18 #include <cassert>
  19 #include <cstring>
  20 #include <errno.h>
  21 #include <fcntl.h>
  22 #include <pthread.h>
  23 #include <sys/stat.h>
  24 #include <sys/syscall.h>
  25 #include <sys/types.h>
  26 #include <time.h>
  27 #include <unistd.h>
  28
  29 #include "sanitizer_common/sanitizer_allocator_internal.h"
  30 #include "sanitizer_common/sanitizer_libc.h"
  31 #include "xray/xray_records.h"
  32 #include "xray_defs.h"
  33 #include "xray_flags.h"
  34 #include "xray_inmemory_log.h"
  35 #include "xray_interface_internal.h"
  36 #include "xray_tsc.h"
  37 #include "xray_utils.h"
  38
  39 namespace __xray {
  40
  41 __sanitizer::SpinMutex LogMutex;
  42
  43 // We use elements of this type to record the entry TSC of every function ID we
  44 // see as we're tracing a particular thread's execution.
  45 struct alignas(16) StackEntry {
  46   int32_t FuncId;
  47   uint16_t Type;
  48   uint8_t CPU;
  49   uint8_t Padding;
  50   uint64_t TSC;
  51 };
  52
  53 static_assert(sizeof(StackEntry) == 16, "Wrong size for StackEntry");
  54
  55 struct alignas(64) ThreadLocalData {
  56   void *InMemoryBuffer = nullptr;
  57   size_t BufferSize = 0;
  58   size_t BufferOffset = 0;
  59   void *ShadowStack = nullptr;
  60   size_t StackSize = 0;
  61   size_t StackEntries = 0;
  62   int Fd = -1;
  63   pid_t TID = 0;
  64 };
  65
  66 static pthread_key_t PThreadKey;
  67
  68 static __sanitizer::atomic_uint8_t BasicInitialized{0};
  69
  70 BasicLoggingOptions GlobalOptions;
  71
  72 thread_local volatile bool RecursionGuard = false;
  73
  74 static uint64_t thresholdTicks() XRAY_NEVER_INSTRUMENT {
  75   static uint64_t TicksPerSec = probeRequiredCPUFeatures()
  76                                     ? getTSCFrequency()
  77                                     : __xray::NanosecondsPerSecond;
  78   static const uint64_t ThresholdTicks =
  79       TicksPerSec * GlobalOptions.DurationFilterMicros / 1000000;
  80   return ThresholdTicks;
  81 }
  82
  83 static int openLogFile() XRAY_NEVER_INSTRUMENT {
  84   int F = getLogFD();
  85   if (F == -1)
  86     return -1;
  87
  88   // Test for required CPU features and cache the cycle frequency
  89   static bool TSCSupported = probeRequiredCPUFeatures();
  90   static uint64_t CycleFrequency =
  91       TSCSupported ? getTSCFrequency() : __xray::NanosecondsPerSecond;
  92
  93   // Since we're here, we get to write the header. We set it up so that the
  94   // header will only be written once, at the start, and let the threads
  95   // logging do writes which just append.
  96   XRayFileHeader Header;
  97   Header.Version = 2; // Version 2 includes tail exit records.
  98   Header.Type = FileTypes::NAIVE_LOG;
  99   Header.CycleFrequency = CycleFrequency;
 100
 101   // FIXME: Actually check whether we have 'constant_tsc' and 'nonstop_tsc'
 102   // before setting the values in the header.
 103   Header.ConstantTSC = 1;
 104   Header.NonstopTSC = 1;
 105   retryingWriteAll(F, reinterpret_cast<char *>(&Header),
 106                    reinterpret_cast<char *>(&Header) + sizeof(Header));
 107   return F;
 108 }
 109
 110 int getGlobalFd() XRAY_NEVER_INSTRUMENT {
 111   static int Fd = openLogFile();
 112   return Fd;
 113 }
 114
 115 ThreadLocalData &getThreadLocalData() XRAY_NEVER_INSTRUMENT {
 116   thread_local ThreadLocalData TLD;
 117   thread_local bool UNUSED TOnce = [] {
 118     if (GlobalOptions.ThreadBufferSize == 0) {
 119       if (__sanitizer::Verbosity())
 120         Report("Not initializing TLD since ThreadBufferSize == 0.\n");
 121       return false;
 122     }
 123     TLD.TID = __sanitizer::GetTid();
 124     pthread_setspecific(PThreadKey, &TLD);
 125     TLD.Fd = getGlobalFd();
 126     TLD.InMemoryBuffer = reinterpret_cast<XRayRecord *>(
 127         InternalAlloc(sizeof(XRayRecord) * GlobalOptions.ThreadBufferSize,
 128                       nullptr, alignof(XRayRecord)));
 129     TLD.BufferSize = GlobalOptions.ThreadBufferSize;
 130     TLD.BufferOffset = 0;
 131     if (GlobalOptions.MaxStackDepth == 0) {
 132       if (__sanitizer::Verbosity())
 133         Report("Not initializing the ShadowStack since MaxStackDepth == 0.\n");
 134       TLD.StackSize = 0;
 135       TLD.StackEntries = 0;
 136       TLD.ShadowStack = nullptr;
 137       return false;
 138     }
 139     TLD.ShadowStack = reinterpret_cast<StackEntry *>(
 140         InternalAlloc(sizeof(StackEntry) * GlobalOptions.MaxStackDepth, nullptr,
 141                       alignof(StackEntry)));
 142     TLD.StackSize = GlobalOptions.MaxStackDepth;
 143     TLD.StackEntries = 0;
 144     if (__sanitizer::Verbosity() >= 2) {
 145       static auto UNUSED Once = [] {
 146         auto ticks = thresholdTicks();
 147         Report("Ticks threshold: %d\n", ticks);
 148         return false;
 149       }();
 150     }
 151     return false;
 152   }();
 153   return TLD;
 154 }
 155
 156 template <class RDTSC>
 157 void InMemoryRawLog(int32_t FuncId, XRayEntryType Type,
 158                     RDTSC ReadTSC) XRAY_NEVER_INSTRUMENT {
 159   auto &TLD = getThreadLocalData();
 160   auto &InMemoryBuffer = TLD.InMemoryBuffer;
 161   int Fd = getGlobalFd();
 162   if (Fd == -1)
 163     return;
 164
 165   // Use a simple recursion guard, to handle cases where we're already logging
 166   // and for one reason or another, this function gets called again in the same
 167   // thread.
 168   if (RecursionGuard)
 169     return;
 170   RecursionGuard = true;
 171   auto ExitGuard = __sanitizer::at_scope_exit([] { RecursionGuard = false; });
 172
 173   uint8_t CPU = 0;
 174   uint64_t TSC = ReadTSC(CPU);
 175
 176   switch (Type) {
 177   case XRayEntryType::ENTRY:
 178   case XRayEntryType::LOG_ARGS_ENTRY: {
 179     // Short circuit if we've reached the maximum depth of the stack.
 180     if (TLD.StackEntries++ >= TLD.StackSize)
 181       return;
 182
 183     // When we encounter an entry event, we keep track of the TSC and the CPU,
 184     // and put it in the stack.
 185     StackEntry E;
 186     E.FuncId = FuncId;
 187     E.CPU = CPU;
 188     E.Type = Type;
 189     E.TSC = TSC;
 190     auto StackEntryPtr = static_cast<char *>(TLD.ShadowStack) +
 191                          (sizeof(StackEntry) * (TLD.StackEntries - 1));
 192     __sanitizer::internal_memcpy(StackEntryPtr, &E, sizeof(StackEntry));
 193     break;
 194   }
 195   case XRayEntryType::EXIT:
 196   case XRayEntryType::TAIL: {
 197     if (TLD.StackEntries == 0)
 198       break;
 199
 200     if (--TLD.StackEntries >= TLD.StackSize)
 201       return;
 202
 203     // When we encounter an exit event, we check whether all the following are
 204     // true:
 205     //
 206     // - The Function ID is the same as the most recent entry in the stack.
 207     // - The CPU is the same as the most recent entry in the stack.
 208     // - The Delta of the TSCs is less than the threshold amount of time we're
 209     //   looking to record.
 210     //
 211     // If all of these conditions are true, we pop the stack and don't write a
 212     // record and move the record offset back.
 213     StackEntry StackTop;
 214     auto StackEntryPtr = static_cast<char *>(TLD.ShadowStack) +
 215                          (sizeof(StackEntry) * TLD.StackEntries);
 216     __sanitizer::internal_memcpy(&StackTop, StackEntryPtr, sizeof(StackEntry));
 217     if (StackTop.FuncId == FuncId && StackTop.CPU == CPU &&
 218         StackTop.TSC < TSC) {
 219       auto Delta = TSC - StackTop.TSC;
 220       if (Delta < thresholdTicks()) {
 221         assert(TLD.BufferOffset > 0);
 222         TLD.BufferOffset -= StackTop.Type == XRayEntryType::ENTRY ? 1 : 2;
 223         return;
 224       }
 225     }
 226     break;
 227   }
 228   default:
 229     // Should be unreachable.
 230     assert(false && "Unsupported XRayEntryType encountered.");
 231     break;
 232   }
 233
 234   // First determine whether the delta between the function's enter record and
 235   // the exit record is higher than the threshold.
 236   __xray::XRayRecord R;
 237   R.RecordType = RecordTypes::NORMAL;
 238   R.CPU = CPU;
 239   R.TSC = TSC;
 240   R.TId = TLD.TID;
 241   R.Type = Type;
 242   R.FuncId = FuncId;
 243   auto EntryPtr = static_cast<char *>(InMemoryBuffer) +
 244                   (sizeof(__xray::XRayRecord) * TLD.BufferOffset);
 245   __sanitizer::internal_memcpy(EntryPtr, &R, sizeof(R));
 246   if (++TLD.BufferOffset == TLD.BufferSize) {
 247     __sanitizer::SpinMutexLock L(&LogMutex);
 248     auto RecordBuffer = reinterpret_cast<__xray::XRayRecord *>(InMemoryBuffer);
 249     retryingWriteAll(Fd, reinterpret_cast<char *>(RecordBuffer),
 250                      reinterpret_cast<char *>(RecordBuffer + TLD.BufferOffset));
 251     TLD.BufferOffset = 0;
 252     TLD.StackEntries = 0;
 253   }
 254 }
 255
 256 template <class RDTSC>
 257 void InMemoryRawLogWithArg(int32_t FuncId, XRayEntryType Type, uint64_t Arg1,
 258                            RDTSC ReadTSC) XRAY_NEVER_INSTRUMENT {
 259   auto &TLD = getThreadLocalData();
 260   auto &InMemoryBuffer = TLD.InMemoryBuffer;
 261   auto &Offset = TLD.BufferOffset;
 262   const auto &BuffLen = TLD.BufferSize;
 263   int Fd = getGlobalFd();
 264   if (Fd == -1)
 265     return;
 266
 267   // First we check whether there's enough space to write the data consecutively
 268   // in the thread-local buffer. If not, we first flush the buffer before
 269   // attempting to write the two records that must be consecutive.
 270   if (Offset + 2 > BuffLen) {
 271     __sanitizer::SpinMutexLock L(&LogMutex);
 272     auto RecordBuffer = reinterpret_cast<__xray::XRayRecord *>(InMemoryBuffer);
 273     retryingWriteAll(Fd, reinterpret_cast<char *>(RecordBuffer),
 274                      reinterpret_cast<char *>(RecordBuffer + Offset));
 275     Offset = 0;
 276     TLD.StackEntries = 0;
 277   }
 278
 279   // Then we write the "we have an argument" record.
 280   InMemoryRawLog(FuncId, Type, ReadTSC);
 281
 282   if (RecursionGuard)
 283     return;
 284   RecursionGuard = true;
 285   auto ExitGuard = __sanitizer::at_scope_exit([] { RecursionGuard = false; });
 286
 287   // And from here on write the arg payload.
 288   __xray::XRayArgPayload R;
 289   R.RecordType = RecordTypes::ARG_PAYLOAD;
 290   R.FuncId = FuncId;
 291   R.TId = TLD.TID;
 292   R.Arg = Arg1;
 293   auto EntryPtr =
 294       &reinterpret_cast<__xray::XRayArgPayload *>(&InMemoryBuffer)[Offset];
 295   std::memcpy(EntryPtr, &R, sizeof(R));
 296   if (++Offset == BuffLen) {
 297     __sanitizer::SpinMutexLock L(&LogMutex);
 298     auto RecordBuffer = reinterpret_cast<__xray::XRayRecord *>(InMemoryBuffer);
 299     retryingWriteAll(Fd, reinterpret_cast<char *>(RecordBuffer),
 300                      reinterpret_cast<char *>(RecordBuffer + Offset));
 301     Offset = 0;
 302     TLD.StackEntries = 0;
 303   }
 304 }
 305
 306 void basicLoggingHandleArg0RealTSC(int32_t FuncId,
 307                                    XRayEntryType Type) XRAY_NEVER_INSTRUMENT {
 308   InMemoryRawLog(FuncId, Type, __xray::readTSC);
 309 }
 310
 311 void basicLoggingHandleArg0EmulateTSC(int32_t FuncId, XRayEntryType Type)
 312     XRAY_NEVER_INSTRUMENT {
 313   InMemoryRawLog(FuncId, Type, [](uint8_t &CPU) XRAY_NEVER_INSTRUMENT {
 314     timespec TS;
 315     int result = clock_gettime(CLOCK_REALTIME, &TS);
 316     if (result != 0) {
 317       Report("clock_gettimg(2) return %d, errno=%d.", result, int(errno));
 318       TS = {0, 0};
 319     }
 320     CPU = 0;
 321     return TS.tv_sec * __xray::NanosecondsPerSecond + TS.tv_nsec;
 322   });
 323 }
 324
 325 void basicLoggingHandleArg1RealTSC(int32_t FuncId, XRayEntryType Type,
 326                                    uint64_t Arg1) XRAY_NEVER_INSTRUMENT {
 327   InMemoryRawLogWithArg(FuncId, Type, Arg1, __xray::readTSC);
 328 }
 329
 330 void basicLoggingHandleArg1EmulateTSC(int32_t FuncId, XRayEntryType Type,
 331                                       uint64_t Arg1) XRAY_NEVER_INSTRUMENT {
 332   InMemoryRawLogWithArg(
 333       FuncId, Type, Arg1, [](uint8_t &CPU) XRAY_NEVER_INSTRUMENT {
 334         timespec TS;
 335         int result = clock_gettime(CLOCK_REALTIME, &TS);
 336         if (result != 0) {
 337           Report("clock_gettimg(2) return %d, errno=%d.", result, int(errno));
 338           TS = {0, 0};
 339         }
 340         CPU = 0;
 341         return TS.tv_sec * __xray::NanosecondsPerSecond + TS.tv_nsec;
 342       });
 343 }
 344
 345 static void TLDDestructor(void *P) XRAY_NEVER_INSTRUMENT {
 346   ThreadLocalData &TLD = *reinterpret_cast<ThreadLocalData *>(P);
 347   auto ExitGuard = __sanitizer::at_scope_exit([&TLD] {
 348     // Clean up dynamic resources.
 349     if (TLD.InMemoryBuffer)
 350       InternalFree(TLD.InMemoryBuffer);
 351     if (TLD.ShadowStack)
 352       InternalFree(TLD.ShadowStack);
 353     if (__sanitizer::Verbosity())
 354       Report("Cleaned up log for TID: %d\n", TLD.TID);
 355   });
 356
 357   if (TLD.Fd == -1 || TLD.BufferOffset == 0) {
 358     if (__sanitizer::Verbosity())
 359       Report("Skipping buffer for TID: %d; Fd = %d; Offset = %llu\n", TLD.TID,
 360              TLD.Fd, TLD.BufferOffset);
 361     return;
 362   }
 363
 364   {
 365     __sanitizer::SpinMutexLock L(&LogMutex);
 366     retryingWriteAll(TLD.Fd, reinterpret_cast<char *>(TLD.InMemoryBuffer),
 367                      reinterpret_cast<char *>(TLD.InMemoryBuffer) +
 368                          (sizeof(__xray::XRayRecord) * TLD.BufferOffset));
 369   }
 370
 371   // Because this thread's exit could be the last one trying to write to
 372   // the file and that we're not able to close out the file properly, we
 373   // sync instead and hope that the pending writes are flushed as the
 374   // thread exits.
 375   fsync(TLD.Fd);
 376 }
 377
 378 XRayLogInitStatus basicLoggingInit(size_t BufferSize, size_t BufferMax,
 379                                    void *Options,
 380                                    size_t OptionsSize) XRAY_NEVER_INSTRUMENT {
 381   static bool UNUSED Once = [] {
 382     pthread_key_create(&PThreadKey, TLDDestructor);
 383     return false;
 384   }();
 385
 386   uint8_t Expected = 0;
 387   if (!__sanitizer::atomic_compare_exchange_strong(
 388           &BasicInitialized, &Expected, 1, __sanitizer::memory_order_acq_rel)) {
 389     if (__sanitizer::Verbosity())
 390       Report("Basic logging already initialized.\n");
 391     return XRayLogInitStatus::XRAY_LOG_INITIALIZED;
 392   }
 393
 394   if (OptionsSize != sizeof(BasicLoggingOptions)) {
 395     Report("Invalid options size, potential ABI mismatch; expected %d got %d",
 396            sizeof(BasicLoggingOptions), OptionsSize);
 397     return XRayLogInitStatus::XRAY_LOG_UNINITIALIZED;
 398   }
 399
 400   static auto UseRealTSC = probeRequiredCPUFeatures();
 401   if (!UseRealTSC && __sanitizer::Verbosity())
 402     Report("WARNING: Required CPU features missing for XRay instrumentation, "
 403            "using emulation instead.\n");
 404
 405   GlobalOptions = *reinterpret_cast<BasicLoggingOptions *>(Options);
 406   __xray_set_handler_arg1(UseRealTSC ? basicLoggingHandleArg1RealTSC
 407                                      : basicLoggingHandleArg1EmulateTSC);
 408   __xray_set_handler(UseRealTSC ? basicLoggingHandleArg0RealTSC
 409                                 : basicLoggingHandleArg0EmulateTSC);
 410   __xray_remove_customevent_handler();
 411
 412   return XRayLogInitStatus::XRAY_LOG_INITIALIZED;
 413 }
 414
 415 XRayLogInitStatus basicLoggingFinalize() XRAY_NEVER_INSTRUMENT {
 416   uint8_t Expected = 0;
 417   if (!__sanitizer::atomic_compare_exchange_strong(
 418           &BasicInitialized, &Expected, 0, __sanitizer::memory_order_acq_rel) &&
 419       __sanitizer::Verbosity())
 420     Report("Basic logging already finalized.\n");
 421
 422   // Nothing really to do aside from marking state of the global to be
 423   // uninitialized.
 424
 425   return XRayLogInitStatus::XRAY_LOG_FINALIZED;
 426 }
 427
 428 XRayLogFlushStatus basicLoggingFlush() XRAY_NEVER_INSTRUMENT {
 429   // This really does nothing, since flushing the logs happen at the end of a
 430   // thread's lifetime, or when the buffers are full.
 431   return XRayLogFlushStatus::XRAY_LOG_FLUSHED;
 432 }
 433
 434 // This is a handler that, effectively, does nothing.
 435 void basicLoggingHandleArg0Empty(int32_t, XRayEntryType) XRAY_NEVER_INSTRUMENT {
 436 }
 437
 438 bool basicLogDynamicInitializer() XRAY_NEVER_INSTRUMENT {
 439   XRayLogImpl Impl{
 440       basicLoggingInit,
 441       basicLoggingFinalize,
 442       basicLoggingHandleArg0Empty,
 443       basicLoggingFlush,
 444   };
 445   auto RegistrationResult = __xray_log_register_mode("xray-basic", Impl);
 446   if (RegistrationResult != XRayLogRegisterStatus::XRAY_REGISTRATION_OK &&
 447       __sanitizer::Verbosity())
 448     Report("Cannot register XRay Basic Mode to 'xray-basic'; error = %d\n",
 449            RegistrationResult);
 450   if (flags()->xray_naive_log ||
 451       !__sanitizer::internal_strcmp(flags()->xray_mode, "xray-basic")) {
 452     __xray_set_log_impl(Impl);
 453     BasicLoggingOptions Options;
 454     Options.DurationFilterMicros =
 455         flags()->xray_naive_log_func_duration_threshold_us;
 456     Options.MaxStackDepth = flags()->xray_naive_log_max_stack_depth;
 457     Options.ThreadBufferSize = flags()->xray_naive_log_thread_buffer_size;
 458     __xray_log_init(flags()->xray_naive_log_thread_buffer_size, 0, &Options,
 459                     sizeof(BasicLoggingOptions));
 460     static auto UNUSED Once = [] {
 461       static auto UNUSED &TLD = getThreadLocalData();
 462       __sanitizer::Atexit(+[] { TLDDestructor(&TLD); });
 463       return false;
 464     }();
 465   }
 466   return true;
 467 }
 468
 469 } // namespace __xray
 470
 471 static auto UNUSED Unused = __xray::basicLogDynamicInitializer();