From aab4e8c7ac164d884cf860296b9dc1b6181de645 Mon Sep 17 00:00:00 2001 From: Dean Michael Berris Date: Fri, 13 Jul 2018 05:38:22 +0000 Subject: [PATCH] [XRay][compiler-rt] Add PID field to llvm-xray tool and add PID metadata record entry in FDR mode Summary: llvm-xray changes: - account-mode - process-id {...} shows after thread-id - convert-mode - process {...} shows after thread - parses FDR and basic mode pid entries - Checks version number for FDR log parsing. Basic logging changes: - Update header version from 2 -> 3 FDR logging changes: - Update header version from 2 -> 3 - in writeBufferPreamble, there is an additional PID Metadata record (after thread id record and tsc record) Test cases changes: - fdr-mode.cc, fdr-single-thread.cc, fdr-thread-order.cc modified to catch process id output in the log. Reviewers: dberris Reviewed By: dberris Subscribers: hiraditya, llvm-commits, #sanitizers Differential Revision: https://reviews.llvm.org/D49153 llvm-svn: 336974 --- include/llvm/XRay/XRayRecord.h | 3 + include/llvm/XRay/YAMLXRayRecord.h | 2 + lib/XRay/Trace.cpp | 71 +++++++++++++++--- .../X86/Inputs/basic-log-arg1-version-3.xray | Bin 0 -> 256 bytes .../X86/Inputs/basic-log-version-3.xray | Bin 0 -> 288 bytes .../X86/Inputs/fdr-log-arg1-version-3.xray | Bin 0 -> 224 bytes .../X86/Inputs/fdr-log-version-3.xray | Bin 0 -> 192 bytes ...onvert-basic-log-arg1-version3-to-yaml.txt | 17 +++++ .../convert-basic-log-version3-to-yaml.txt | 19 +++++ .../convert-fdr-log-arg1-version3-to-yaml.txt | 17 +++++ .../X86/convert-fdr-log-version3-to-yaml.txt | 17 +++++ tools/llvm-xray/xray-account.cpp | 4 +- tools/llvm-xray/xray-converter.cpp | 48 ++++++++---- 13 files changed, 169 insertions(+), 29 deletions(-) create mode 100644 test/tools/llvm-xray/X86/Inputs/basic-log-arg1-version-3.xray create mode 100644 test/tools/llvm-xray/X86/Inputs/basic-log-version-3.xray create mode 100644 test/tools/llvm-xray/X86/Inputs/fdr-log-arg1-version-3.xray create mode 100644 test/tools/llvm-xray/X86/Inputs/fdr-log-version-3.xray create mode 100644 test/tools/llvm-xray/X86/convert-basic-log-arg1-version3-to-yaml.txt create mode 100644 test/tools/llvm-xray/X86/convert-basic-log-version3-to-yaml.txt create mode 100644 test/tools/llvm-xray/X86/convert-fdr-log-arg1-version3-to-yaml.txt create mode 100644 test/tools/llvm-xray/X86/convert-fdr-log-version3-to-yaml.txt diff --git a/include/llvm/XRay/XRayRecord.h b/include/llvm/XRay/XRayRecord.h index 5c5e9f436f4..76873447f17 100644 --- a/include/llvm/XRay/XRayRecord.h +++ b/include/llvm/XRay/XRayRecord.h @@ -75,6 +75,9 @@ struct XRayRecord { /// The thread ID for the currently running thread. uint32_t TId; + /// The process ID for the currently running process. + uint32_t PId; + /// The function call arguments. std::vector CallArgs; }; diff --git a/include/llvm/XRay/YAMLXRayRecord.h b/include/llvm/XRay/YAMLXRayRecord.h index b436aefb1e8..0de9ea0968e 100644 --- a/include/llvm/XRay/YAMLXRayRecord.h +++ b/include/llvm/XRay/YAMLXRayRecord.h @@ -37,6 +37,7 @@ struct YAMLXRayRecord { std::string Function; uint64_t TSC; uint32_t TId; + uint32_t PId; std::vector CallArgs; }; @@ -79,6 +80,7 @@ template <> struct MappingTraits { IO.mapOptional("args", Record.CallArgs); IO.mapRequired("cpu", Record.CPU); IO.mapRequired("thread", Record.TId); + IO.mapOptional("process", Record.PId, 0U); IO.mapRequired("kind", Record.Type); IO.mapRequired("tsc", Record.TSC); } diff --git a/lib/XRay/Trace.cpp b/lib/XRay/Trace.cpp index d8c54ddc2b9..a8764b25483 100644 --- a/lib/XRay/Trace.cpp +++ b/lib/XRay/Trace.cpp @@ -48,7 +48,8 @@ Error readBinaryFormatHeader(StringRef Data, XRayFileHeader &FileHeader) { FileHeader.NonstopTSC = Bitfield & 1uL << 1; FileHeader.CycleFrequency = HeaderExtractor.getU64(&OffsetPtr); std::memcpy(&FileHeader.FreeFormData, Data.bytes_begin() + OffsetPtr, 16); - if (FileHeader.Version != 1 && FileHeader.Version != 2) + if (FileHeader.Version != 1 && FileHeader.Version != 2 && + FileHeader.Version != 3) return make_error( Twine("Unsupported XRay file version: ") + Twine(FileHeader.Version), std::make_error_code(std::errc::invalid_argument)); @@ -78,7 +79,8 @@ Error loadNaiveFormatLog(StringRef Data, XRayFileHeader &FileHeader, // (4) sint32 : function id // (8) uint64 : tsc // (4) uint32 : thread id - // (12) - : padding + // (4) uint32 : process id + // (8) - : padding for (auto S = Data.drop_front(32); !S.empty(); S = S.drop_front(32)) { DataExtractor RecordExtractor(S, true, 8); uint32_t OffsetPtr = 0; @@ -110,6 +112,7 @@ Error loadNaiveFormatLog(StringRef Data, XRayFileHeader &FileHeader, Record.FuncId = RecordExtractor.getSigned(&OffsetPtr, sizeof(int32_t)); Record.TSC = RecordExtractor.getU64(&OffsetPtr); Record.TId = RecordExtractor.getU32(&OffsetPtr); + Record.PId = RecordExtractor.getU32(&OffsetPtr); break; } case 1: { // Arg payload record. @@ -118,15 +121,18 @@ Error loadNaiveFormatLog(StringRef Data, XRayFileHeader &FileHeader, OffsetPtr += 2; int32_t FuncId = RecordExtractor.getSigned(&OffsetPtr, sizeof(int32_t)); auto TId = RecordExtractor.getU32(&OffsetPtr); - if (Record.FuncId != FuncId || Record.TId != TId) + auto PId = RecordExtractor.getU32(&OffsetPtr); + + // Make a check for versions above 3 for the Pid field + if (Record.FuncId != FuncId || Record.TId != TId || + (FileHeader.Version >= 3 ? Record.PId != PId : false)) return make_error( Twine("Corrupted log, found arg payload following non-matching " "function + thread record. Record for function ") + Twine(Record.FuncId) + " != " + Twine(FuncId) + "; offset: " + Twine(S.data() - Data.data()), std::make_error_code(std::errc::executable_format_error)); - // Advance another four bytes to avoid padding. - OffsetPtr += 4; + auto Arg = RecordExtractor.getU64(&OffsetPtr); Record.CallArgs.push_back(Arg); break; @@ -148,6 +154,7 @@ Error loadNaiveFormatLog(StringRef Data, XRayFileHeader &FileHeader, struct FDRState { uint16_t CPUId; uint16_t ThreadId; + int32_t ProcessId; uint64_t BaseTSC; /// Encode some of the state transitions for the FDR log reader as explicit @@ -161,6 +168,7 @@ struct FDRState { CUSTOM_EVENT_DATA, CALL_ARGUMENT, BUFFER_EXTENTS, + PID_RECORD, }; Token Expects; @@ -188,6 +196,8 @@ const char *fdrStateToTwine(const FDRState::Token &state) { return "CALL_ARGUMENT"; case FDRState::Token::BUFFER_EXTENTS: return "BUFFER_EXTENTS"; + case FDRState::Token::PID_RECORD: + return "PID_RECORD"; } return "UNKNOWN"; } @@ -268,6 +278,23 @@ Error processFDRWallTimeRecord(FDRState &State, uint8_t RecordFirstByte, return Error::success(); } +/// State transition when a PidRecord is encountered. +Error processFDRPidRecord(FDRState &State, uint8_t RecordFirstByte, + DataExtractor &RecordExtractor) { + + if (State.Expects != FDRState::Token::PID_RECORD) + return make_error( + Twine("Malformed log. Read Pid 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.ProcessId = RecordExtractor.getU32(&OffsetPtr); + State.Expects = FDRState::Token::NEW_CPU_ID_RECORD; + return Error::success(); +} + /// State transition when a CustomEventMarker is encountered. Error processCustomEventMarker(FDRState &State, uint8_t RecordFirstByte, DataExtractor &RecordExtractor, @@ -325,6 +352,9 @@ Error processFDRCallArgumentRecord(FDRState &State, uint8_t RecordFirstByte, /// 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. +/// +/// In Version 3, FDR log now includes a pid metadata record after +/// WallTimeMarker Error processFDRMetadataRecord(FDRState &State, uint8_t RecordFirstByte, DataExtractor &RecordExtractor, size_t &RecordSize, @@ -361,6 +391,9 @@ Error processFDRMetadataRecord(FDRState &State, uint8_t RecordFirstByte, if (auto E = processFDRWallTimeRecord(State, RecordFirstByte, RecordExtractor)) return E; + // In Version 3 and and above, a PidRecord is expected after WallTimeRecord + if (Version >= 3) + State.Expects = FDRState::Token::PID_RECORD; break; case 5: // CustomEventMarker if (auto E = processCustomEventMarker(State, RecordFirstByte, @@ -376,6 +409,10 @@ Error processFDRMetadataRecord(FDRState &State, uint8_t RecordFirstByte, if (auto E = processBufferExtents(State, RecordFirstByte, RecordExtractor)) return E; break; + case 9: // Pid + if (auto E = processFDRPidRecord(State, RecordFirstByte, RecordExtractor)) + return E; + break; default: // Widen the record type to uint16_t to prevent conversion to char. return make_error( @@ -405,6 +442,10 @@ Error processFDRFunctionRecord(FDRState &State, uint8_t RecordFirstByte, return make_error( "Malformed log. Received Function Record when expecting wallclock.", std::make_error_code(std::errc::executable_format_error)); + case FDRState::Token::PID_RECORD: + return make_error( + "Malformed log. Received Function Record when expecting pid.", + 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.", @@ -434,6 +475,7 @@ Error processFDRFunctionRecord(FDRState &State, uint8_t RecordFirstByte, } Record.CPU = State.CPUId; Record.TId = State.ThreadId; + Record.PId = State.ProcessId; // Back up to read first 32 bits, including the 4 we pulled RecordType // and RecordKind out of. The remaining 28 are FunctionId. uint32_t OffsetPtr = 0; @@ -477,6 +519,7 @@ Error processFDRFunctionRecord(FDRState &State, uint8_t RecordFirstByte, /// BufSize: 8 byte unsigned integer indicating how large the buffer is. /// NewBuffer: 16 byte metadata record with Thread Id. /// WallClockTime: 16 byte metadata record with human readable time. +/// Pid: 16 byte metadata record with Pid /// NewCPUId: 16 byte metadata record with CPUId and a 64 bit TSC reading. /// EOB: 16 byte record in a thread buffer plus mem garbage to fill BufSize. /// FunctionSequence: NewCPUId | TSCWrap | FunctionRecord @@ -490,6 +533,11 @@ Error processFDRFunctionRecord(FDRState &State, uint8_t RecordFirstByte, /// 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). +/// +/// In Version 3, we make the following changes: +/// +/// ThreadBuffer: BufferExtents NewBuffer WallClockTime Pid NewCPUId +/// FunctionSequence /// EOB: *deprecated* Error loadFDRLog(StringRef Data, XRayFileHeader &FileHeader, std::vector &Records) { @@ -523,6 +571,7 @@ Error loadFDRLog(StringRef Data, XRayFileHeader &FileHeader, InitialExpectation = FDRState::Token::NEW_BUFFER_RECORD_OR_EOF; break; case 2: + case 3: InitialExpectation = FDRState::Token::BUFFER_EXTENTS; break; default: @@ -530,7 +579,7 @@ Error loadFDRLog(StringRef Data, XRayFileHeader &FileHeader, Twine("Unsupported version '") + Twine(FileHeader.Version) + "'", std::make_error_code(std::errc::executable_format_error)); } - FDRState State{0, 0, 0, InitialExpectation, BufferSize, 0}; + FDRState State{0, 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. @@ -572,7 +621,7 @@ Error loadFDRLog(StringRef Data, XRayFileHeader &FileHeader, if (!isBufferExtents) State.CurrentBufferConsumed += RecordSize; assert(State.CurrentBufferConsumed <= State.CurrentBufferSize); - if (FileHeader.Version == 2 && + if ((FileHeader.Version == 2 || FileHeader.Version == 3) && 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. @@ -621,8 +670,8 @@ Error loadYAMLLog(StringRef Data, XRayFileHeader &FileHeader, Records.clear(); std::transform(Trace.Records.begin(), Trace.Records.end(), std::back_inserter(Records), [&](const YAMLXRayRecord &R) { - return XRayRecord{R.RecordType, R.CPU, R.Type, R.FuncId, - R.TSC, R.TId, R.CallArgs}; + return XRayRecord{R.RecordType, R.CPU, R.Type, R.FuncId, + R.TSC, R.TId, R.PId, R.CallArgs}; }); return Error::success(); } @@ -681,7 +730,7 @@ Expected llvm::xray::loadTraceFile(StringRef Filename, bool Sort) { Trace T; switch (Type) { case NAIVE_FORMAT: - if (Version == 1 || Version == 2) { + if (Version == 1 || Version == 2 || Version == 3) { if (auto E = loadNaiveFormatLog(Data, T.FileHeader, T.Records)) return std::move(E); } else { @@ -692,7 +741,7 @@ Expected llvm::xray::loadTraceFile(StringRef Filename, bool Sort) { } break; case FLIGHT_DATA_RECORDER_FORMAT: - if (Version == 1 || Version == 2) { + if (Version == 1 || Version == 2 || Version == 3) { if (auto E = loadFDRLog(Data, T.FileHeader, T.Records)) return std::move(E); } else { diff --git a/test/tools/llvm-xray/X86/Inputs/basic-log-arg1-version-3.xray b/test/tools/llvm-xray/X86/Inputs/basic-log-arg1-version-3.xray new file mode 100644 index 0000000000000000000000000000000000000000..7c537033964eabffc2d34839b6bb6c40db01e0ea GIT binary patch literal 256 zcmZQ(U|{$U#0>7GFF+K70+?hl+~x>j07+&b{_<&Yin}E{gB%wF7{etQ7#KnFf2PFs z#bK9cU;@gU=m}me!Yrid1gkCyuzAjZ1NyE5Qe$S8OTNhj3D_BGqCFi E0D@5$w*UYD literal 0 HcmV?d00001 diff --git a/test/tools/llvm-xray/X86/Inputs/basic-log-version-3.xray b/test/tools/llvm-xray/X86/Inputs/basic-log-version-3.xray new file mode 100644 index 0000000000000000000000000000000000000000..2a603903b3d20f379b3d9c6e51e1d0b7a002b7ae GIT binary patch literal 288 zcmZQ(U|{$U#0>7GFF+K70+?iI+~x>jFt9T)f>_(tC8DC)8P+8;fH71ONU<}5K9KjX#kQe65$_7}MR!6gs2|BndQ0$ln*_U|abE)M_$ CNGMhS literal 0 HcmV?d00001 diff --git a/test/tools/llvm-xray/X86/Inputs/fdr-log-arg1-version-3.xray b/test/tools/llvm-xray/X86/Inputs/fdr-log-arg1-version-3.xray new file mode 100644 index 0000000000000000000000000000000000000000..6aee7aacad3e86cf5996d00e9420f34ede0a6191 GIT binary patch literal 224 zcmZQ(U}Rus00Q^Y7a)qk0ZhUP{ta*@n8E1Ig(ARds>TTxm|O>@gwf<#*%)pp-3 Error { errs() << "Error processing record: " << llvm::formatv( - R"({{type: {0}; cpu: {1}; record-type: {2}; function-id: {3}; tsc: {4}; thread-id: {5}}})", + R"({{type: {0}; cpu: {1}; record-type: {2}; function-id: {3}; tsc: {4}; thread-id: {5}; process-id: {6}}})", Record.RecordType, Record.CPU, Record.Type, Record.FuncId, - Record.TId) + Record.TSC, Record.TId, Record.PId) << '\n'; for (const auto &ThreadStack : FCA.getPerThreadFunctionStack()) { errs() << "Thread ID: " << ThreadStack.first << "\n"; diff --git a/tools/llvm-xray/xray-converter.cpp b/tools/llvm-xray/xray-converter.cpp index 1c10e416942..1563ef1faec 100644 --- a/tools/llvm-xray/xray-converter.cpp +++ b/tools/llvm-xray/xray-converter.cpp @@ -91,7 +91,7 @@ void TraceConverter::exportAsYAML(const Trace &Records, raw_ostream &OS) { 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.CallArgs}); + R.TSC, R.TId, R.PId, R.CallArgs}); } Output Out(OS, nullptr, 0); Out << Trace; @@ -141,7 +141,12 @@ void TraceConverter::exportAsRAWv1(const Trace &Records, raw_ostream &OS) { Writer.write(R.FuncId); Writer.write(R.TSC); Writer.write(R.TId); - Writer.write(Padding4B); + + if (FH.Version >= 3) + Writer.write(R.PId); + else + Writer.write(Padding4B); + Writer.write(Padding4B); Writer.write(Padding4B); } @@ -229,19 +234,29 @@ StackTrieNode *findOrCreateStackNode( return CurrentStack; } -void writeTraceViewerRecord(raw_ostream &OS, int32_t FuncId, uint32_t TId, - bool Symbolize, +void writeTraceViewerRecord(uint16_t Version, raw_ostream &OS, int32_t FuncId, + uint32_t TId, uint32_t PId, bool Symbolize, const FuncIdConversionHelper &FuncIdHelper, double EventTimestampUs, const StackTrieNode &StackCursor, StringRef FunctionPhenotype) { OS << " "; - OS << llvm::formatv( - R"({ "name" : "{0}", "ph" : "{1}", "tid" : "{2}", "pid" : "1", )" - R"("ts" : "{3:f3}", "sf" : "{4}" })", - (Symbolize ? FuncIdHelper.SymbolOrNumber(FuncId) - : llvm::to_string(FuncId)), - FunctionPhenotype, TId, EventTimestampUs, StackCursor.ExtraData.id); + if (Version >= 3) { + OS << llvm::formatv( + R"({ "name" : "{0}", "ph" : "{1}", "tid" : "{2}", "pid" : "{3}", )" + R"("ts" : "{4:f4}", "sf" : "{5}" })", + (Symbolize ? FuncIdHelper.SymbolOrNumber(FuncId) + : llvm::to_string(FuncId)), + FunctionPhenotype, TId, PId, EventTimestampUs, + StackCursor.ExtraData.id); + } else { + OS << llvm::formatv( + R"({ "name" : "{0}", "ph" : "{1}", "tid" : "{2}", "pid" : "1", )" + R"("ts" : "{3:f3}", "sf" : "{4}" })", + (Symbolize ? FuncIdHelper.SymbolOrNumber(FuncId) + : llvm::to_string(FuncId)), + FunctionPhenotype, TId, EventTimestampUs, StackCursor.ExtraData.id); + } } } // namespace @@ -249,6 +264,7 @@ void writeTraceViewerRecord(raw_ostream &OS, int32_t FuncId, uint32_t TId, void TraceConverter::exportAsChromeTraceEventFormat(const Trace &Records, raw_ostream &OS) { const auto &FH = Records.getFileHeader(); + auto Version = FH.Version; auto CycleFreq = FH.CycleFrequency; unsigned id_counter = 0; @@ -282,11 +298,11 @@ void TraceConverter::exportAsChromeTraceEventFormat(const Trace &Records, StackRootsByThreadId, StacksByStackId, &id_counter, NodeStore); // Each record is represented as a json dictionary with function name, - // type of B for begin or E for end, thread id, process id (faked), + // type of B for begin or E for end, thread id, process id, // timestamp in microseconds, and a stack frame id. The ids are logged // in an id dictionary after the events. - writeTraceViewerRecord(OS, R.FuncId, R.TId, Symbolize, FuncIdHelper, - EventTimestampUs, *StackCursor, "B"); + writeTraceViewerRecord(Version, OS, R.FuncId, R.TId, R.PId, Symbolize, + FuncIdHelper, EventTimestampUs, *StackCursor, "B"); break; case RecordTypes::EXIT: case RecordTypes::TAIL_EXIT: @@ -297,9 +313,9 @@ void TraceConverter::exportAsChromeTraceEventFormat(const Trace &Records, // (And/Or in loop termination below) StackTrieNode *PreviousCursor = nullptr; do { - writeTraceViewerRecord(OS, StackCursor->FuncId, R.TId, Symbolize, - FuncIdHelper, EventTimestampUs, *StackCursor, - "E"); + writeTraceViewerRecord(Version, OS, StackCursor->FuncId, R.TId, R.PId, + Symbolize, FuncIdHelper, EventTimestampUs, + *StackCursor, "E"); PreviousCursor = StackCursor; StackCursor = StackCursor->Parent; } while (PreviousCursor->FuncId != R.FuncId && StackCursor != nullptr);