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

   1 //===-- xray_fdr_logging.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 // Here we implement the Flight Data Recorder mode for XRay, where we use
  13 // compact structures to store records in memory as well as when writing out the
  14 // data to files.
  15 //
  16 //===----------------------------------------------------------------------===//
  17 #include "xray_fdr_logging.h"
  18 #include <algorithm>
  19 #include <bitset>
  20 #include <cerrno>
  21 #include <cstring>
  22 #include <sys/syscall.h>
  23 #include <sys/time.h>
  24 #include <time.h>
  25 #include <unistd.h>
  26 #include <unordered_map>
  27
  28 #include "sanitizer_common/sanitizer_atomic.h"
  29 #include "sanitizer_common/sanitizer_common.h"
  30 #include "xray/xray_interface.h"
  31 #include "xray/xray_records.h"
  32 #include "xray_buffer_queue.h"
  33 #include "xray_defs.h"
  34 #include "xray_fdr_logging_impl.h"
  35 #include "xray_flags.h"
  36 #include "xray_tsc.h"
  37 #include "xray_utils.h"
  38
  39 namespace __xray {
  40
  41 // Global BufferQueue.
  42 std::shared_ptr<BufferQueue> BQ;
  43
  44 __sanitizer::atomic_sint32_t LogFlushStatus = {
  45     XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING};
  46
  47 FDRLoggingOptions FDROptions;
  48
  49 __sanitizer::SpinMutex FDROptionsMutex;
  50
  51 // Must finalize before flushing.
  52 XRayLogFlushStatus fdrLoggingFlush() XRAY_NEVER_INSTRUMENT {
  53   if (__sanitizer::atomic_load(&LoggingStatus,
  54                                __sanitizer::memory_order_acquire) !=
  55       XRayLogInitStatus::XRAY_LOG_FINALIZED)
  56     return XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING;
  57
  58   s32 Result = XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING;
  59   if (!__sanitizer::atomic_compare_exchange_strong(
  60           &LogFlushStatus, &Result, XRayLogFlushStatus::XRAY_LOG_FLUSHING,
  61           __sanitizer::memory_order_release))
  62     return static_cast<XRayLogFlushStatus>(Result);
  63
  64   // Make a copy of the BufferQueue pointer to prevent other threads that may be
  65   // resetting it from blowing away the queue prematurely while we're dealing
  66   // with it.
  67   auto LocalBQ = BQ;
  68
  69   // We write out the file in the following format:
  70   //
  71   //   1) We write down the XRay file header with version 1, type FDR_LOG.
  72   //   2) Then we use the 'apply' member of the BufferQueue that's live, to
  73   //      ensure that at this point in time we write down the buffers that have
  74   //      been released (and marked "used") -- we dump the full buffer for now
  75   //      (fixed-sized) and let the tools reading the buffers deal with the data
  76   //      afterwards.
  77   //
  78   int Fd = -1;
  79   {
  80     __sanitizer::SpinMutexLock Guard(&FDROptionsMutex);
  81     Fd = FDROptions.Fd;
  82   }
  83   if (Fd == -1)
  84     Fd = getLogFD();
  85   if (Fd == -1) {
  86     auto Result = XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING;
  87     __sanitizer::atomic_store(&LogFlushStatus, Result,
  88                               __sanitizer::memory_order_release);
  89     return Result;
  90   }
  91
  92   // Test for required CPU features and cache the cycle frequency
  93   static bool TSCSupported = probeRequiredCPUFeatures();
  94   static uint64_t CycleFrequency =
  95       TSCSupported ? getTSCFrequency() : __xray::NanosecondsPerSecond;
  96
  97   XRayFileHeader Header;
  98   Header.Version = 1;
  99   Header.Type = FileTypes::FDR_LOG;
 100   Header.CycleFrequency = CycleFrequency;
 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   Header.FdrData = FdrAdditionalHeaderData{LocalBQ->ConfiguredBufferSize()};
 106   retryingWriteAll(Fd, reinterpret_cast<char *>(&Header),
 107                    reinterpret_cast<char *>(&Header) + sizeof(Header));
 108
 109   LocalBQ->apply([&](const BufferQueue::Buffer &B) {
 110     uint64_t BufferSize = B.Size;
 111     if (BufferSize > 0) {
 112       retryingWriteAll(Fd, reinterpret_cast<char *>(B.Buffer),
 113                        reinterpret_cast<char *>(B.Buffer) + B.Size);
 114     }
 115   });
 116   __sanitizer::atomic_store(&LogFlushStatus,
 117                             XRayLogFlushStatus::XRAY_LOG_FLUSHED,
 118                             __sanitizer::memory_order_release);
 119   return XRayLogFlushStatus::XRAY_LOG_FLUSHED;
 120 }
 121
 122 XRayLogInitStatus fdrLoggingFinalize() XRAY_NEVER_INSTRUMENT {
 123   s32 CurrentStatus = XRayLogInitStatus::XRAY_LOG_INITIALIZED;
 124   if (!__sanitizer::atomic_compare_exchange_strong(
 125           &LoggingStatus, &CurrentStatus,
 126           XRayLogInitStatus::XRAY_LOG_FINALIZING,
 127           __sanitizer::memory_order_release))
 128     return static_cast<XRayLogInitStatus>(CurrentStatus);
 129
 130   // Do special things to make the log finalize itself, and not allow any more
 131   // operations to be performed until re-initialized.
 132   BQ->finalize();
 133
 134   __sanitizer::atomic_store(&LoggingStatus,
 135                             XRayLogInitStatus::XRAY_LOG_FINALIZED,
 136                             __sanitizer::memory_order_release);
 137   return XRayLogInitStatus::XRAY_LOG_FINALIZED;
 138 }
 139
 140 XRayLogInitStatus fdrLoggingReset() XRAY_NEVER_INSTRUMENT {
 141   s32 CurrentStatus = XRayLogInitStatus::XRAY_LOG_FINALIZED;
 142   if (__sanitizer::atomic_compare_exchange_strong(
 143           &LoggingStatus, &CurrentStatus,
 144           XRayLogInitStatus::XRAY_LOG_INITIALIZED,
 145           __sanitizer::memory_order_release))
 146     return static_cast<XRayLogInitStatus>(CurrentStatus);
 147
 148   // Release the in-memory buffer queue.
 149   BQ.reset();
 150
 151   // Spin until the flushing status is flushed.
 152   s32 CurrentFlushingStatus = XRayLogFlushStatus::XRAY_LOG_FLUSHED;
 153   while (__sanitizer::atomic_compare_exchange_weak(
 154       &LogFlushStatus, &CurrentFlushingStatus,
 155       XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING,
 156       __sanitizer::memory_order_release)) {
 157     if (CurrentFlushingStatus == XRayLogFlushStatus::XRAY_LOG_NOT_FLUSHING)
 158       break;
 159     CurrentFlushingStatus = XRayLogFlushStatus::XRAY_LOG_FLUSHED;
 160   }
 161
 162   // At this point, we know that the status is flushed, and that we can assume
 163   return XRayLogInitStatus::XRAY_LOG_UNINITIALIZED;
 164 }
 165
 166 static std::tuple<uint64_t, unsigned char>
 167 getTimestamp() XRAY_NEVER_INSTRUMENT {
 168   // We want to get the TSC as early as possible, so that we can check whether
 169   // we've seen this CPU before. We also do it before we load anything else, to
 170   // allow for forward progress with the scheduling.
 171   unsigned char CPU;
 172   uint64_t TSC;
 173
 174   // Test once for required CPU features
 175   static bool TSCSupported = probeRequiredCPUFeatures();
 176
 177   if (TSCSupported) {
 178     TSC = __xray::readTSC(CPU);
 179   } else {
 180     // FIXME: This code needs refactoring as it appears in multiple locations
 181     timespec TS;
 182     int result = clock_gettime(CLOCK_REALTIME, &TS);
 183     if (result != 0) {
 184       Report("clock_gettime(2) return %d, errno=%d", result, int(errno));
 185       TS = {0, 0};
 186     }
 187     CPU = 0;
 188     TSC = TS.tv_sec * __xray::NanosecondsPerSecond + TS.tv_nsec;
 189   }
 190   return std::make_tuple(TSC, CPU);
 191 }
 192
 193 void fdrLoggingHandleArg0(int32_t FuncId,
 194                           XRayEntryType Entry) XRAY_NEVER_INSTRUMENT {
 195   auto TSC_CPU = getTimestamp();
 196   __xray_fdr_internal::processFunctionHook(FuncId, Entry, std::get<0>(TSC_CPU),
 197                                            std::get<1>(TSC_CPU), clock_gettime,
 198                                            LoggingStatus, BQ);
 199 }
 200
 201 void fdrLoggingHandleCustomEvent(void *Event,
 202                                  std::size_t EventSize) XRAY_NEVER_INSTRUMENT {
 203   using namespace __xray_fdr_internal;
 204   auto TSC_CPU = getTimestamp();
 205   auto &TSC = std::get<0>(TSC_CPU);
 206   auto &CPU = std::get<1>(TSC_CPU);
 207   thread_local bool Running = false;
 208   RecursionGuard Guard{Running};
 209   if (!Guard) {
 210     assert(Running && "RecursionGuard is buggy!");
 211     return;
 212   }
 213   if (EventSize > std::numeric_limits<int32_t>::max()) {
 214     using Empty = struct {};
 215     static Empty Once = [&] {
 216       Report("Event size too large = %zu ; > max = %d\n", EventSize,
 217              std::numeric_limits<int32_t>::max());
 218       return Empty();
 219     }();
 220     (void)Once;
 221   }
 222   int32_t ReducedEventSize = static_cast<int32_t>(EventSize);
 223   if (!isLogInitializedAndReady(LocalBQ, TSC, CPU, clock_gettime))
 224     return;
 225
 226   // Here we need to prepare the log to handle:
 227   //   - The metadata record we're going to write. (16 bytes)
 228   //   - The additional data we're going to write. Currently, that's the size of
 229   //   the event we're going to dump into the log as free-form bytes.
 230   if (!prepareBuffer(clock_gettime, MetadataRecSize + EventSize)) {
 231     LocalBQ = nullptr;
 232     return;
 233   }
 234
 235   // Write the custom event metadata record, which consists of the following
 236   // information:
 237   //   - 8 bytes (64-bits) for the full TSC when the event started.
 238   //   - 4 bytes (32-bits) for the length of the data.
 239   MetadataRecord CustomEvent;
 240   CustomEvent.Type = uint8_t(RecordType::Metadata);
 241   CustomEvent.RecordKind =
 242       uint8_t(MetadataRecord::RecordKinds::CustomEventMarker);
 243   constexpr auto TSCSize = sizeof(std::get<0>(TSC_CPU));
 244   std::memcpy(&CustomEvent.Data, &ReducedEventSize, sizeof(int32_t));
 245   std::memcpy(&CustomEvent.Data[sizeof(int32_t)], &TSC, TSCSize);
 246   std::memcpy(RecordPtr, &CustomEvent, sizeof(CustomEvent));
 247   RecordPtr += sizeof(CustomEvent);
 248   std::memcpy(RecordPtr, Event, ReducedEventSize);
 249   endBufferIfFull();
 250 }
 251
 252 XRayLogInitStatus fdrLoggingInit(std::size_t BufferSize, std::size_t BufferMax,
 253                                  void *Options,
 254                                  size_t OptionsSize) XRAY_NEVER_INSTRUMENT {
 255   if (OptionsSize != sizeof(FDRLoggingOptions))
 256     return static_cast<XRayLogInitStatus>(__sanitizer::atomic_load(
 257         &LoggingStatus, __sanitizer::memory_order_acquire));
 258   s32 CurrentStatus = XRayLogInitStatus::XRAY_LOG_UNINITIALIZED;
 259   if (!__sanitizer::atomic_compare_exchange_strong(
 260           &LoggingStatus, &CurrentStatus,
 261           XRayLogInitStatus::XRAY_LOG_INITIALIZING,
 262           __sanitizer::memory_order_release))
 263     return static_cast<XRayLogInitStatus>(CurrentStatus);
 264
 265   {
 266     __sanitizer::SpinMutexLock Guard(&FDROptionsMutex);
 267     memcpy(&FDROptions, Options, OptionsSize);
 268   }
 269
 270   bool Success = false;
 271   BQ = std::make_shared<BufferQueue>(BufferSize, BufferMax, Success);
 272   if (!Success) {
 273     Report("BufferQueue init failed.\n");
 274     return XRayLogInitStatus::XRAY_LOG_UNINITIALIZED;
 275   }
 276
 277   // Install the actual handleArg0 handler after initialising the buffers.
 278   __xray_set_handler(fdrLoggingHandleArg0);
 279   __xray_set_customevent_handler(fdrLoggingHandleCustomEvent);
 280
 281   __sanitizer::atomic_store(&LoggingStatus,
 282                             XRayLogInitStatus::XRAY_LOG_INITIALIZED,
 283                             __sanitizer::memory_order_release);
 284   Report("XRay FDR init successful.\n");
 285   return XRayLogInitStatus::XRAY_LOG_INITIALIZED;
 286 }
 287
 288 } // namespace __xray
 289
 290 static auto UNUSED Unused = [] {
 291   using namespace __xray;
 292   if (flags()->xray_fdr_log) {
 293     XRayLogImpl Impl{
 294         fdrLoggingInit, fdrLoggingFinalize, fdrLoggingHandleArg0,
 295         fdrLoggingFlush,
 296     };
 297     __xray_set_log_impl(Impl);
 298   }
 299   return true;
 300 }();