[XRay] convert FDR arg1 log entries

[pelikan]

Summary

A new FDR metadata record will support logging function arguments
using a 16-bit position (we currently only plan to support "1" for arg1 logging)
and a 64-bit value (useful for "this" pointers and synchronization objects).
If present, we put this argument to the function call "entry" record it belongs
to, and alter its type to notify the user of the first argument's presence.

[dberris]

include/llvm/XRay/XRayRecord.h

77–78

For this API, I think it would make sense for us to use a std::vector<...> or even an llvm::SmallVector<uint64_t, 1> if we ever support more argument logging.

lib/XRay/Trace.cpp

224–227

If you supported multiple arguments today, you can make this error go away.

228

Have you considered parsing the following metadata record greedily here, instead of trying to refer to the last record in the vector?

274–279

Have you considered special handling for the "function with call arguments" instead of trying to handle the metadata records independently? Since this is already a greedy parser, it seems much simpler (and self-contained) to add another state for "we are parsing arguments". This way we can enforce that if we encounter records that indicate we are entering a function with arguments, that we should only look for metadata records following it that contain the arguments.

408–409

Did clang-format do this?

[dberris]

Adding in @kpw who knows this bit of code a lot better, can probably provide more insights too.

[pelikan]

after long discussions and long time on a different project, update to reflect comments

include/llvm/XRay/XRayRecord.h

77–78

Makes sense. Last discussion did clear up the intents of the API a lot.

lib/XRay/Trace.cpp

224–227

Changed everything as discussed.

228

The rest of the code does 1 record at a time, it didn't look appealing to me to deviate. It also isn't required for performance, and it's a very rare case.

274–279

Again, the rest of the code processes each record separately. It would look uglier IMO if only one case differed.

408–409

No, I had a previous version of the code there and later erased it. clang-format wants it to be the old way :-(

[dberris]

Looking better. I'll ask for tests now. :)

[kpw]

Looks reasonable. Here's some suggestions on prior integration tests that can be cargo culted.

If you are OK playing with a hex editor, making a test similar to llvm/test/tools/llvm-xray/X86/convert-fdr-to-yaml.txt could be a quick sanity check.

llvm/projects/compiler-rt/test/xray/TestCases/Linux/fdr-mode.cc uses a REQUIRES: built-in-llvm-tree to be able to use llvm-xray convert within a lit test after instrumenting a binary as well. You might be able to do something clever to have the program emit the memory address and use lit to capture it and see that it matches the ENTER_ARG value.

lib/XRay/Trace.cpp

217–238

we do se -> we do use?

[kpw]

include/llvm/XRay/XRayRecord.h

56

I just realized that doing this definition would be unfortunate, because we'll drift out of sync with XRayEntryType defined in compiler-rt/include/xray/xray_interface.h

enum XRayEntryType {
  ENTRY = 0,
  EXIT = 1,
  TAIL = 2,
  LOG_ARGS_ENTRY = 3,
  CUSTOM_EVENT = 4,
};

Could you either define TAIL or assign 3 to ENTER_ARG. Defining TAIL is likely better done in a separate patch that updates the llvm-xray subcommands to handle it.

[kpw]

include/llvm/XRay/XRayRecord.h

56

Ugh. These are also defined in AsmPrinter::SledKind.

[dberris]

Is there something else we need to do here?

[pelikan]

Rebased to HEAD, added a test. Not sure if it passes as I have to fix a local toolchain issue with some other tests.

[pelikan]

include/llvm/XRay/XRayRecord.h

56

Ugh indeed. I was under the impression this should be ignored as compiler-rt is "a different project". I've added the "= 3" there.

lib/XRay/Trace.cpp

217–238

Resolved in a different diff.

[dberris]

I'm adding support for tail exit records, can you wait on submitting this as this changes a number of similar places?

include/llvm/XRay/YAMLXRayRecord.h

89

What is this meant to do? Is it meant to force text wrapping? If so, please don't do that (it messes with the tests and the settings that can be defined on the YAML stream instead).

[pelikan]

I will wait for the other diff to go in then. In the meantime I can sort out my new system's toolchain issues.

include/llvm/XRay/YAMLXRayRecord.h

89

It's meant to *remove* text wrapping. Since we only really support one argument in the list, we want it to look like "[ 1 ]", not like "[\n\t1,\n]\n" or whatever it thinks is in order. This way each log entry will only occupy one line, as they should (both for readability and parsability).

[dberris]

I think you need to rebase this too. :)

include/llvm/XRay/YAMLXRayRecord.h

89

Isn't text wrapping controlled on the stream too? Or is this different?

I guess the question is whether this is actually required, or whether this is something controllable through the serialisation instead of being hard-coded on the type.

[pelikan]

include/llvm/XRay/YAMLXRayRecord.h

89

