[XRay] Use optimistic logging model for FDR mode

Summary:
Before this change, the FDR mode implementation relied on at thread-exit
handling to return buffers back to the (global) buffer queue. This
introduces issues with the initialisation of the thread_local objects
which, even through the use of pthread_setspecific(...) may eventually
call into an allocation function. Similar to previous changes in this
line, we're finding that there is a huge potential for deadlocks when
initialising these thread-locals when the memory allocation
implementation is also xray-instrumented.

In this change, we limit the call to pthread_setspecific(...) to provide
a non-null value to associate to the key created with
pthread_key_create(...). While this doesn't completely eliminate the
potential for the deadlock(s), it does allow us to still clean up at
thread exit when we need to. The change is that we don't need to do more
work when starting and ending a thread's lifetime. We also have a test
to make sure that we actually can safely recycle the buffers in case we
end up re-using the buffer(s) available from the queue on multiple
thread entry/exits.

This change cuts across both LLVM and compiler-rt to allow us to update
both the XRay runtime implementation as well as the library support for
loading these new versions of the FDR mode logging. Version 2 of the FDR
logging implementation makes the following changes:

  * Introduction of a new 'BufferExtents' metadata record that's outside
    of the buffer's contents but are written before the actual buffer.
    This data is associated to the Buffer handed out by the BufferQueue
    rather than a record that occupies bytes in the actual buffer.

  * Removal of the "end of buffer" records. This is in-line with the
    changes we described above, to allow for optimistic logging without
    explicit record writing at thread exit.

The optimistic logging model operates under the following assumptions:

  * Threads writing to the buffers will potentially race with the thread
    attempting to flush the log. To avoid this situation from occuring,
    we make sure that when we've finalized the logging implementation,
    that threads will see this finalization state on the next write, and
    either choose to not write records the thread would have written or
    write the record(s) in two phases -- first write the record(s), then
    update the extents metadata.

  * We change the buffer queue implementation so that once it's handed
    out a buffer to a thread, that we assume that buffer is marked
    "used" to be able to capture partial writes. None of this will be
    safe to handle if threads are racing to write the extents records
    and the reader thread is attempting to flush the log. The optimism
    comes from the finalization routine being required to complete
    before we attempt to flush the log.

This is a fairly significant semantics change for the FDR
implementation. This is why we've decided to update the version number
for FDR mode logs. The tools, however, still need to be able to support
older versions of the log until we finally deprecate those earlier
versions.

Reviewers: dblaikie, pelikan, kpw

Subscribers: llvm-commits, hiraditya

Differential Revision: https://reviews.llvm.org/D39526

llvm-svn: 318733

1 files changed, 122 insertions, 22 deletions

diff --git a/llvm/lib/XRay/Trace.cpp b/llvm/lib/XRay/Trace.cpp
index d4ce6b2ffeb..d1fcf1c35b3 100644
--- a/llvm/lib/XRay/Trace.cpp
+++ b/llvm/lib/XRay/Trace.cpp
@@ -159,6 +159,7 @@ struct FDRState {
     SCAN_TO_END_OF_THREAD_BUF,
     CUSTOM_EVENT_DATA,
     CALL_ARGUMENT,
+    BUFFER_EXTENTS,
   };
   Token Expects;
 
@@ -184,6 +185,8 @@ const char *fdrStateToTwine(const FDRState::Token &state) {
     return "CUSTOM_EVENT_DATA";
   case FDRState::Token::CALL_ARGUMENT:
     return "CALL_ARGUMENT";
+  case FDRState::Token::BUFFER_EXTENTS:
+    return "BUFFER_EXTENTS";
   }
   return "UNKNOWN";
 }
