From 4f83c4d1a6952e395e9be8da1e8886e62ce959b6 Mon Sep 17 00:00:00 2001 From: Dean Michael Berris Date: Fri, 17 Feb 2017 01:47:16 +0000 Subject: [PATCH] [XRAY] [x86_64] Adding a Flight Data filetype reader to the llvm-xray Trace implementation. Summary: The file type packs function trace data onto disk from potentially multiple threads that are aggregated and flushed during the course of an instrumented program's runtime. It is named FDR mode or Flight Data recorder as an analogy to plane blackboxes, which instrument a running system without access to IO. The writer code is defined in compiler-rt in xray_fdr_logging.h/cc Reviewers: rSerge, kcc, dberris Reviewed By: dberris Subscribers: llvm-commits Differential Revision: https://reviews.llvm.org/D29697 llvm-svn: 295397 --- llvm/include/llvm/XRay/XRayRecord.h | 4 +- llvm/include/llvm/XRay/YAMLXRayRecord.h | 2 +- llvm/lib/XRay/Trace.cpp | 323 ++++++++++++++++-- .../X86/Inputs/fdr-log-version-1.xray | Bin 0 -> 232 bytes .../llvm-xray/X86/convert-fdr-to-yaml.txt | 24 ++ llvm/tools/llvm-xray/xray-converter.cc | 4 +- 6 files changed, 334 insertions(+), 23 deletions(-) create mode 100644 llvm/test/tools/llvm-xray/X86/Inputs/fdr-log-version-1.xray create mode 100644 llvm/test/tools/llvm-xray/X86/convert-fdr-to-yaml.txt diff --git a/llvm/include/llvm/XRay/XRayRecord.h b/llvm/include/llvm/XRay/XRayRecord.h index a96846136ec3..f7314e1bebde 100644 --- a/llvm/include/llvm/XRay/XRayRecord.h +++ b/llvm/include/llvm/XRay/XRayRecord.h @@ -54,8 +54,8 @@ struct XRayRecord { /// The type of record. uint16_t RecordType; - /// The CPU where the thread is running. We assume number of CPUs <= 256. - uint8_t CPU; + /// The CPU where the thread is running. We assume number of CPUs <= 65536. + uint16_t CPU; /// Identifies the type of record. RecordTypes Type; diff --git a/llvm/include/llvm/XRay/YAMLXRayRecord.h b/llvm/include/llvm/XRay/YAMLXRayRecord.h index f5836b392242..7e1a4112818e 100644 --- a/llvm/include/llvm/XRay/YAMLXRayRecord.h +++ b/llvm/include/llvm/XRay/YAMLXRayRecord.h @@ -31,7 +31,7 @@ struct YAMLXRayFileHeader { struct YAMLXRayRecord { uint16_t RecordType; - uint8_t CPU; + uint16_t CPU; RecordTypes Type; int32_t FuncId; std::string Function; diff --git a/llvm/lib/XRay/Trace.cpp b/llvm/lib/XRay/Trace.cpp index 6d5e45276832..47539e9ed7e3 100644 --- a/llvm/lib/XRay/Trace.cpp +++ b/llvm/lib/XRay/Trace.cpp @@ -24,8 +24,8 @@ using llvm::yaml::Input; using XRayRecordStorage = std::aligned_storage::type; -static Error NaiveLogLoader(StringRef Data, XRayFileHeader &FileHeader, - std::vector &Records) { +// Populates the FileHeader reference by reading the first 32 bytes of the file. +Error readBinaryFormatHeader(StringRef Data, XRayFileHeader &FileHeader) { // FIXME: Maybe deduce whether the data is little or big-endian using some // magic bytes in the beginning of the file? @@ -37,16 +37,6 @@ static Error NaiveLogLoader(StringRef Data, XRayFileHeader &FileHeader, // (4) uint32 : bitfield // (8) uint64 : cycle frequency // (16) - : padding - // - if (Data.size() < 32) - return make_error( - "Not enough bytes for an XRay log.", - std::make_error_code(std::errc::invalid_argument)); - - if (Data.size() - 32 == 0 || Data.size() % 32 != 0) - return make_error( - "Invalid-sized XRay data.", - std::make_error_code(std::errc::invalid_argument)); DataExtractor HeaderExtractor(Data, true, 8); uint32_t OffsetPtr = 0; @@ -61,6 +51,24 @@ static Error NaiveLogLoader(StringRef Data, XRayFileHeader &FileHeader, return make_error( Twine("Unsupported XRay file version: ") + Twine(FileHeader.Version), std::make_error_code(std::errc::invalid_argument)); + return Error::success(); +} + +Error loadNaiveFormatLog(StringRef Data, XRayFileHeader &FileHeader, + std::vector &Records) { + // Check that there is at least a header + if (Data.size() < 32) + return make_error( + "Not enough bytes for an XRay log.", + std::make_error_code(std::errc::invalid_argument)); + + if (Data.size() - 32 == 0 || Data.size() % 32 != 0) + return make_error( + "Invalid-sized XRay data.", + std::make_error_code(std::errc::invalid_argument)); + + if (auto E = readBinaryFormatHeader(Data, FileHeader)) + return E; // Each record after the header will be 32 bytes, in the following format: // @@ -98,9 +106,279 @@ static Error NaiveLogLoader(StringRef Data, XRayFileHeader &FileHeader, return Error::success(); } -static Error YAMLLogLoader(StringRef Data, XRayFileHeader &FileHeader, - std::vector &Records) { +/// When reading from a Flight Data Recorder mode log, metadata records are +/// sparse compared to packed function records, so we must maintain state as we +/// read through the sequence of entries. This allows the reader to denormalize +/// the CPUId and Thread Id onto each Function Record and transform delta +/// encoded TSC values into absolute encodings on each record. +struct FDRState { + uint16_t CPUId; + uint16_t ThreadId; + uint64_t BaseTSC; + /// 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 + }; + Token Expects; +}; +/// State transition when a NewBufferRecord is encountered. +Error processFDRNewBufferRecord(FDRState &State, uint8_t RecordFirstByte, + DataExtractor &RecordExtractor) { + + if (State.Expects != FDRState::Token::NEW_BUFFER_RECORD_OR_EOF) { + return make_error( + "Malformed log. Read New Buffer record kind out of sequence", + std::make_error_code(std::errc::executable_format_error)); + } + uint32_t OffsetPtr = 1; // 1 byte into record. + State.ThreadId = RecordExtractor.getU16(&OffsetPtr); + State.Expects = FDRState::Token::WALLCLOCK_RECORD; + return Error::success(); +} + +/// State transition when an EndOfBufferRecord is encountered. +Error processFDREndOfBufferRecord(FDRState &State, uint8_t RecordFirstByte, + DataExtractor &RecordExtractor) { + if (State.Expects == FDRState::Token::NEW_BUFFER_RECORD_OR_EOF) { + return make_error( + "Malformed log. Received EOB message without current buffer.", + std::make_error_code(std::errc::executable_format_error)); + } + State.Expects = FDRState::Token::NEW_BUFFER_RECORD_OR_EOF; + return Error::success(); +} + +/// State transition when a NewCPUIdRecord is encountered. +Error processFDRNewCPUIdRecord(FDRState &State, uint8_t RecordFirstByte, + DataExtractor &RecordExtractor) { + if (State.Expects != FDRState::Token::FUNCTION_SEQUENCE && + State.Expects != FDRState::Token::NEW_CPU_ID_RECORD) { + return make_error( + "Malformed log. Read NewCPUId record kind out of sequence", + std::make_error_code(std::errc::executable_format_error)); + } + uint32_t OffsetPtr = 1; // Read starting after the first byte. + State.CPUId = RecordExtractor.getU16(&OffsetPtr); + State.BaseTSC = RecordExtractor.getU64(&OffsetPtr); + State.Expects = FDRState::Token::FUNCTION_SEQUENCE; + return Error::success(); +} + +/// State transition when a TSCWrapRecord (overflow detection) is encountered. +Error processFDRTSCWrapRecord(FDRState &State, uint8_t RecordFirstByte, + DataExtractor &RecordExtractor) { + if (State.Expects != FDRState::Token::FUNCTION_SEQUENCE) { + return make_error( + "Malformed log. Read TSCWrap record kind out of sequence", + std::make_error_code(std::errc::executable_format_error)); + } + uint32_t OffsetPtr = 1; // Read starting after the first byte. + State.BaseTSC = RecordExtractor.getU64(&OffsetPtr); + return Error::success(); +} + +/// State transition when a WallTimeMarkerRecord is encountered. +Error processFDRWallTimeRecord(FDRState &State, uint8_t RecordFirstByte, + DataExtractor &RecordExtractor) { + if (State.Expects != FDRState::Token::WALLCLOCK_RECORD) { + return make_error( + "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(); +} + +/// Advances the state machine for reading the FDR record type by reading one +/// Metadata Record and updating the State approriately 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) { + // 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; + case 1: // EndOfBuffer + if (auto E = processFDREndOfBufferRecord(State, RecordFirstByte, + RecordExtractor)) + return E; + break; + case 2: // NewCPUId + if (auto E = + processFDRNewCPUIdRecord(State, RecordFirstByte, RecordExtractor)) + return E; + break; + case 3: // TSCWrap + if (auto E = + processFDRTSCWrapRecord(State, RecordFirstByte, RecordExtractor)) + return E; + break; + case 4: // WallTimeMarker + if (auto E = + processFDRWallTimeRecord(State, RecordFirstByte, RecordExtractor)) + return E; + break; + default: + // Widen the record type to uint16_t to prevent conversion to char. + return make_error( + Twine("Illegal metadata record type: ") + .concat(Twine(static_cast(RecordKind))), + std::make_error_code(std::errc::executable_format_error)); + } + return Error::success(); +} + +/// Reads a function record from an FDR format log, appending a new XRayRecord +/// to the vector being populated and updating the State with a new value +/// reference value to interpret TSC deltas. +/// +/// The XRayRecord constructed includes information from the function record +/// processed here as well as Thread ID and CPU ID formerly extracted into +/// State. +Error processFDRFunctionRecord(FDRState &State, uint8_t RecordFirstByte, + DataExtractor &RecordExtractor, + std::vector &Records) { + switch (State.Expects) { + case FDRState::Token::NEW_BUFFER_RECORD_OR_EOF: + return make_error( + "Malformed log. Received Function Record before new buffer setup.", + std::make_error_code(std::errc::executable_format_error)); + case FDRState::Token::WALLCLOCK_RECORD: + return make_error( + "Malformed log. Received Function Record when expecting wallclock.", + std::make_error_code(std::errc::executable_format_error)); + case FDRState::Token::NEW_CPU_ID_RECORD: + return make_error( + "Malformed log. Received Function Record before first CPU record.", + std::make_error_code(std::errc::executable_format_error)); + default: + Records.emplace_back(); + auto &Record = Records.back(); + Record.RecordType = 0; // Record is type NORMAL. + // Strip off record type bit and use the next three bits. + uint8_t RecordType = (RecordFirstByte >> 1) & 0x07; + switch (RecordType) { + case static_cast(RecordTypes::ENTER): + Record.Type = RecordTypes::ENTER; + break; + case static_cast(RecordTypes::EXIT): + case 2: // TAIL_EXIT is not yet defined in RecordTypes. + Record.Type = RecordTypes::EXIT; + break; + default: + // When initializing the error, convert to uint16_t so that the record + // type isn't interpreted as a char. + return make_error( + Twine("Illegal function record type: ") + .concat(Twine(static_cast(RecordType))), + std::make_error_code(std::errc::executable_format_error)); + } + Record.CPU = State.CPUId; + Record.TId = State.ThreadId; + // Back up to read first 32 bits, including the 8 we pulled RecordType + // and RecordKind out of. The remaining 28 are FunctionId. + uint32_t OffsetPtr = 0; + // Despite function Id being a signed int on XRayRecord, + // when it is written to an FDR format, the top bits are truncated, + // so it is effectively an unsigned value. When we shift off the + // top four bits, we want the shift to be logical, so we read as + // uint32_t. + uint32_t FuncIdBitField = RecordExtractor.getU32(&OffsetPtr); + Record.FuncId = FuncIdBitField >> 4; + // FunctionRecords have a 32 bit delta from the previous absolute TSC + // or TSC delta. If this would overflow, we should read a TSCWrap record + // with an absolute TSC reading. + uint64_t new_tsc = State.BaseTSC + RecordExtractor.getU32(&OffsetPtr); + State.BaseTSC = new_tsc; + Record.TSC = new_tsc; + } + return Error::success(); +} + +/// Reads a log in FDR mode for version 1 of this binary format. FDR mode is +/// defined as part of the compiler-rt project in xray_fdr_logging.h, and such +/// a log consists of the familiar 32 bit XRayHeader, followed by sequences of +/// of interspersed 16 byte Metadata Records and 8 byte Function Records. +/// +/// The following is an attempt to document the grammar of the format, which is +/// parsed by this function for little-endian machines. Since the format makes +/// use of BitFields, when we support big-Endian architectures, we will need to +/// adjust not only the endianess parameter to llvm's RecordExtractor, but also +/// the bit twiddling logic, which is consistent with the little-endian +/// 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. +/// +/// FDRLog: XRayFileHeader ThreadBuffer* +/// XRayFileHeader: 32 bits to identify the log as FDR with machine metadata. +/// ThreadBuffer: NewBuffer WallClockTime NewCPUId FunctionSequence EOB +/// NewBuffer: 16 byte metadata record with Thread Id. +/// WallClockTime: 16 byte metadata record with human readable time. +/// NewCPUId: 16 byte metadata record with CPUId and a 64 bit TSC reading. +/// EOB: 16 byte metadata record marking the end of a thread's sequence. +/// 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. +Error loadFDRLog(StringRef Data, XRayFileHeader &FileHeader, + std::vector &Records) { + if (Data.size() < 32) + return make_error( + "Not enough bytes for an XRay log.", + std::make_error_code(std::errc::invalid_argument)); + + // For an FDR log, there are records sized 16 and 8 bytes. + if (Data.size() - 32 == 0 || Data.size() % 8 != 0) + return make_error( + "Invalid-sized XRay data.", + std::make_error_code(std::errc::invalid_argument)); + + if (auto E = readBinaryFormatHeader(Data, FileHeader)) + return E; + + FDRState State{0, 0, 0, FDRState::Token::NEW_BUFFER_RECORD_OR_EOF}; + // 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; + uint8_t BitField = RecordExtractor.getU8(&OffsetPtr); + bool isMetadataRecord = BitField & 0x01uL; + if (isMetadataRecord) { + RecordSize = 16; + if (auto E = processFDRMetadataRecord(State, BitField, RecordExtractor)) + return E; + } else { // Process Function Record + RecordSize = 8; + if (auto E = processFDRFunctionRecord(State, BitField, RecordExtractor, + Records)) + return E; + } + } + if (State.Expects != FDRState::Token::NEW_BUFFER_RECORD_OR_EOF) + return make_error( + "Encountered EOF without preceding End of Buffer record.", + std::make_error_code(std::errc::executable_format_error)); + + return Error::success(); +} + +Error loadYAMLLog(StringRef Data, XRayFileHeader &FileHeader, + std::vector &Records) { // Load the documents from the MappedFile. YAMLXRayTrace Trace; Input In(Data); @@ -175,14 +453,21 @@ Expected llvm::xray::loadTraceFile(StringRef Filename, bool Sort) { uint16_t Version = HeaderExtractor.getU16(&OffsetPtr); uint16_t Type = HeaderExtractor.getU16(&OffsetPtr); + enum BinaryFormatType { NAIVE_FORMAT = 0, FLIGHT_DATA_RECORDER_FORMAT = 1 }; + Trace T; - if (Version == 1 && (Type == 0 || Type == 1)) { - if (auto E = NaiveLogLoader(StringRef(MappedFile.data(), MappedFile.size()), - T.FileHeader, T.Records)) + if (Version == 1 && Type == NAIVE_FORMAT) { + if (auto E = + loadNaiveFormatLog(StringRef(MappedFile.data(), MappedFile.size()), + T.FileHeader, T.Records)) + return std::move(E); + } else if (Version == 1 && Type == FLIGHT_DATA_RECORDER_FORMAT) { + if (auto E = loadFDRLog(StringRef(MappedFile.data(), MappedFile.size()), + T.FileHeader, T.Records)) return std::move(E); } else { - if (auto E = YAMLLogLoader(StringRef(MappedFile.data(), MappedFile.size()), - T.FileHeader, T.Records)) + if (auto E = loadYAMLLog(StringRef(MappedFile.data(), MappedFile.size()), + T.FileHeader, T.Records)) return std::move(E); } diff --git a/llvm/test/tools/llvm-xray/X86/Inputs/fdr-log-version-1.xray b/llvm/test/tools/llvm-xray/X86/Inputs/fdr-log-version-1.xray new file mode 100644 index 0000000000000000000000000000000000000000..8581776e888cbf766802ba7a9390884a91ea43ec GIT binary patch literal 232 zcmZQ%U}RusU|`S_0}?(R.CPU)); switch (R.Type) { case RecordTypes::ENTER: Writer.write(uint8_t{0});