This isn't *stream* wrapping, this is just wrapping for the (one element) list of arguments. Trust me, I had to re-read the entire YAML code base just to find this flag, which fortunately does precisely what we want. :-)

[pelikan]

rebase to HEAD

[dberris]

LGTM -- thanks @pelikan!

[pelikan]

rebase again; tests now pass

include/llvm/XRay/XRayRecord.h

struct XRayFileHeader {
   // buffer.
   char FreeFormData[16];
 };
 
 /// Determines the supported types of records that could be seen in XRay traces.
 /// This may or may not correspond to actual record types in the raw trace (as
 /// the loader implementation may synthesize this information in the process of
 /// of loading).
-enum class RecordTypes { ENTER, EXIT };
+enum class RecordTypes { ENTER, EXIT, ENTER_ARG };
 
 struct XRayRecord {
   /// The type of record.
   uint16_t RecordType;
 
   /// The CPU where the thread is running. We assume number of CPUs <= 65536.
   uint16_t CPU;
 
   /// Identifies the type of record.
   RecordTypes Type;
 
   /// The function ID for the record.
   int32_t FuncId;
 
   /// Get the full 8 bytes of the TSC when we get the log record.
   uint64_t TSC;
 
   /// The thread ID for the currently running thread.
   uint32_t TId;
+
+  /// The function call argument.
+  uint64_t CallArg;
 };
 
 } // namespace xray
 } // namespace llvm
 
 #endif // LLVM_XRAY_XRAY_RECORD_H

include/llvm/XRay/YAMLXRayRecord.h

 struct YAMLXRayRecord {
   uint16_t RecordType;
   uint16_t CPU;
   RecordTypes Type;
   int32_t FuncId;
   std::string Function;
   uint64_t TSC;
   uint32_t TId;
+  uint64_t CallArg;
 };
 
 struct YAMLXRayTrace {
   YAMLXRayFileHeader Header;
   std::vector<YAMLXRayRecord> Records;
 };
 
 } // namespace xray
 
 namespace yaml {
 
 // YAML Traits
 // -----------
 template <> struct ScalarEnumerationTraits<xray::RecordTypes> {
   static void enumeration(IO &IO, xray::RecordTypes &Type) {
     IO.enumCase(Type, "function-enter", xray::RecordTypes::ENTER);
     IO.enumCase(Type, "function-exit", xray::RecordTypes::EXIT);
+    IO.enumCase(Type, "function-enter-arg", xray::RecordTypes::ENTER_ARG);
   }
 };
 
 template <> struct MappingTraits<xray::YAMLXRayFileHeader> {
   static void mapping(IO &IO, xray::YAMLXRayFileHeader &Header) {
     IO.mapRequired("version", Header.Version);
     IO.mapRequired("type", Header.Type);
     IO.mapRequired("constant-tsc", Header.ConstantTSC);
     IO.mapRequired("nonstop-tsc", Header.NonstopTSC);
     IO.mapRequired("cycle-frequency", Header.CycleFrequency);
   }
 };
 
 template <> struct MappingTraits<xray::YAMLXRayRecord> {
   static void mapping(IO &IO, xray::YAMLXRayRecord &Record) {
     // FIXME: Make this type actually be descriptive
     IO.mapRequired("type", Record.RecordType);
     IO.mapRequired("func-id", Record.FuncId);
     IO.mapOptional("function", Record.Function);
+    IO.mapOptional("arg1", Record.CallArg);
     IO.mapRequired("cpu", Record.CPU);
     IO.mapRequired("thread", Record.TId);
     IO.mapRequired("kind", Record.Type);
     IO.mapRequired("tsc", Record.TSC);
   }
 
   static constexpr bool flow = true;
 };
 
 template <> struct MappingTraits<xray::YAMLXRayTrace> {
   static void mapping(IO &IO, xray::YAMLXRayTrace &Trace) {
     // A trace file contains two parts, the header and the list of all the
     // trace records.
     IO.mapRequired("header", Trace.Header);
     IO.mapRequired("records", Trace.Records);
   }
 };
 
 } // namespace yaml
 } // namespace llvm
 
 LLVM_YAML_IS_SEQUENCE_VECTOR(xray::YAMLXRayRecord)
 
 #endif // LLVM_XRAY_YAML_XRAY_RECORD_H

lib/XRay/Trace.cpp