@@ -194,7 +197,9 @@ Error processFDRNewBufferRecord(FDRState &State, uint8_t RecordFirstByte,
 
   if (State.Expects != FDRState::Token::NEW_BUFFER_RECORD_OR_EOF)
     return make_error<StringError>(
-        "Malformed log. Read New Buffer record kind out of sequence",
+        Twine("Malformed log. Read New Buffer record kind out of sequence; "
+              "expected: ") +
+            fdrStateToTwine(State.Expects),
         std::make_error_code(std::errc::executable_format_error));
   uint32_t OffsetPtr = 1; // 1 byte into record.
   State.ThreadId = RecordExtractor.getU16(&OffsetPtr);
@@ -207,7 +212,9 @@ Error processFDREndOfBufferRecord(FDRState &State, uint8_t RecordFirstByte,
                                   DataExtractor &RecordExtractor) {
   if (State.Expects == FDRState::Token::NEW_BUFFER_RECORD_OR_EOF)
     return make_error<StringError>(
-        "Malformed log. Received EOB message without current buffer.",
+        Twine("Malformed log. Received EOB message without current buffer; "
+              "expected: ") +
+            fdrStateToTwine(State.Expects),
         std::make_error_code(std::errc::executable_format_error));
   State.Expects = FDRState::Token::SCAN_TO_END_OF_THREAD_BUF;
   return Error::success();
@@ -219,7 +226,9 @@ Error processFDRNewCPUIdRecord(FDRState &State, uint8_t RecordFirstByte,
   if (State.Expects != FDRState::Token::FUNCTION_SEQUENCE &&
       State.Expects != FDRState::Token::NEW_CPU_ID_RECORD)
     return make_error<StringError>(
-        "Malformed log. Read NewCPUId record kind out of sequence",
+        Twine("Malformed log. Read NewCPUId record kind out of sequence; "
+              "expected: ") +
+            fdrStateToTwine(State.Expects),
         std::make_error_code(std::errc::executable_format_error));
   uint32_t OffsetPtr = 1; // Read starting after the first byte.
   State.CPUId = RecordExtractor.getU16(&OffsetPtr);
@@ -233,7 +242,9 @@ Error processFDRTSCWrapRecord(FDRState &State, uint8_t RecordFirstByte,
                               DataExtractor &RecordExtractor) {
   if (State.Expects != FDRState::Token::FUNCTION_SEQUENCE)
     return make_error<StringError>(
-        "Malformed log. Read TSCWrap record kind out of sequence",
+        Twine("Malformed log. Read TSCWrap record kind out of sequence; "
+              "expecting: ") +
+            fdrStateToTwine(State.Expects),
         std::make_error_code(std::errc::executable_format_error));
   uint32_t OffsetPtr = 1; // Read starting after the first byte.
   State.BaseTSC = RecordExtractor.getU64(&OffsetPtr);
@@ -245,10 +256,13 @@ Error processFDRWallTimeRecord(FDRState &State, uint8_t RecordFirstByte,
                                DataExtractor &RecordExtractor) {
   if (State.Expects != FDRState::Token::WALLCLOCK_RECORD)
     return make_error<StringError>(
-        "Malformed log. Read Wallclock record kind out of sequence",
+        Twine("Malformed log. Read Wallclock record kind out of sequence; "
+              "expecting: ") +
+            fdrStateToTwine(State.Expects),
         std::make_error_code(std::errc::executable_format_error));
-  // We don't encode the wall time into any of the records.
-  // XRayRecords are concerned with the TSC instead.
+
+  // TODO: Someday, reconcile the TSC ticks to wall clock time for presentation
+  // purposes. For now, we're ignoring these records.
   State.Expects = FDRState::Token::NEW_CPU_ID_RECORD;
   return Error::success();
 }
@@ -271,6 +285,20 @@ Error processCustomEventMarker(FDRState &State, uint8_t RecordFirstByte,
   return Error::success();
 }
 
+/// State transition when an BufferExtents record is encountered.
+Error processBufferExtents(FDRState &State, uint8_t RecordFirstByte,
+                           DataExtractor &RecordExtractor) {
+  if (State.Expects != FDRState::Token::BUFFER_EXTENTS)
+    return make_error<StringError>(
+        Twine("Malformed log. Buffer Extents unexpected; expected: ") +
+            fdrStateToTwine(State.Expects),
+        std::make_error_code(std::errc::executable_format_error));
+  uint32_t OffsetPtr = 1; // Read after the first byte.
+  State.CurrentBufferSize = RecordExtractor.getU64(&OffsetPtr);
+  State.Expects = FDRState::Token::NEW_BUFFER_RECORD_OR_EOF;
+  return Error::success();
+}
+
 /// State transition when a CallArgumentRecord is encountered.
 Error processFDRCallArgumentRecord(FDRState &State, uint8_t RecordFirstByte,
                                    DataExtractor &RecordExtractor,
@@ -292,10 +320,15 @@ Error processFDRCallArgumentRecord(FDRState &State, uint8_t RecordFirstByte,
 /// record encountered. The RecordKind is encoded in the first byte of the
 /// Record, which the caller should pass in because they have already read it
 /// to determine that this is a metadata record as opposed to a function record.
+///
+/// Beginning with Version 2 of the FDR log, we do not depend on the size of the
+/// buffer, but rather use the extents to determine how far to read in the log
+/// for this particular buffer.
 Error processFDRMetadataRecord(FDRState &State, uint8_t RecordFirstByte,
                                DataExtractor &RecordExtractor,
                                size_t &RecordSize,
-                               std::vector<XRayRecord> &Records) {
+                               std::vector<XRayRecord> &Records,
+                               uint16_t Version) {
   // The remaining 7 bits are the RecordKind enum.
   uint8_t RecordKind = RecordFirstByte >> 1;
   switch (RecordKind) {
@@ -305,6 +338,10 @@ Error processFDRMetadataRecord(FDRState &State, uint8_t RecordFirstByte,
       return E;
     break;
   case 1: // EndOfBuffer
+    if (Version >= 2)
+      return make_error<StringError>(
+          "Since Version 2 of FDR logging, we no longer support EOB records.",
+          std::make_error_code(std::errc::executable_format_error));
     if (auto E = processFDREndOfBufferRecord(State, RecordFirstByte,
                                              RecordExtractor))
       return E;
@@ -334,6 +371,10 @@ Error processFDRMetadataRecord(FDRState &State, uint8_t RecordFirstByte,
                                               RecordExtractor, Records))
       return E;
     break;
+  case 7: // BufferExtents
+    if (auto E = processBufferExtents(State, RecordFirstByte, RecordExtractor))
+      return E;
+    break;
   default:
     // Widen the record type to uint16_t to prevent conversion to char.
     return make_error<StringError>(
@@ -425,7 +466,8 @@ Error processFDRFunctionRecord(FDRState &State, uint8_t RecordFirstByte,
 /// convention that BitFields within a struct will first be packed into the
 /// least significant bits the address they belong to.
 ///
-/// We expect a format complying with the grammar in the following pseudo-EBNF.
+/// We expect a format complying with the grammar in the following pseudo-EBNF
+/// in Version 1 of the FDR log.
 ///
 /// FDRLog: XRayFileHeader ThreadBuffer*
 /// XRayFileHeader: 32 bytes to identify the log as FDR with machine metadata.
@@ -439,6 +481,15 @@ Error processFDRFunctionRecord(FDRState &State, uint8_t RecordFirstByte,
 /// FunctionSequence: NewCPUId | TSCWrap | FunctionRecord
 /// TSCWrap: 16 byte metadata record with a full 64 bit TSC reading.
 /// FunctionRecord: 8 byte record with FunctionId, entry/exit, and TSC delta.
+///
+/// In Version 2, we make the following changes:
+///
+/// ThreadBuffer: BufferExtents NewBuffer WallClockTime NewCPUId
+///               FunctionSequence
+/// BufferExtents: 16 byte metdata record describing how many usable bytes are
+///                in the buffer. This is measured from the start of the buffer
+///                and must always be at least 48 (bytes).
+/// EOB: *deprecated*
 Error loadFDRLog(StringRef Data, XRayFileHeader &FileHeader,
                  std::vector<XRayRecord> &Records) {
   if (Data.size() < 32)
@@ -464,8 +515,22 @@ Error loadFDRLog(StringRef Data, XRayFileHeader &FileHeader,
     uint32_t ExtraDataOffset = 0;
     BufferSize = ExtraDataExtractor.getU64(&ExtraDataOffset);
   }
-  FDRState State{0,          0, 0, FDRState::Token::NEW_BUFFER_RECORD_OR_EOF,
-                 BufferSize, 0};
+
+  FDRState::Token InitialExpectation;
+  switch (FileHeader.Version) {
+  case 1:
+    InitialExpectation = FDRState::Token::NEW_BUFFER_RECORD_OR_EOF;
+    break;
+  case 2:
+    InitialExpectation = FDRState::Token::BUFFER_EXTENTS;
+    break;
+  default:
+    return make_error<StringError>(
+        Twine("Unsupported version '") + Twine(FileHeader.Version) + "'",
+        std::make_error_code(std::errc::executable_format_error));
+  }
+  FDRState State{0, 0, 0, InitialExpectation, BufferSize, 0};
+
   // RecordSize will tell the loop how far to seek ahead based on the record
   // type that we have just read.
   size_t RecordSize = 0;
@@ -486,10 +551,13 @@ Error loadFDRLog(StringRef Data, XRayFileHeader &FileHeader,
     }
     uint8_t BitField = RecordExtractor.getU8(&OffsetPtr);
     bool isMetadataRecord = BitField & 0x01uL;
+    bool isBufferExtents =
+        (BitField >> 1) == 7; // BufferExtents record kind == 7
     if (isMetadataRecord) {
       RecordSize = 16;
-      if (auto E = processFDRMetadataRecord(State, BitField, RecordExtractor,
-                                            RecordSize, Records))
+      if (auto E =
+              processFDRMetadataRecord(State, BitField, RecordExtractor,
+                                       RecordSize, Records, FileHeader.Version))
         return E;
     } else { // Process Function Record
       RecordSize = 8;
@@ -497,14 +565,29 @@ Error loadFDRLog(StringRef Data, XRayFileHeader &FileHeader,
                                             Records))
         return E;
     }
-    State.CurrentBufferConsumed += RecordSize;
+
+    // The BufferExtents record is technically not part of the buffer, so we
+    // don't count the size of that record against the buffer's actual size.
+    if (!isBufferExtents)
+      State.CurrentBufferConsumed += RecordSize;
+    assert(State.CurrentBufferConsumed <= State.CurrentBufferSize);
+    if (FileHeader.Version == 2 &&
+        State.CurrentBufferSize == State.CurrentBufferConsumed) {
+      // In Version 2 of the log, we don't need to scan to the end of the thread
+      // buffer if we've already consumed all the bytes we need to.
+      State.Expects = FDRState::Token::BUFFER_EXTENTS;
+      State.CurrentBufferSize = BufferSize;
+      State.CurrentBufferConsumed = 0;
+    }
   }
 
   // Having iterated over everything we've been given, we've either consumed
   // everything and ended up in the end state, or were told to skip the rest.
   bool Finished = State.Expects == FDRState::Token::SCAN_TO_END_OF_THREAD_BUF &&
                   State.CurrentBufferSize == State.CurrentBufferConsumed;
-  if (State.Expects != FDRState::Token::NEW_BUFFER_RECORD_OR_EOF && !Finished)
+  if ((State.Expects != FDRState::Token::NEW_BUFFER_RECORD_OR_EOF &&
+       State.Expects != FDRState::Token::BUFFER_EXTENTS) &&
+      !Finished)
     return make_error<StringError>(
         Twine("Encountered EOF with unexpected state expectation ") +
             fdrStateToTwine(State.Expects) +
@@ -579,6 +662,7 @@ Expected<Trace> llvm::xray::loadTraceFile(StringRef Filename, bool Sort) {
   //
   //   0x01 0x00 0x00 0x00 - version 1, "naive" format
   //   0x01 0x00 0x01 0x00 - version 1, "flight data recorder" format
+  //   0x02 0x00 0x01 0x00 - version 2, "flight data recorder" format
   //
   // YAML files don't typically have those first four bytes as valid text so we
   // try loading assuming YAML if we don't find these bytes.
@@ -594,13 +678,29 @@ Expected<Trace> llvm::xray::loadTraceFile(StringRef Filename, bool Sort) {
   enum BinaryFormatType { NAIVE_FORMAT = 0, FLIGHT_DATA_RECORDER_FORMAT = 1 };
 
   Trace T;
-  if (Type == NAIVE_FORMAT && (Version == 1 || Version == 2)) {
-    if (auto E = loadNaiveFormatLog(Data, T.FileHeader, T.Records))
-      return std::move(E);
-  } else if (Version == 1 && Type == FLIGHT_DATA_RECORDER_FORMAT) {
-    if (auto E = loadFDRLog(Data, T.FileHeader, T.Records))
-      return std::move(E);
-  } else {
+  switch (Type) {
+  case NAIVE_FORMAT:
+    if (Version == 1 || Version == 2) {
+      if (auto E = loadNaiveFormatLog(Data, T.FileHeader, T.Records))
+        return std::move(E);
+    } else {
+      return make_error<StringError>(
+          Twine("Unsupported version for Basic/Naive Mode logging: ") +
+              Twine(Version),
+          std::make_error_code(std::errc::executable_format_error));
+    }
+    break;
+  case FLIGHT_DATA_RECORDER_FORMAT:
+    if (Version == 1 || Version == 2) {
+      if (auto E = loadFDRLog(Data, T.FileHeader, T.Records))
+        return std::move(E);
+    } else {
+      return make_error<StringError>(
+          Twine("Unsupported version for FDR Mode logging: ") + Twine(Version),
+          std::make_error_code(std::errc::executable_format_error));
+    }
+    break;
+  default:
     if (auto E = loadYAMLLog(Data, T.FileHeader, T.Records))
       return std::move(E);
   }