Index: compiler-rt/lib/xray/xray_fdr_log_records.h =================================================================== --- compiler-rt/lib/xray/xray_fdr_log_records.h +++ compiler-rt/lib/xray/xray_fdr_log_records.h @@ -33,6 +33,7 @@ CallArgument, BufferExtents, TypedEventMarker, + Pid, }; // Use 7 bits to identify this record type. Index: compiler-rt/lib/xray/xray_fdr_logging.cc =================================================================== --- compiler-rt/lib/xray/xray_fdr_logging.cc +++ compiler-rt/lib/xray/xray_fdr_logging.cc @@ -126,8 +126,9 @@ } static void writeNewBufferPreamble(tid_t Tid, - timespec TS) XRAY_NEVER_INSTRUMENT { - static constexpr int InitRecordsCount = 2; + timespec TS, + pid_t Pid) XRAY_NEVER_INSTRUMENT { + static constexpr int InitRecordsCount = 3; auto &TLD = getThreadLocalData(); MetadataRecord Metadata[InitRecordsCount]; { @@ -161,6 +162,16 @@ sizeof(Micros)); } + // Also write the Pid record. + { + // Write out a MetadataRecord that contains the current pid + auto &PidMetadata = Metadata[2]; + PidMetadata.Type = uint8_t(RecordType::Metadata); + PidMetadata.RecordKind = uint8_t(MetadataRecord::RecordKinds::Pid); + int32_t pid = static_cast(Pid); + internal_memcpy(&PidMetadata.Data, &pid, sizeof(pid)); + } + TLD.NumConsecutiveFnEnters = 0; TLD.NumTailCalls = 0; if (TLD.BQ == nullptr || TLD.BQ->finalizing()) @@ -180,9 +191,10 @@ TLD.RecordPtr = static_cast(B.Data); tid_t Tid = GetTid(); timespec TS{0, 0}; + pid_t Pid = internal_getpid(); // This is typically clock_gettime, but callers have injection ability. wall_clock_reader(CLOCK_MONOTONIC, &TS); - writeNewBufferPreamble(Tid, TS); + writeNewBufferPreamble(Tid, TS, Pid); TLD.NumConsecutiveFnEnters = 0; TLD.NumTailCalls = 0; } Index: compiler-rt/test/xray/TestCases/Posix/fdr-mode.cc =================================================================== --- compiler-rt/test/xray/TestCases/Posix/fdr-mode.cc +++ compiler-rt/test/xray/TestCases/Posix/fdr-mode.cc @@ -81,32 +81,32 @@ } // Check that we're able to see two threads, each entering and exiting fA(). -// TRACE-DAG: - { type: 0, func-id: [[FIDA:[0-9]+]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} } -// TRACE: - { type: 0, func-id: [[FIDA]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD1]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} } -// TRACE-DAG: - { type: 0, func-id: [[FIDA]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} } -// TRACE: - { type: 0, func-id: [[FIDA]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD2]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} } +// TRACE-DAG: - { type: 0, func-id: [[FIDA:[0-9]+]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], process: [[PROCESS:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} } +// TRACE: - { type: 0, func-id: [[FIDA]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD1]], process: [[PROCESS]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} } +// TRACE-DAG: - { type: 0, func-id: [[FIDA]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], process: [[PROCESS]], kind: function-enter, tsc: {{[0-9]+}} } +// TRACE: - { type: 0, func-id: [[FIDA]], function: {{.*fA.*}}, cpu: {{.*}}, thread: [[THREAD2]], process: [[PROCESS]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} } // // Do the same as above for fC() -// TRACE-DAG: - { type: 0, func-id: [[FIDC:[0-9]+]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} } -// TRACE: - { type: 0, func-id: [[FIDC]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD1]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} } -// TRACE-DAG: - { type: 0, func-id: [[FIDC]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} } -// TRACE: - { type: 0, func-id: [[FIDC]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD2]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} } +// TRACE-DAG: - { type: 0, func-id: [[FIDC:[0-9]+]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], process: [[PROCESS]], kind: function-enter, tsc: {{[0-9]+}} } +// TRACE: - { type: 0, func-id: [[FIDC]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD1]], process: [[PROCESS]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} } +// TRACE-DAG: - { type: 0, func-id: [[FIDC]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], process: [[PROCESS]], kind: function-enter, tsc: {{[0-9]+}} } +// TRACE: - { type: 0, func-id: [[FIDC]], function: {{.*fC.*}}, cpu: {{.*}}, thread: [[THREAD2]], process: [[PROCESS]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} } // Do the same as above for fB() -// TRACE-DAG: - { type: 0, func-id: [[FIDB:[0-9]+]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} } -// TRACE: - { type: 0, func-id: [[FIDB]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD1]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} } -// TRACE-DAG: - { type: 0, func-id: [[FIDB]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} } -// TRACE: - { type: 0, func-id: [[FIDB]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD2]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} } +// TRACE-DAG: - { type: 0, func-id: [[FIDB:[0-9]+]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], process: [[PROCESS]], kind: function-enter, tsc: {{[0-9]+}} } +// TRACE: - { type: 0, func-id: [[FIDB]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD1]], process: [[PROCESS]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} } +// TRACE-DAG: - { type: 0, func-id: [[FIDB]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], process: [[PROCESS]], kind: function-enter, tsc: {{[0-9]+}} } +// TRACE: - { type: 0, func-id: [[FIDB]], function: {{.*fB.*}}, cpu: {{.*}}, thread: [[THREAD2]], process: [[PROCESS]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} } -// TRACE-DAG: - { type: 0, func-id: [[FIDARG:[0-9]+]], function: 'fArg(int)', args: [ 1 ], cpu: {{.*}}, thread: [[THREAD2]], kind: function-enter-arg, tsc: {{[0-9]+}} } -// TRACE-DAG: - { type: 0, func-id: [[FIDARG]], function: 'fArg(int)', cpu: {{.*}}, thread: [[THREAD2]], kind: function-exit, tsc: {{[0-9]+}} } +// TRACE-DAG: - { type: 0, func-id: [[FIDARG:[0-9]+]], function: 'fArg(int)', args: [ 1 ], cpu: {{.*}}, thread: [[THREAD2]], process: [[PROCESS]], kind: function-enter-arg, tsc: {{[0-9]+}} } +// TRACE-DAG: - { type: 0, func-id: [[FIDARG]], function: 'fArg(int)', cpu: {{.*}}, thread: [[THREAD2]], process: [[PROCESS]], kind: function-exit, tsc: {{[0-9]+}} } // Assert that when unwriting is enabled with a high threshold time, all the function records are erased. A CPU switch could erroneously fail this test, but // is unlikely given the test program. // Even with a high threshold, arg1 logging is never unwritten. // UNWRITE: header: // UNWRITE: records: -// UNWRITE-NEXT: - { type: 0, func-id: [[FIDARG:[0-9]+]], function: 'fArg(int)', args: [ 1 ], cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], kind: function-enter-arg, tsc: {{[0-9]+}} } -// UNWRITE-NEXT: - { type: 0, func-id: [[FIDARG]], function: 'fArg(int)', cpu: {{.*}}, thread: [[THREAD2]], kind: function-exit, tsc: {{[0-9]+}} } +// UNWRITE-NEXT: - { type: 0, func-id: [[FIDARG:[0-9]+]], function: 'fArg(int)', args: [ 1 ], cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], process: [[PROCESS:[0-9]+]], kind: function-enter-arg, tsc: {{[0-9]+}} } +// UNWRITE-NEXT: - { type: 0, func-id: [[FIDARG]], function: 'fArg(int)', cpu: {{.*}}, thread: [[THREAD2]], process: [[PROCESS]], kind: function-exit, tsc: {{[0-9]+}} } // UNWRITE-NOT: function-enter // UNWRITE-NOT: function-{{exit|tail-exit}} Index: compiler-rt/test/xray/TestCases/Posix/fdr-single-thread.cc =================================================================== --- compiler-rt/test/xray/TestCases/Posix/fdr-single-thread.cc +++ compiler-rt/test/xray/TestCases/Posix/fdr-single-thread.cc @@ -34,5 +34,5 @@ } // CHECK: records: -// CHECK-NEXT: - { type: 0, func-id: [[FID1:[0-9]+]], function: {{.*fn.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} } -// CHECK-NEXT: - { type: 0, func-id: [[FID1:[0-9]+]], function: {{.*fn.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], kind: function-exit, tsc: {{[0-9]+}} } +// CHECK-NEXT: - { type: 0, func-id: [[FID1:[0-9]+]], function: {{.*fn.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], process: [[PROCESS:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} } +// CHECK-NEXT: - { type: 0, func-id: [[FID1:[0-9]+]], function: {{.*fn.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], process: [[PROCESS:[0-9]+]], kind: function-exit, tsc: {{[0-9]+}} } Index: compiler-rt/test/xray/TestCases/Posix/fdr-thread-order.cc =================================================================== --- compiler-rt/test/xray/TestCases/Posix/fdr-thread-order.cc +++ compiler-rt/test/xray/TestCases/Posix/fdr-thread-order.cc @@ -61,7 +61,7 @@ } // We want to make sure that the order of the function log doesn't matter. -// TRACE-DAG: - { type: 0, func-id: [[FID1:[0-9]+]], function: {{.*f1.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} } -// TRACE-DAG: - { type: 0, func-id: [[FID2:[0-9]+]], function: {{.*f2.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} } -// TRACE-DAG: - { type: 0, func-id: [[FID1]], function: {{.*f1.*}}, cpu: {{.*}}, thread: [[THREAD1]], kind: {{function-exit|function-tail-exit}}, tsc: {{[0-9]+}} } -// TRACE-DAG: - { type: 0, func-id: [[FID2]], function: {{.*f2.*}}, cpu: {{.*}}, thread: [[THREAD2]], kind: {{function-exit|function-tail-exit}}, tsc: {{[0-9]+}} } +// TRACE-DAG: - { type: 0, func-id: [[FID1:[0-9]+]], function: {{.*f1.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], process: [[PROCESS:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} } +// TRACE-DAG: - { type: 0, func-id: [[FID2:[0-9]+]], function: {{.*f2.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], process: [[PROCESS]], kind: function-enter, tsc: {{[0-9]+}} } +// TRACE-DAG: - { type: 0, func-id: [[FID1]], function: {{.*f1.*}}, cpu: {{.*}}, thread: [[THREAD1]], process: [[PROCESS]], kind: {{function-exit|function-tail-exit}}, tsc: {{[0-9]+}} } +// TRACE-DAG: - { type: 0, func-id: [[FID2]], function: {{.*f2.*}}, cpu: {{.*}}, thread: [[THREAD2]], process: [[PROCESS]], kind: {{function-exit|function-tail-exit}}, tsc: {{[0-9]+}} } Index: llvm/include/llvm/XRay/XRayRecord.h =================================================================== --- llvm/include/llvm/XRay/XRayRecord.h +++ llvm/include/llvm/XRay/XRayRecord.h @@ -75,6 +75,9 @@ /// 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; }; Index: llvm/include/llvm/XRay/YAMLXRayRecord.h =================================================================== --- llvm/include/llvm/XRay/YAMLXRayRecord.h +++ llvm/include/llvm/XRay/YAMLXRayRecord.h @@ -37,6 +37,7 @@ std::string Function; uint64_t TSC; uint32_t TId; + uint32_t PId; std::vector CallArgs; }; @@ -79,6 +80,7 @@ IO.mapOptional("args", Record.CallArgs); IO.mapRequired("cpu", Record.CPU); IO.mapRequired("thread", Record.TId); + IO.mapRequired("process", Record.PId); IO.mapRequired("kind", Record.Type); IO.mapRequired("tsc", Record.TSC); } Index: llvm/lib/XRay/Trace.cpp =================================================================== --- llvm/lib/XRay/Trace.cpp +++ llvm/lib/XRay/Trace.cpp @@ -148,6 +148,7 @@ 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 +162,7 @@ CUSTOM_EVENT_DATA, CALL_ARGUMENT, BUFFER_EXTENTS, + PID_RECORD, }; Token Expects; @@ -188,6 +190,8 @@ return "CALL_ARGUMENT"; case FDRState::Token::BUFFER_EXTENTS: return "BUFFER_EXTENTS"; + case FDRState::Token::PID_RECORD: + return "PID_RECORD"; } return "UNKNOWN"; } @@ -264,6 +268,23 @@ // TODO: Someday, reconcile the TSC ticks to wall clock time for presentation // purposes. For now, we're ignoring these records. + State.Expects = FDRState::Token::PID_RECORD; + 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(); } @@ -376,6 +397,10 @@ 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 +430,10 @@ 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 +463,7 @@ } 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; @@ -530,7 +560,7 @@ 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. @@ -622,7 +652,7 @@ 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}; + R.TSC, R.TId, R.PId, R.CallArgs}; }); return Error::success(); } Index: llvm/tools/llvm-xray/xray-account.cpp =================================================================== --- llvm/tools/llvm-xray/xray-account.cpp +++ llvm/tools/llvm-xray/xray-account.cpp @@ -476,9 +476,9 @@ errs() << "Error processing record: " << llvm::formatv( - R"({{type: {0}; cpu: {1}; record-type: {2}; function-id: {3}; tsc: {4}; thread-id: {5}}})", - Record.RecordType, Record.CPU, Record.Type, Record.FuncId, - Record.TId) + 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.TSC, + Record.TId, Record.PId) << '\n'; for (const auto &ThreadStack : FCA.getPerThreadFunctionStack()) { errs() << "Thread ID: " << ThreadStack.first << "\n"; Index: llvm/tools/llvm-xray/xray-converter.cpp =================================================================== --- llvm/tools/llvm-xray/xray-converter.cpp +++ llvm/tools/llvm-xray/xray-converter.cpp @@ -91,7 +91,7 @@ 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,6 +141,7 @@ Writer.write(R.FuncId); Writer.write(R.TSC); Writer.write(R.TId); + Writer.write(R.PId); Writer.write(Padding4B); Writer.write(Padding4B); Writer.write(Padding4B); @@ -230,6 +231,7 @@ } void writeTraceViewerRecord(raw_ostream &OS, int32_t FuncId, uint32_t TId, + uint32_t PId, bool Symbolize, const FuncIdConversionHelper &FuncIdHelper, double EventTimestampUs, @@ -237,11 +239,11 @@ StringRef FunctionPhenotype) { OS << " "; OS << llvm::formatv( - R"({ "name" : "{0}", "ph" : "{1}", "tid" : "{2}", "pid" : "1", )" - R"("ts" : "{3:f3}", "sf" : "{4}" })", + 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, EventTimestampUs, StackCursor.ExtraData.id); + FunctionPhenotype, TId, PId, EventTimestampUs, StackCursor.ExtraData.id); } } // namespace @@ -285,7 +287,7 @@ // type of B for begin or E for end, thread id, process id (faked), // 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, + writeTraceViewerRecord(OS, R.FuncId, R.TId, R.PId, Symbolize, FuncIdHelper, EventTimestampUs, *StackCursor, "B"); break; case RecordTypes::EXIT: @@ -297,7 +299,7 @@ // (And/Or in loop termination below) StackTrieNode *PreviousCursor = nullptr; do { - writeTraceViewerRecord(OS, StackCursor->FuncId, R.TId, Symbolize, + writeTraceViewerRecord(OS, StackCursor->FuncId, R.TId, R.PId, Symbolize, FuncIdHelper, EventTimestampUs, *StackCursor, "E"); PreviousCursor = StackCursor;