diff options
Diffstat (limited to 'contrib/llvm-project/compiler-rt/lib/xray/xray_basic_logging.cpp')
| -rw-r--r-- | contrib/llvm-project/compiler-rt/lib/xray/xray_basic_logging.cpp | 515 | 
1 files changed, 515 insertions, 0 deletions
| diff --git a/contrib/llvm-project/compiler-rt/lib/xray/xray_basic_logging.cpp b/contrib/llvm-project/compiler-rt/lib/xray/xray_basic_logging.cpp new file mode 100644 index 000000000000..6ac5417bef75 --- /dev/null +++ b/contrib/llvm-project/compiler-rt/lib/xray/xray_basic_logging.cpp @@ -0,0 +1,515 @@ +//===-- xray_basic_logging.cpp ----------------------------------*- C++ -*-===// +// +// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions. +// See https://llvm.org/LICENSE.txt for license information. +// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception +// +//===----------------------------------------------------------------------===// +// +// This file is a part of XRay, a dynamic runtime instrumentation system. +// +// Implementation of a simple in-memory log of XRay events. This defines a +// logging function that's compatible with the XRay handler interface, and +// routines for exporting data to files. +// +//===----------------------------------------------------------------------===// + +#include <errno.h> +#include <fcntl.h> +#include <pthread.h> +#include <sys/stat.h> +#if SANITIZER_FREEBSD || SANITIZER_NETBSD || SANITIZER_APPLE +#include <sys/syscall.h> +#endif +#include <sys/types.h> +#include <time.h> +#include <unistd.h> + +#include "sanitizer_common/sanitizer_allocator_internal.h" +#include "sanitizer_common/sanitizer_libc.h" +#include "xray/xray_records.h" +#include "xray_recursion_guard.h" +#include "xray_basic_flags.h" +#include "xray_basic_logging.h" +#include "xray_defs.h" +#include "xray_flags.h" +#include "xray_interface_internal.h" +#include "xray_tsc.h" +#include "xray_utils.h" + +namespace __xray { + +static SpinMutex LogMutex; + +namespace { +// We use elements of this type to record the entry TSC of every function ID we +// see as we're tracing a particular thread's execution. +struct alignas(16) StackEntry { +  int32_t FuncId; +  uint16_t Type; +  uint8_t CPU; +  uint8_t Padding; +  uint64_t TSC; +}; + +static_assert(sizeof(StackEntry) == 16, "Wrong size for StackEntry"); + +struct XRAY_TLS_ALIGNAS(64) ThreadLocalData { +  void *InMemoryBuffer = nullptr; +  size_t BufferSize = 0; +  size_t BufferOffset = 0; +  void *ShadowStack = nullptr; +  size_t StackSize = 0; +  size_t StackEntries = 0; +  __xray::LogWriter *LogWriter = nullptr; +}; + +struct BasicLoggingOptions { +  int DurationFilterMicros = 0; +  size_t MaxStackDepth = 0; +  size_t ThreadBufferSize = 0; +}; +} // namespace + +static pthread_key_t PThreadKey; + +static atomic_uint8_t BasicInitialized{0}; + +struct BasicLoggingOptions GlobalOptions; + +thread_local atomic_uint8_t Guard{0}; + +static atomic_uint8_t UseRealTSC{0}; +static atomic_uint64_t ThresholdTicks{0}; +static atomic_uint64_t TicksPerSec{0}; +static atomic_uint64_t CycleFrequency{NanosecondsPerSecond}; + +static LogWriter *getLog() XRAY_NEVER_INSTRUMENT { +  LogWriter* LW = LogWriter::Open(); +  if (LW == nullptr) +    return LW; + +  static pthread_once_t DetectOnce = PTHREAD_ONCE_INIT; +  pthread_once(&DetectOnce, +[] { +    if (atomic_load(&UseRealTSC, memory_order_acquire)) +      atomic_store(&CycleFrequency, getTSCFrequency(), memory_order_release); +  }); + +  // Since we're here, we get to write the header. We set it up so that the +  // header will only be written once, at the start, and let the threads +  // logging do writes which just append. +  XRayFileHeader Header; +  // Version 2 includes tail exit records. +  // Version 3 includes pid inside records. +  Header.Version = 3; +  Header.Type = FileTypes::NAIVE_LOG; +  Header.CycleFrequency = atomic_load(&CycleFrequency, memory_order_acquire); + +  // FIXME: Actually check whether we have 'constant_tsc' and 'nonstop_tsc' +  // before setting the values in the header. +  Header.ConstantTSC = 1; +  Header.NonstopTSC = 1; +  LW->WriteAll(reinterpret_cast<char *>(&Header), +               reinterpret_cast<char *>(&Header) + sizeof(Header)); +  return LW; +} + +static LogWriter *getGlobalLog() XRAY_NEVER_INSTRUMENT { +  static pthread_once_t OnceInit = PTHREAD_ONCE_INIT; +  static LogWriter *LW = nullptr; +  pthread_once(&OnceInit, +[] { LW = getLog(); }); +  return LW; +} + +static ThreadLocalData &getThreadLocalData() XRAY_NEVER_INSTRUMENT { +  thread_local ThreadLocalData TLD; +  thread_local bool UNUSED TOnce = [] { +    if (GlobalOptions.ThreadBufferSize == 0) { +      if (Verbosity()) +        Report("Not initializing TLD since ThreadBufferSize == 0.\n"); +      return false; +    } +    pthread_setspecific(PThreadKey, &TLD); +    TLD.LogWriter = getGlobalLog(); +    TLD.InMemoryBuffer = reinterpret_cast<XRayRecord *>( +        InternalAlloc(sizeof(XRayRecord) * GlobalOptions.ThreadBufferSize, +                      nullptr, alignof(XRayRecord))); +    TLD.BufferSize = GlobalOptions.ThreadBufferSize; +    TLD.BufferOffset = 0; +    if (GlobalOptions.MaxStackDepth == 0) { +      if (Verbosity()) +        Report("Not initializing the ShadowStack since MaxStackDepth == 0.\n"); +      TLD.StackSize = 0; +      TLD.StackEntries = 0; +      TLD.ShadowStack = nullptr; +      return false; +    } +    TLD.ShadowStack = reinterpret_cast<StackEntry *>( +        InternalAlloc(sizeof(StackEntry) * GlobalOptions.MaxStackDepth, nullptr, +                      alignof(StackEntry))); +    TLD.StackSize = GlobalOptions.MaxStackDepth; +    TLD.StackEntries = 0; +    return false; +  }(); +  return TLD; +} + +template <class RDTSC> +void InMemoryRawLog(int32_t FuncId, XRayEntryType Type, +                    RDTSC ReadTSC) XRAY_NEVER_INSTRUMENT { +  auto &TLD = getThreadLocalData(); +  LogWriter *LW = getGlobalLog(); +  if (LW == nullptr) +    return; + +  // Use a simple recursion guard, to handle cases where we're already logging +  // and for one reason or another, this function gets called again in the same +  // thread. +  RecursionGuard G(Guard); +  if (!G) +    return; + +  uint8_t CPU = 0; +  uint64_t TSC = ReadTSC(CPU); + +  switch (Type) { +  case XRayEntryType::ENTRY: +  case XRayEntryType::LOG_ARGS_ENTRY: { +    // Short circuit if we've reached the maximum depth of the stack. +    if (TLD.StackEntries++ >= TLD.StackSize) +      return; + +    // When we encounter an entry event, we keep track of the TSC and the CPU, +    // and put it in the stack. +    StackEntry E; +    E.FuncId = FuncId; +    E.CPU = CPU; +    E.Type = Type; +    E.TSC = TSC; +    auto StackEntryPtr = static_cast<char *>(TLD.ShadowStack) + +                         (sizeof(StackEntry) * (TLD.StackEntries - 1)); +    internal_memcpy(StackEntryPtr, &E, sizeof(StackEntry)); +    break; +  } +  case XRayEntryType::EXIT: +  case XRayEntryType::TAIL: { +    if (TLD.StackEntries == 0) +      break; + +    if (--TLD.StackEntries >= TLD.StackSize) +      return; + +    // When we encounter an exit event, we check whether all the following are +    // true: +    // +    // - The Function ID is the same as the most recent entry in the stack. +    // - The CPU is the same as the most recent entry in the stack. +    // - The Delta of the TSCs is less than the threshold amount of time we're +    //   looking to record. +    // +    // If all of these conditions are true, we pop the stack and don't write a +    // record and move the record offset back. +    StackEntry StackTop; +    auto StackEntryPtr = static_cast<char *>(TLD.ShadowStack) + +                         (sizeof(StackEntry) * TLD.StackEntries); +    internal_memcpy(&StackTop, StackEntryPtr, sizeof(StackEntry)); +    if (StackTop.FuncId == FuncId && StackTop.CPU == CPU && +        StackTop.TSC < TSC) { +      auto Delta = TSC - StackTop.TSC; +      if (Delta < atomic_load(&ThresholdTicks, memory_order_relaxed)) { +        DCHECK(TLD.BufferOffset > 0); +        TLD.BufferOffset -= StackTop.Type == XRayEntryType::ENTRY ? 1 : 2; +        return; +      } +    } +    break; +  } +  default: +    // Should be unreachable. +    DCHECK(false && "Unsupported XRayEntryType encountered."); +    break; +  } + +  // First determine whether the delta between the function's enter record and +  // the exit record is higher than the threshold. +  XRayRecord R; +  R.RecordType = RecordTypes::NORMAL; +  R.CPU = CPU; +  R.TSC = TSC; +  R.TId = GetTid();  +  R.PId = internal_getpid();  +  R.Type = Type; +  R.FuncId = FuncId; +  auto FirstEntry = reinterpret_cast<XRayRecord *>(TLD.InMemoryBuffer); +  internal_memcpy(FirstEntry + TLD.BufferOffset, &R, sizeof(R)); +  if (++TLD.BufferOffset == TLD.BufferSize) { +    SpinMutexLock Lock(&LogMutex); +    LW->WriteAll(reinterpret_cast<char *>(FirstEntry), +                 reinterpret_cast<char *>(FirstEntry + TLD.BufferOffset)); +    TLD.BufferOffset = 0; +    TLD.StackEntries = 0; +  } +} + +template <class RDTSC> +void InMemoryRawLogWithArg(int32_t FuncId, XRayEntryType Type, uint64_t Arg1, +                           RDTSC ReadTSC) XRAY_NEVER_INSTRUMENT { +  auto &TLD = getThreadLocalData(); +  auto FirstEntry = +      reinterpret_cast<XRayArgPayload *>(TLD.InMemoryBuffer); +  const auto &BuffLen = TLD.BufferSize; +  LogWriter *LW = getGlobalLog(); +  if (LW == nullptr) +    return; + +  // First we check whether there's enough space to write the data consecutively +  // in the thread-local buffer. If not, we first flush the buffer before +  // attempting to write the two records that must be consecutive. +  if (TLD.BufferOffset + 2 > BuffLen) { +    SpinMutexLock Lock(&LogMutex); +    LW->WriteAll(reinterpret_cast<char *>(FirstEntry), +                 reinterpret_cast<char *>(FirstEntry + TLD.BufferOffset)); +    TLD.BufferOffset = 0; +    TLD.StackEntries = 0; +  } + +  // Then we write the "we have an argument" record. +  InMemoryRawLog(FuncId, Type, ReadTSC); + +  RecursionGuard G(Guard); +  if (!G) +    return; + +  // And, from here on write the arg payload. +  XRayArgPayload R; +  R.RecordType = RecordTypes::ARG_PAYLOAD; +  R.FuncId = FuncId; +  R.TId = GetTid();  +  R.PId = internal_getpid();  +  R.Arg = Arg1; +  internal_memcpy(FirstEntry + TLD.BufferOffset, &R, sizeof(R)); +  if (++TLD.BufferOffset == BuffLen) { +    SpinMutexLock Lock(&LogMutex); +    LW->WriteAll(reinterpret_cast<char *>(FirstEntry), +                 reinterpret_cast<char *>(FirstEntry + TLD.BufferOffset)); +    TLD.BufferOffset = 0; +    TLD.StackEntries = 0; +  } +} + +void basicLoggingHandleArg0RealTSC(int32_t FuncId, +                                   XRayEntryType Type) XRAY_NEVER_INSTRUMENT { +  InMemoryRawLog(FuncId, Type, readTSC); +} + +void basicLoggingHandleArg0EmulateTSC(int32_t FuncId, XRayEntryType Type) +    XRAY_NEVER_INSTRUMENT { +  InMemoryRawLog(FuncId, Type, [](uint8_t &CPU) XRAY_NEVER_INSTRUMENT { +    timespec TS; +    int result = clock_gettime(CLOCK_REALTIME, &TS); +    if (result != 0) { +      Report("clock_gettimg(2) return %d, errno=%d.", result, int(errno)); +      TS = {0, 0}; +    } +    CPU = 0; +    return TS.tv_sec * NanosecondsPerSecond + TS.tv_nsec; +  }); +} + +void basicLoggingHandleArg1RealTSC(int32_t FuncId, XRayEntryType Type, +                                   uint64_t Arg1) XRAY_NEVER_INSTRUMENT { +  InMemoryRawLogWithArg(FuncId, Type, Arg1, readTSC); +} + +void basicLoggingHandleArg1EmulateTSC(int32_t FuncId, XRayEntryType Type, +                                      uint64_t Arg1) XRAY_NEVER_INSTRUMENT { +  InMemoryRawLogWithArg( +      FuncId, Type, Arg1, [](uint8_t &CPU) XRAY_NEVER_INSTRUMENT { +        timespec TS; +        int result = clock_gettime(CLOCK_REALTIME, &TS); +        if (result != 0) { +          Report("clock_gettimg(2) return %d, errno=%d.", result, int(errno)); +          TS = {0, 0}; +        } +        CPU = 0; +        return TS.tv_sec * NanosecondsPerSecond + TS.tv_nsec; +      }); +} + +static void TLDDestructor(void *P) XRAY_NEVER_INSTRUMENT { +  ThreadLocalData &TLD = *reinterpret_cast<ThreadLocalData *>(P); +  auto ExitGuard = at_scope_exit([&TLD] { +    // Clean up dynamic resources. +    if (TLD.InMemoryBuffer) +      InternalFree(TLD.InMemoryBuffer); +    if (TLD.ShadowStack) +      InternalFree(TLD.ShadowStack); +    if (Verbosity()) +      Report("Cleaned up log for TID: %llu\n", GetTid()); +  }); + +  if (TLD.LogWriter == nullptr || TLD.BufferOffset == 0) { +    if (Verbosity()) +      Report("Skipping buffer for TID: %llu; Offset = %zu\n", GetTid(), +             TLD.BufferOffset); +    return; +  } + +  { +    SpinMutexLock L(&LogMutex); +    TLD.LogWriter->WriteAll(reinterpret_cast<char *>(TLD.InMemoryBuffer), +                            reinterpret_cast<char *>(TLD.InMemoryBuffer) + +                            (sizeof(XRayRecord) * TLD.BufferOffset)); +  } + +  // Because this thread's exit could be the last one trying to write to +  // the file and that we're not able to close out the file properly, we +  // sync instead and hope that the pending writes are flushed as the +  // thread exits. +  TLD.LogWriter->Flush(); +} + +XRayLogInitStatus basicLoggingInit(UNUSED size_t BufferSize, +                                   UNUSED size_t BufferMax, void *Options, +                                   size_t OptionsSize) XRAY_NEVER_INSTRUMENT { +  uint8_t Expected = 0; +  if (!atomic_compare_exchange_strong(&BasicInitialized, &Expected, 1, +                                      memory_order_acq_rel)) { +    if (Verbosity()) +      Report("Basic logging already initialized.\n"); +    return XRayLogInitStatus::XRAY_LOG_INITIALIZED; +  } + +  static pthread_once_t OnceInit = PTHREAD_ONCE_INIT; +  pthread_once(&OnceInit, +[] { +    pthread_key_create(&PThreadKey, TLDDestructor); +    atomic_store(&UseRealTSC, probeRequiredCPUFeatures(), memory_order_release); +    // Initialize the global TicksPerSec value. +    atomic_store(&TicksPerSec, +                 probeRequiredCPUFeatures() ? getTSCFrequency() +                                            : NanosecondsPerSecond, +                 memory_order_release); +    if (!atomic_load(&UseRealTSC, memory_order_relaxed) && Verbosity()) +      Report("WARNING: Required CPU features missing for XRay instrumentation, " +             "using emulation instead.\n"); +  }); + +  FlagParser P; +  BasicFlags F; +  F.setDefaults(); +  registerXRayBasicFlags(&P, &F); +  P.ParseString(useCompilerDefinedBasicFlags()); +  auto *EnvOpts = GetEnv("XRAY_BASIC_OPTIONS"); +  if (EnvOpts == nullptr) +    EnvOpts = ""; + +  P.ParseString(EnvOpts); + +  // If XRAY_BASIC_OPTIONS was not defined, then we use the deprecated options +  // set through XRAY_OPTIONS instead. +  if (internal_strlen(EnvOpts) == 0) { +    F.func_duration_threshold_us = +        flags()->xray_naive_log_func_duration_threshold_us; +    F.max_stack_depth = flags()->xray_naive_log_max_stack_depth; +    F.thread_buffer_size = flags()->xray_naive_log_thread_buffer_size; +  } + +  P.ParseString(static_cast<const char *>(Options)); +  GlobalOptions.ThreadBufferSize = F.thread_buffer_size; +  GlobalOptions.DurationFilterMicros = F.func_duration_threshold_us; +  GlobalOptions.MaxStackDepth = F.max_stack_depth; +  *basicFlags() = F; + +  atomic_store(&ThresholdTicks, +               atomic_load(&TicksPerSec, memory_order_acquire) * +                   GlobalOptions.DurationFilterMicros / 1000000, +               memory_order_release); +  __xray_set_handler_arg1(atomic_load(&UseRealTSC, memory_order_acquire) +                              ? basicLoggingHandleArg1RealTSC +                              : basicLoggingHandleArg1EmulateTSC); +  __xray_set_handler(atomic_load(&UseRealTSC, memory_order_acquire) +                         ? basicLoggingHandleArg0RealTSC +                         : basicLoggingHandleArg0EmulateTSC); + +  // TODO: Implement custom event and typed event handling support in Basic +  // Mode. +  __xray_remove_customevent_handler(); +  __xray_remove_typedevent_handler(); + +  return XRayLogInitStatus::XRAY_LOG_INITIALIZED; +} + +XRayLogInitStatus basicLoggingFinalize() XRAY_NEVER_INSTRUMENT { +  uint8_t Expected = 0; +  if (!atomic_compare_exchange_strong(&BasicInitialized, &Expected, 0, +                                      memory_order_acq_rel) && +      Verbosity()) +    Report("Basic logging already finalized.\n"); + +  // Nothing really to do aside from marking state of the global to be +  // uninitialized. + +  return XRayLogInitStatus::XRAY_LOG_FINALIZED; +} + +XRayLogFlushStatus basicLoggingFlush() XRAY_NEVER_INSTRUMENT { +  // This really does nothing, since flushing the logs happen at the end of a +  // thread's lifetime, or when the buffers are full. +  return XRayLogFlushStatus::XRAY_LOG_FLUSHED; +} + +// This is a handler that, effectively, does nothing. +void basicLoggingHandleArg0Empty(int32_t, XRayEntryType) XRAY_NEVER_INSTRUMENT { +} + +bool basicLogDynamicInitializer() XRAY_NEVER_INSTRUMENT { +  XRayLogImpl Impl{ +      basicLoggingInit, +      basicLoggingFinalize, +      basicLoggingHandleArg0Empty, +      basicLoggingFlush, +  }; +  auto RegistrationResult = __xray_log_register_mode("xray-basic", Impl); +  if (RegistrationResult != XRayLogRegisterStatus::XRAY_REGISTRATION_OK && +      Verbosity()) +    Report("Cannot register XRay Basic Mode to 'xray-basic'; error = %d\n", +           RegistrationResult); +  if (flags()->xray_naive_log || +      !internal_strcmp(flags()->xray_mode, "xray-basic")) { +    auto SelectResult = __xray_log_select_mode("xray-basic"); +    if (SelectResult != XRayLogRegisterStatus::XRAY_REGISTRATION_OK) { +      if (Verbosity()) +        Report("Failed selecting XRay Basic Mode; error = %d\n", SelectResult); +      return false; +    } + +    // We initialize the implementation using the data we get from the +    // XRAY_BASIC_OPTIONS environment variable, at this point of the +    // implementation. +    auto *Env = GetEnv("XRAY_BASIC_OPTIONS"); +    auto InitResult = +        __xray_log_init_mode("xray-basic", Env == nullptr ? "" : Env); +    if (InitResult != XRayLogInitStatus::XRAY_LOG_INITIALIZED) { +      if (Verbosity()) +        Report("Failed initializing XRay Basic Mode; error = %d\n", InitResult); +      return false; +    } + +    // At this point we know that we've successfully initialized Basic mode +    // tracing, and the only chance we're going to get for the current thread to +    // clean-up may be at thread/program exit. To ensure that we're going to get +    // the cleanup even without calling the finalization routines, we're +    // registering a program exit function that will do the cleanup. +    static pthread_once_t DynamicOnce = PTHREAD_ONCE_INIT; +    pthread_once(&DynamicOnce, +[] { +      static void *FakeTLD = nullptr; +      FakeTLD = &getThreadLocalData(); +      Atexit(+[] { TLDDestructor(FakeTLD); }); +    }); +  } +  return true; +} + +} // namespace __xray + +static auto UNUSED Unused = __xray::basicLogDynamicInitializer(); | 
