replica
/
hanchenye-llvm-project
2
0
Fork 0
Code Issues Pull Requests Projects Releases Wiki Activity

[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
This commit is contained in:
Dean Michael Berris 2018-07-13 05:38:22 +00:00
parent 2ab325ba23
commit 10141261e1
21 changed files with 224 additions and 69 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

6
compiler-rt/lib/xray/tests/unit/fdr_logging_test.cc
View File

@ -87,7 +87,7 @@ TEST(FDRLoggingTest, Simple) {
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 @@ TEST(FDRLoggingTest, Multiple) {
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 @@ TEST(FDRLoggingTest, MultiThreadedCycling) {
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;

4
compiler-rt/lib/xray/xray_basic_logging.cc
View File

@ -90,7 +90,9 @@ static int openLogFile() XRAY_NEVER_INSTRUMENT {
// 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);

1
compiler-rt/lib/xray/xray_fdr_log_records.h
View File

@ -33,6 +33,7 @@ struct alignas(16) MetadataRecord {
CallArgument,
BufferExtents,
TypedEventMarker,
Pid,
};
// Use 7 bits to identify this record type.

22
compiler-rt/lib/xray/xray_fdr_logging.cc
View File

@ -125,9 +125,9 @@ static ThreadLocalData &getThreadLocalData() {
return TLD;
}
static void writeNewBufferPreamble(tid_t Tid,
timespec TS) XRAY_NEVER_INSTRUMENT {
static constexpr int InitRecordsCount = 2;
static void writeNewBufferPreamble(tid_t Tid, timespec TS,
pid_t Pid) XRAY_NEVER_INSTRUMENT {
static constexpr int InitRecordsCount = 3;
auto &TLD = getThreadLocalData();
MetadataRecord Metadata[InitRecordsCount];
{
@ -161,6 +161,16 @@ static void writeNewBufferPreamble(tid_t Tid,
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<int32_t>(Pid);
internal_memcpy(&PidMetadata.Data, &pid, sizeof(pid));
}
TLD.NumConsecutiveFnEnters = 0;
TLD.NumTailCalls = 0;
if (TLD.BQ == nullptr || TLD.BQ->finalizing())
@ -180,9 +190,10 @@ static void setupNewBuffer(int (*wall_clock_reader)(
TLD.RecordPtr = static_cast<char *>(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 +674,8 @@ static XRayFileHeader &fdrCommonHeaderInfo() {
XRayFileHeader &H = reinterpret_cast<XRayFileHeader &>(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

32
compiler-rt/test/xray/TestCases/Posix/fdr-mode.cc
View File

@ -81,32 +81,32 @@ int main(int argc, char *argv[]) {
}
// 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}}

4
compiler-rt/test/xray/TestCases/Posix/fdr-single-thread.cc
View File

@ -34,5 +34,5 @@ int main(int argc, char *argv[]) {
}
// 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]+}} }

8
compiler-rt/test/xray/TestCases/Posix/fdr-thread-order.cc
View File

@ -61,7 +61,7 @@ int main(int argc, char *argv[]) {
}
// 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]+}} }

18
compiler-rt/test/xray/TestCases/Posix/fork_basic_logging.cc
View File

@ -81,20 +81,20 @@ int main()
}
// 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]+}} }

3
llvm/include/llvm/XRay/XRayRecord.h
View File

@ -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<uint64_t> CallArgs;
};

2
llvm/include/llvm/XRay/YAMLXRayRecord.h
View File

@ -37,6 +37,7 @@ struct YAMLXRayRecord {
std::string Function;
uint64_t TSC;
uint32_t TId;
uint32_t PId;
std::vector<uint64_t> CallArgs;
};
@ -79,6 +80,7 @@ template <> struct MappingTraits<xray::YAMLXRayRecord> {
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);
}

71
llvm/lib/XRay/Trace.cpp
View File

@ -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<StringError>(
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<StringError>(
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<StringError>(
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<StringError>(
@ -405,6 +442,10 @@ Error processFDRFunctionRecord(FDRState &State, uint8_t RecordFirstByte,
return make_error<StringError>(
"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<StringError>(
"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<StringError>(
"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<XRayRecord> &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<Trace> 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<Trace> 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 {

BIN
llvm/test/tools/llvm-xray/X86/Inputs/basic-log-arg1-version-3.xray Normal file
View File

Binary file not shown.

BIN
llvm/test/tools/llvm-xray/X86/Inputs/basic-log-version-3.xray Normal file
View File

Binary file not shown.

BIN
llvm/test/tools/llvm-xray/X86/Inputs/fdr-log-arg1-version-3.xray Normal file
View File

Binary file not shown.

BIN
llvm/test/tools/llvm-xray/X86/Inputs/fdr-log-version-3.xray Normal file
View File

Binary file not shown.

17
llvm/test/tools/llvm-xray/X86/convert-basic-log-arg1-version3-to-yaml.txt Normal file
View File

@ -0,0 +1,17 @@
; RUN: llvm-xray convert %S/Inputs/basic-log-arg1-version-3.xray -f=yaml -o - | FileCheck %s
; CHECK: ---
; CHECK-NEXT: header:
; CHECK-NEXT: version: 3
; CHECK-NEXT: type: 0
; CHECK-NEXT: constant-tsc: true
; CHECK-NEXT: nonstop-tsc: true
; CHECK-NEXT: cycle-frequency: 3900000000
; CHECK-NEXT: records:
; CHECK-NEXT: - { type: 0, func-id: 3, function: '3', cpu: 0, thread: 2590, process: 2590, kind: function-enter, tsc: 2033303630902004 }
; CHECK-NEXT: - { type: 0, func-id: 3, function: '3', cpu: 0, thread: 2590, process: 2590, kind: function-exit, tsc: 2033403115246844 }
; CHECK-NEXT: - { type: 0, func-id: 2, function: '2', cpu: 0, thread: 2590, process: 2590, kind: function-enter, tsc: 2033490200702516 }
; CHECK-NEXT: - { type: 0, func-id: 2, function: '2', cpu: 0, thread: 2590, process: 2590, kind: function-exit, tsc: 2033504122687120 }
; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', args: [ 67 ], cpu: 0, thread: 2590, process: 2590, kind: function-enter-arg, tsc: 2033505343905936 }
; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', cpu: 0, thread: 2590, process: 2590, kind: function-exit, tsc: 2033505343936752 }
; CHECK-NEXT: ...

19
llvm/test/tools/llvm-xray/X86/convert-basic-log-version3-to-yaml.txt Normal file
View File

@ -0,0 +1,19 @@
; RUN: llvm-xray convert %S/Inputs/basic-log-version-3.xray -f=yaml -o - | FileCheck %s
; CHECK: ---
; CHECK-NEXT: header:
; CHECK-NEXT: version: 3
; CHECK-NEXT: type: 0
; CHECK-NEXT: constant-tsc: true
; CHECK-NEXT: nonstop-tsc: true
; CHECK-NEXT: cycle-frequency: 3900000000
; CHECK-NEXT: records:
; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', cpu: 7, thread: 25518, process: 25518, kind: function-enter, tsc: 2070767347414784 }
; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', cpu: 7, thread: 25518, process: 25518, kind: function-exit, tsc: 2070767347496472 }
; CHECK-NEXT: - { type: 0, func-id: 2, function: '2', cpu: 7, thread: 25518, process: 25518, kind: function-enter, tsc: 2070768324320264 }
; CHECK-NEXT: - { type: 0, func-id: 2, function: '2', cpu: 7, thread: 25518, process: 25518, kind: function-exit, tsc: 2070768324344100 }
; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', cpu: 7, thread: 25518, process: 25518, kind: function-enter, tsc: 2070768921602152 }
; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', cpu: 7, thread: 25518, process: 25518, kind: function-exit, tsc: 2070768921625968 }
; CHECK-NEXT: - { type: 0, func-id: 2, function: '2', cpu: 7, thread: 25518, process: 25518, kind: function-enter, tsc: 2070769627174140 }
; CHECK-NEXT: - { type: 0, func-id: 2, function: '2', cpu: 7, thread: 25518, process: 25518, kind: function-exit, tsc: 2070769627197624 }
; CHECK-NEXT: ...

17
llvm/test/tools/llvm-xray/X86/convert-fdr-log-arg1-version3-to-yaml.txt Normal file
View File

@ -0,0 +1,17 @@
; RUN: llvm-xray convert %S/Inputs/fdr-log-arg1-version-3.xray -f=yaml -o - | FileCheck %s
; CHECK: ---
; CHECK-NEXT: header:
; CHECK-NEXT: version: 3
; CHECK-NEXT: type: 1
; CHECK-NEXT: constant-tsc: true
; CHECK-NEXT: nonstop-tsc: true
; CHECK-NEXT: cycle-frequency: 3900000000
; CHECK-NEXT: records:
; CHECK-NEXT: - { type: 0, func-id: 3, function: '3', cpu: 6, thread: 2631, process: 2631, kind: function-enter, tsc: 2034042117104344 }
; CHECK-NEXT: - { type: 0, func-id: 3, function: '3', cpu: 6, thread: 2631, process: 2631, kind: function-exit, tsc: 2034042117199088 }
; CHECK-NEXT: - { type: 0, func-id: 2, function: '2', cpu: 6, thread: 2631, process: 2631, kind: function-enter, tsc: 2034043145686378 }
; CHECK-NEXT: - { type: 0, func-id: 2, function: '2', cpu: 6, thread: 2631, process: 2631, kind: function-exit, tsc: 2034043145762200 }
; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', args: [ 67 ], cpu: 6, thread: 2631, process: 2631, kind: function-enter-arg, tsc: 2034049739853430 }
; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', cpu: 6, thread: 2631, process: 2631, kind: function-exit, tsc: 2034049739878154 }
; CHECK-NEXT: ...

17
llvm/test/tools/llvm-xray/X86/convert-fdr-log-version3-to-yaml.txt Normal file
View File

@ -0,0 +1,17 @@
; RUN: llvm-xray convert %S/Inputs/fdr-log-version-3.xray -f=yaml -o - | FileCheck %s
; CHECK: ---
; CHECK-NEXT: header:
; CHECK-NEXT: version: 3
; CHECK-NEXT: type: 1
; CHECK-NEXT: constant-tsc: true
; CHECK-NEXT: nonstop-tsc: true
; CHECK-NEXT: cycle-frequency: 3900000000
; CHECK-NEXT: records:
; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', cpu: 4, thread: 25190, process: 25190, kind: function-enter, tsc: 2069294857657498 }
; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', cpu: 4, thread: 25190, process: 25190, kind: function-exit, tsc: 2069294857707502 }
; CHECK-NEXT: - { type: 0, func-id: 2, function: '2', cpu: 4, thread: 25190, process: 25190, kind: function-enter, tsc: 2069295590705912 }
; CHECK-NEXT: - { type: 0, func-id: 2, function: '2', cpu: 4, thread: 25190, process: 25190, kind: function-exit, tsc: 2069295590734308 }
; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', cpu: 4, thread: 25190, process: 25190, kind: function-enter, tsc: 2069296377598128 }
; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', cpu: 4, thread: 25190, process: 25190, kind: function-exit, tsc: 2069296377627032 }
; CHECK-NEXT: ...

4
llvm/tools/llvm-xray/xray-account.cpp
View File

@ -476,9 +476,9 @@ static CommandRegistration Unused(&Account, []() -> 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";

48
llvm/tools/llvm-xray/xray-converter.cpp
View File

@ -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);