struct FDRState {
   /// Encode some of the state transitions for the FDR log reader as explicit
   /// checks. These are expectations for the next Record in the stream.
   enum class Token {
     NEW_BUFFER_RECORD_OR_EOF,
     WALLCLOCK_RECORD,
     NEW_CPU_ID_RECORD,
     FUNCTION_SEQUENCE,
     SCAN_TO_END_OF_THREAD_BUF,
+    CALL_ARGUMENT,
   };
   Token Expects;
   // Each threads buffer may have trailing garbage to scan over, so we track our
   // progress.
   uint64_t CurrentBufferSize;
   uint64_t CurrentBufferConsumed;
 };
 
 Twine fdrStateToTwine(const FDRState::Token &state) {
   switch (state) {
   case FDRState::Token::NEW_BUFFER_RECORD_OR_EOF:
     return "NEW_BUFFER_RECORD_OR_EOF";
   case FDRState::Token::WALLCLOCK_RECORD:
     return "WALLCLOCK_RECORD";
   case FDRState::Token::NEW_CPU_ID_RECORD:
     return "NEW_CPU_ID_RECORD";
   case FDRState::Token::FUNCTION_SEQUENCE:
     return "FUNCTION_SEQUENCE";
   case FDRState::Token::SCAN_TO_END_OF_THREAD_BUF:
     return "SCAN_TO_END_OF_THREAD_BUF";
+  case FDRState::Token::CALL_ARGUMENT:
+    return "CALL_ARGUMENT";
   }
   return "UNKNOWN";
 }
 
 /// State transition when a NewBufferRecord is encountered.
 Error processFDRNewBufferRecord(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",
         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.
   State.Expects = FDRState::Token::NEW_CPU_ID_RECORD;
   return Error::success();
 }
 
