Index: compiler-rt/lib/xray/tests/unit/fdr_logging_test.cc =================================================================== --- compiler-rt/lib/xray/tests/unit/fdr_logging_test.cc +++ compiler-rt/lib/xray/tests/unit/fdr_logging_test.cc @@ -87,7 +87,7 @@ XRayFileHeader H; memcpy(&H, Contents, sizeof(XRayFileHeader)); - ASSERT_EQ(H.Version, 2); + ASSERT_EQ(H.Version, 3); ASSERT_EQ(H.Type, FileTypes::FDR_LOG); // We require one buffer at least to have the "extents" metadata record, @@ -132,7 +132,7 @@ XRayFileHeader H; memcpy(&H, Contents, sizeof(XRayFileHeader)); - ASSERT_EQ(H.Version, 2); + ASSERT_EQ(H.Version, 3); ASSERT_EQ(H.Type, FileTypes::FDR_LOG); MetadataRecord MDR0, MDR1; @@ -183,7 +183,7 @@ XRayFileHeader H; memcpy(&H, Contents, sizeof(XRayFileHeader)); - ASSERT_EQ(H.Version, 2); + ASSERT_EQ(H.Version, 3); ASSERT_EQ(H.Type, FileTypes::FDR_LOG); MetadataRecord MDR0, MDR1; Index: compiler-rt/lib/xray/xray_basic_logging.cc =================================================================== --- compiler-rt/lib/xray/xray_basic_logging.cc +++ compiler-rt/lib/xray/xray_basic_logging.cc @@ -90,7 +90,9 @@ // header will only be written once, at the start, and let the threads // logging do writes which just append. XRayFileHeader Header; - Header.Version = 2; // Version 2 includes tail exit records. + // Version 2 includes tail exit records. + // Version 3 includes pid inside records. + Header.Version = 3; Header.Type = FileTypes::NAIVE_LOG; Header.CycleFrequency = atomic_load(&CycleFrequency, memory_order_acquire); 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; } @@ -663,7 +675,8 @@ XRayFileHeader &H = reinterpret_cast(HStorage); // Version 2 of the log writes the extents of the buffer, instead of // relying on an end-of-buffer record. - H.Version = 2; + // Version 3 includes PID metadata record + H.Version = 3; H.Type = FileTypes::FDR_LOG; // Test for required CPU features and cache the cycle frequency 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: compiler-rt/test/xray/TestCases/Posix/fork_basic_logging.cc =================================================================== --- compiler-rt/test/xray/TestCases/Posix/fork_basic_logging.cc +++ compiler-rt/test/xray/TestCases/Posix/fork_basic_logging.cc @@ -81,20 +81,20 @@ } // Make sure we know which thread is the parent process -// TRACE-DAG: - { type: 0, func-id: [[LSGT:[0-9]+]], function: {{.*log_syscall_gettid.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} } +// TRACE-DAG: - { type: 0, func-id: [[LSGT:[0-9]+]], function: {{.*log_syscall_gettid.*}}, cpu: {{.*}}, thread: [[THREAD1:[0-9]+]], process: [[PROCESS1:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} } -// TRACE-DAG: - { type: 0, func-id: [[PPOC:[0-9]+]], function: {{.*print_parent_or_child.*}}, cpu: {{.*}}, thread: [[THREAD1]], kind: function-enter, tsc: {{[0-9]+}} } +// TRACE-DAG: - { type: 0, func-id: [[PPOC:[0-9]+]], function: {{.*print_parent_or_child.*}}, cpu: {{.*}}, thread: [[THREAD1]], process: [[PROCESS1]], kind: function-enter, tsc: {{[0-9]+}} } // // The parent will print its pid first -// TRACE-DAG: - { type: 0, func-id: [[PPTARG:[0-9]+]], function: {{.*print_parent_tid.*}}, args: [ [[THREAD1]] ], cpu: {{.*}}, thread: [[THREAD1]], kind: function-enter-arg, tsc: {{[0-9]+}} } -// TRACE-DAG: - { type: 0, func-id: [[PPTARG]], function: {{.*print_parent_tid.*}}, cpu: {{.*}}, thread: [[THREAD1]], kind: function-exit, tsc: {{[0-9]+}} } +// TRACE-DAG: - { type: 0, func-id: [[PPTARG:[0-9]+]], function: {{.*print_parent_tid.*}}, args: [ [[THREAD1]] ], cpu: {{.*}}, thread: [[THREAD1]], process: [[PROCESS1]], kind: function-enter-arg, tsc: {{[0-9]+}} } +// TRACE-DAG: - { type: 0, func-id: [[PPTARG]], function: {{.*print_parent_tid.*}}, cpu: {{.*}}, thread: [[THREAD1]], process: [[PROCESS1]], kind: function-exit, tsc: {{[0-9]+}} } // -// TRACE: - { type: 0, func-id: [[PPOC]], function: {{.*print_parent_or_child.*}}, cpu: {{.*}}, thread: [[THREAD1]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} } +// TRACE: - { type: 0, func-id: [[PPOC]], function: {{.*print_parent_or_child.*}}, cpu: {{.*}}, thread: [[THREAD1]], process: [[PROCESS1]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} } -// TRACE-DAG: - { type: 0, func-id: [[PPOC]], function: {{.*print_parent_or_child.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} } +// TRACE-DAG: - { type: 0, func-id: [[PPOC]], function: {{.*print_parent_or_child.*}}, cpu: {{.*}}, thread: [[THREAD2:[0-9]+]], process: [[PROCESS2:[0-9]+]], kind: function-enter, tsc: {{[0-9]+}} } // // The child will print its pid now -// TRACE-DAG: - { type: 0, func-id: [[PCTARG:[0-9]+]], function: {{.*print_child_tid.*}}, args: [ [[THREAD2]] ], cpu: {{.*}}, thread: [[THREAD2]], kind: function-enter-arg, tsc: {{[0-9]+}} } -// TRACE-DAG: - { type: 0, func-id: [[PCTARG]], function: {{.*print_child_tid.*}}, cpu: {{.*}}, thread: [[THREAD2]], kind: function-exit, tsc: {{[0-9]+}} } +// TRACE-DAG: - { type: 0, func-id: [[PCTARG:[0-9]+]], function: {{.*print_child_tid.*}}, args: [ [[THREAD2]] ], cpu: {{.*}}, thread: [[THREAD2]], process: [[PROCESS2]], kind: function-enter-arg, tsc: {{[0-9]+}} } +// TRACE-DAG: - { type: 0, func-id: [[PCTARG]], function: {{.*print_child_tid.*}}, cpu: {{.*}}, thread: [[THREAD2]], process: [[PROCESS2]], kind: function-exit, tsc: {{[0-9]+}} } // -// TRACE: - { type: 0, func-id: [[PPOC]], function: {{.*print_parent_or_child.*}}, cpu: {{.*}}, thread: [[THREAD2]], kind: function-{{exit|tail-exit}}, tsc: {{[0-9]+}} } +// TRACE: - { type: 0, func-id: [[PPOC]], function: {{.*print_parent_or_child.*}}, cpu: {{.*}}, thread: [[THREAD2]], process: [[PROCESS2]], kind: function-{{exit|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.mapOptional("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 @@ -48,7 +48,7 @@ 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 +78,8 @@ // (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 +111,7 @@ 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 +120,14 @@ 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); + if (Record.FuncId != FuncId || Record.TId != TId || Record.PId != PId) 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 +149,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 +163,7 @@ CUSTOM_EVENT_DATA, CALL_ARGUMENT, BUFFER_EXTENTS, + PID_RECORD, }; Token Expects; @@ -188,6 +191,8 @@ return "CALL_ARGUMENT"; case FDRState::Token::BUFFER_EXTENTS: return "BUFFER_EXTENTS"; + case FDRState::Token::PID_RECORD: + return "PID_RECORD"; } return "UNKNOWN"; } @@ -268,6 +273,23 @@ 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 +347,8 @@ /// 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, @@ -360,7 +384,17 @@ case 4: // WallTimeMarker if (auto E = processFDRWallTimeRecord(State, RecordFirstByte, RecordExtractor)) - return E; + { + return E; + } + else + { + // 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 +410,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 +443,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 +476,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; @@ -477,6 +520,7 @@ /// 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 +534,11 @@ /// 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 +572,7 @@ InitialExpectation = FDRState::Token::NEW_BUFFER_RECORD_OR_EOF; break; case 2: + case 3: InitialExpectation = FDRState::Token::BUFFER_EXTENTS; break; default: @@ -530,7 +580,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. @@ -572,7 +622,7 @@ 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. @@ -622,7 +672,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(); } @@ -681,7 +731,7 @@ 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 +742,7 @@ } 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 { 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,7 +141,8 @@ Writer.write(R.FuncId); Writer.write(R.TSC); Writer.write(R.TId); - Writer.write(Padding4B); + Writer.write(R.PId); + 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 @@ -282,10 +284,10 @@ 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, + 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;