+/// State transition when a CallArgumentRecord is encountered.
+Error processFDRCallArgumentRecord(FDRState &State, uint8_t RecordFirstByte,
+                                   DataExtractor &RecordExtractor,
+                                   std::vector<XRayRecord> &Records) {
+  uint32_t OffsetPtr = 1; // Read starting after the first byte.
+  uint16_t ArgNum = RecordExtractor.getU16(&OffsetPtr);
+  if (ArgNum != 1)
+    return make_error<StringError>(
+        "CallArgument only supports the first argument.",
+        std::make_error_code(std::errc::executable_format_error));
+  auto &Enter = Records.back();
+  if (Enter.Type != RecordTypes::ENTER)
+    return make_error<StringError>(
+        "CallArgument needs to be right after a function entry",
+        std::make_error_code(std::errc::executable_format_error));
+  Enter.Type = RecordTypes::ENTER_ARG;
+  Enter.CallArg = RecordExtractor.getU64(&OffsetPtr);
+  return Error::success();
+}
+
 /// Advances the state machine for reading the FDR record type by reading one
 /// Metadata Record and updating the State appropriately based on the kind of
 /// 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.
 Error processFDRMetadataRecord(FDRState &State, uint8_t RecordFirstByte,
-                               DataExtractor &RecordExtractor) {
+                               DataExtractor &RecordExtractor,
+                               std::vector<XRayRecord> &Records) {
   // The remaining 7 bits are the RecordKind enum.
   uint8_t RecordKind = RecordFirstByte >> 1;
   switch (RecordKind) {
   case 0: // NewBuffer
     if (auto E =
             processFDRNewBufferRecord(State, RecordFirstByte, RecordExtractor))
       return E;
     break;
if (auto E =
             processFDRTSCWrapRecord(State, RecordFirstByte, RecordExtractor))
       return E;
     break;
   case 4: // WallTimeMarker
     if (auto E =
             processFDRWallTimeRecord(State, RecordFirstByte, RecordExtractor))
       return E;
     break;
+  case 5: // CallArgument
+    if (auto E =
+            processFDRCallArgumentRecord(State, RecordFirstByte,
+                                         RecordExtractor, Records))
+      return E;
+    break;
   default:
     // Widen the record type to uint16_t to prevent conversion to char.
     return make_error<StringError>(
         Twine("Illegal metadata record type: ")
             .concat(Twine(static_cast<unsigned>(RecordKind))),
         std::make_error_code(std::errc::executable_format_error));
   }
   return Error::success();
Error loadFDRLog(StringRef Data, XRayFileHeader &FileHeader,
 
   uint64_t BufferSize = 0;
   {
     StringRef ExtraDataRef(FileHeader.FreeFormData, 16);
     DataExtractor ExtraDataExtractor(ExtraDataRef, true, 8);
     uint32_t ExtraDataOffset = 0;
     BufferSize = ExtraDataExtractor.getU64(&ExtraDataOffset);
   }
-  FDRState State{0,          0, 0, FDRState::Token::NEW_BUFFER_RECORD_OR_EOF,
+  FDRState State{0, 0, 0, FDRState::Token::NEW_BUFFER_RECORD_OR_EOF,
                  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;
   for (auto S = Data.drop_front(32); !S.empty(); S = S.drop_front(RecordSize)) {
     DataExtractor RecordExtractor(S, true, 8);
     uint32_t OffsetPtr = 0;
     if (State.Expects == FDRState::Token::SCAN_TO_END_OF_THREAD_BUF) {
       RecordSize = State.CurrentBufferSize - State.CurrentBufferConsumed;
       if (S.size() < State.CurrentBufferSize - State.CurrentBufferConsumed) {
         return make_error<StringError>(
             Twine("Incomplete thread buffer. Expected ") +
                 Twine(State.CurrentBufferSize - State.CurrentBufferConsumed) +
                 " remaining bytes but found " + Twine(S.size()),
             make_error_code(std::errc::invalid_argument));
       }
       State.CurrentBufferConsumed = 0;
       State.Expects = FDRState::Token::NEW_BUFFER_RECORD_OR_EOF;
       continue;
     }
     uint8_t BitField = RecordExtractor.getU8(&OffsetPtr);
     bool isMetadataRecord = BitField & 0x01uL;
     if (isMetadataRecord) {
       RecordSize = 16;
-      if (auto E = processFDRMetadataRecord(State, BitField, RecordExtractor))
+      if (auto E = processFDRMetadataRecord(State, BitField, RecordExtractor,
+                                            Records))
         return E;
       State.CurrentBufferConsumed += RecordSize;
     } else { // Process Function Record
       RecordSize = 8;
       if (auto E = processFDRFunctionRecord(State, BitField, RecordExtractor,
                                             Records))
         return E;
       State.CurrentBufferConsumed += RecordSize;

tools/llvm-xray/xray-account.cc

bool LatencyAccountant::accountRecord(const XRayRecord &Record) {
   if (CurrentMaxTSC == 0)
     CurrentMaxTSC = Record.TSC;
 
   if (Record.TSC < CurrentMaxTSC)
     return false;
 
   auto &ThreadStack = PerThreadFunctionStack[Record.TId];
   switch (Record.Type) {
-  case RecordTypes::ENTER: {
+  case RecordTypes::ENTER:
+  case RecordTypes::ENTER_ARG: {
     // Function Enter
     ThreadStack.emplace_back(Record.FuncId, Record.TSC);
     break;
   }
   case RecordTypes::EXIT: {
     // Function Exit
     if (ThreadStack.back().first == Record.FuncId) {
       const auto &Top = ThreadStack.back();

tools/llvm-xray/xray-converter.cc

void TraceConverter::exportAsYAML(const Trace &Records, raw_ostream &OS) {
   const auto &FH = Records.getFileHeader();
   Trace.Header = {FH.Version, FH.Type, FH.ConstantTSC, FH.NonstopTSC,
                   FH.CycleFrequency};
   Trace.Records.reserve(Records.size());
   for (const auto &R : Records) {
     Trace.Records.push_back({R.RecordType, R.CPU, R.Type, R.FuncId,
                              Symbolize ? FuncIdHelper.SymbolOrNumber(R.FuncId)
                                        : llvm::to_string(R.FuncId),
-                             R.TSC, R.TId});
+                             R.TSC, R.TId, R.CallArg});
   }
   Output Out(OS, nullptr, 0);
   Out << Trace;
 }
 
 void TraceConverter::exportAsRAWv1(const Trace &Records, raw_ostream &OS) {
   // First write out the file header, in the correct endian-appropriate format
   // (XRay assumes currently little endian).
void TraceConverter::exportAsRAWv1(const Trace &Records, raw_ostream &OS) {
   // format.
   for (const auto &R : Records) {
     Writer.write(R.RecordType);
     // The on disk naive raw format uses 8 bit CPUs, but the record has 16.
     // There's no choice but truncation.
     Writer.write(static_cast<uint8_t>(R.CPU));
     switch (R.Type) {
     case RecordTypes::ENTER:
+    case RecordTypes::ENTER_ARG:
       Writer.write(uint8_t{0});
       break;
     case RecordTypes::EXIT:
       Writer.write(uint8_t{1});
       break;
     }
     Writer.write(R.FuncId);
     Writer.write(R.TSC);

tools/llvm-xray/xray-graph.cc

if (CurrentMaxTSC == 0)
     CurrentMaxTSC = Record.TSC;
 
   if (Record.TSC < CurrentMaxTSC)
     return make_error<StringError>("Records not in order",
                                    make_error_code(errc::invalid_argument));
 
   auto &ThreadStack = PerThreadFunctionStack[Record.TId];
   switch (Record.Type) {
-  case RecordTypes::ENTER: {
+  case RecordTypes::ENTER:
+  case RecordTypes::ENTER_ARG: {
     if (Record.FuncId != 0 && G.count(Record.FuncId) == 0)
       G[Record.FuncId].SymbolName = FuncIdHelper.SymbolOrNumber(Record.FuncId);
     ThreadStack.push_back({Record.FuncId, Record.TSC});
     break;
   }
   case RecordTypes::EXIT: {
     // FIXME: Refactor this and the account subcommand to reduce code
     // duplication