llvm.org GIT mirror llvm / 9317746
[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 git-svn-id: https://llvm.org/svn/llvm-project/llvm/trunk@336974 91177308-0d34-0410-b5e6-96231b3b80d8 Dean Michael Berris 1 year, 10 months ago
13 changed file(s) with 169 addition(s) and 29 deletion(s). Raw diff Collapse all Expand all
7474 /// The thread ID for the currently running thread.
7575 uint32_t TId;
7676
77 /// The process ID for the currently running process.
78 uint32_t PId;
79
7780 /// The function call arguments.
7881 std::vector CallArgs;
7982 };
3636 std::string Function;
3737 uint64_t TSC;
3838 uint32_t TId;
39 uint32_t PId;
3940 std::vector CallArgs;
4041 };
4142
7879 IO.mapOptional("args", Record.CallArgs);
7980 IO.mapRequired("cpu", Record.CPU);
8081 IO.mapRequired("thread", Record.TId);
82 IO.mapOptional("process", Record.PId, 0U);
8183 IO.mapRequired("kind", Record.Type);
8284 IO.mapRequired("tsc", Record.TSC);
8385 }
4747 FileHeader.NonstopTSC = Bitfield & 1uL << 1;
4848 FileHeader.CycleFrequency = HeaderExtractor.getU64(&OffsetPtr);
4949 std::memcpy(&FileHeader.FreeFormData, Data.bytes_begin() + OffsetPtr, 16);
50 if (FileHeader.Version != 1 && FileHeader.Version != 2)
50 if (FileHeader.Version != 1 && FileHeader.Version != 2 &&
51 FileHeader.Version != 3)
5152 return make_error(
5253 Twine("Unsupported XRay file version: ") + Twine(FileHeader.Version),
5354 std::make_error_code(std::errc::invalid_argument));
7778 // (4) sint32 : function id
7879 // (8) uint64 : tsc
7980 // (4) uint32 : thread id
80 // (12) - : padding
81 // (4) uint32 : process id
82 // (8) - : padding
8183 for (auto S = Data.drop_front(32); !S.empty(); S = S.drop_front(32)) {
8284 DataExtractor RecordExtractor(S, true, 8);
8385 uint32_t OffsetPtr = 0;
109111 Record.FuncId = RecordExtractor.getSigned(&OffsetPtr, sizeof(int32_t));
110112 Record.TSC = RecordExtractor.getU64(&OffsetPtr);
111113 Record.TId = RecordExtractor.getU32(&OffsetPtr);
114 Record.PId = RecordExtractor.getU32(&OffsetPtr);
112115 break;
113116 }
114117 case 1: { // Arg payload record.
117120 OffsetPtr += 2;
118121 int32_t FuncId = RecordExtractor.getSigned(&OffsetPtr, sizeof(int32_t));
119122 auto TId = RecordExtractor.getU32(&OffsetPtr);
120 if (Record.FuncId != FuncId || Record.TId != TId)
123 auto PId = RecordExtractor.getU32(&OffsetPtr);
124
125 // Make a check for versions above 3 for the Pid field
126 if (Record.FuncId != FuncId || Record.TId != TId ||
127 (FileHeader.Version >= 3 ? Record.PId != PId : false))
121128 return make_error(
122129 Twine("Corrupted log, found arg payload following non-matching "
123130 "function + thread record. Record for function ") +
124131 Twine(Record.FuncId) + " != " + Twine(FuncId) + "; offset: " +
125132 Twine(S.data() - Data.data()),
126133 std::make_error_code(std::errc::executable_format_error));
127 // Advance another four bytes to avoid padding.
128 OffsetPtr += 4;
134
129135 auto Arg = RecordExtractor.getU64(&OffsetPtr);
130136 Record.CallArgs.push_back(Arg);
131137 break;
147153 struct FDRState {
148154 uint16_t CPUId;
149155 uint16_t ThreadId;
156 int32_t ProcessId;
150157 uint64_t BaseTSC;
151158
152159 /// Encode some of the state transitions for the FDR log reader as explicit
160167 CUSTOM_EVENT_DATA,
161168 CALL_ARGUMENT,
162169 BUFFER_EXTENTS,
170 PID_RECORD,
163171 };
164172 Token Expects;
165173
187195 return "CALL_ARGUMENT";
188196 case FDRState::Token::BUFFER_EXTENTS:
189197 return "BUFFER_EXTENTS";
198 case FDRState::Token::PID_RECORD:
199 return "PID_RECORD";
190200 }
191201 return "UNKNOWN";
192202 }
263273
264274 // TODO: Someday, reconcile the TSC ticks to wall clock time for presentation
265275 // purposes. For now, we're ignoring these records.
276 State.Expects = FDRState::Token::NEW_CPU_ID_RECORD;
277 return Error::success();
278 }
279
280 /// State transition when a PidRecord is encountered.
281 Error processFDRPidRecord(FDRState &State, uint8_t RecordFirstByte,
282 DataExtractor &RecordExtractor) {
283
284 if (State.Expects != FDRState::Token::PID_RECORD)
285 return make_error(
286 Twine("Malformed log. Read Pid record kind out of sequence; "
287 "expected: ") +
288 fdrStateToTwine(State.Expects),
289 std::make_error_code(std::errc::executable_format_error));
290
291 uint32_t OffsetPtr = 1; // Read starting after the first byte.
292 State.ProcessId = RecordExtractor.getU32(&OffsetPtr);
266293 State.Expects = FDRState::Token::NEW_CPU_ID_RECORD;
267294 return Error::success();
268295 }
324351 /// Beginning with Version 2 of the FDR log, we do not depend on the size of the
325352 /// buffer, but rather use the extents to determine how far to read in the log
326353 /// for this particular buffer.
354 ///
355 /// In Version 3, FDR log now includes a pid metadata record after
356 /// WallTimeMarker
327357 Error processFDRMetadataRecord(FDRState &State, uint8_t RecordFirstByte,
328358 DataExtractor &RecordExtractor,
329359 size_t &RecordSize,
360390 if (auto E =
361391 processFDRWallTimeRecord(State, RecordFirstByte, RecordExtractor))
362392 return E;
393 // In Version 3 and and above, a PidRecord is expected after WallTimeRecord
394 if (Version >= 3)
395 State.Expects = FDRState::Token::PID_RECORD;
363396 break;
364397 case 5: // CustomEventMarker
365398 if (auto E = processCustomEventMarker(State, RecordFirstByte,
373406 break;
374407 case 7: // BufferExtents
375408 if (auto E = processBufferExtents(State, RecordFirstByte, RecordExtractor))
409 return E;
410 break;
411 case 9: // Pid
412 if (auto E = processFDRPidRecord(State, RecordFirstByte, RecordExtractor))
376413 return E;
377414 break;
378415 default:
403440 case FDRState::Token::WALLCLOCK_RECORD:
404441 return make_error(
405442 "Malformed log. Received Function Record when expecting wallclock.",
443 std::make_error_code(std::errc::executable_format_error));
444 case FDRState::Token::PID_RECORD:
445 return make_error(
446 "Malformed log. Received Function Record when expecting pid.",
406447 std::make_error_code(std::errc::executable_format_error));
407448 case FDRState::Token::NEW_CPU_ID_RECORD:
408449 return make_error(
433474 }
434475 Record.CPU = State.CPUId;
435476 Record.TId = State.ThreadId;
477 Record.PId = State.ProcessId;
436478 // Back up to read first 32 bits, including the 4 we pulled RecordType
437479 // and RecordKind out of. The remaining 28 are FunctionId.
438480 uint32_t OffsetPtr = 0;
476518 /// BufSize: 8 byte unsigned integer indicating how large the buffer is.
477519 /// NewBuffer: 16 byte metadata record with Thread Id.
478520 /// WallClockTime: 16 byte metadata record with human readable time.
521 /// Pid: 16 byte metadata record with Pid
479522 /// NewCPUId: 16 byte metadata record with CPUId and a 64 bit TSC reading.
480523 /// EOB: 16 byte record in a thread buffer plus mem garbage to fill BufSize.
481524 /// FunctionSequence: NewCPUId | TSCWrap | FunctionRecord
489532 /// BufferExtents: 16 byte metdata record describing how many usable bytes are
490533 /// in the buffer. This is measured from the start of the buffer
491534 /// and must always be at least 48 (bytes).
535 ///
536 /// In Version 3, we make the following changes:
537 ///
538 /// ThreadBuffer: BufferExtents NewBuffer WallClockTime Pid NewCPUId
539 /// FunctionSequence
492540 /// EOB: *deprecated*
493541 Error loadFDRLog(StringRef Data, XRayFileHeader &FileHeader,
494542 std::vector &Records) {
522570 InitialExpectation = FDRState::Token::NEW_BUFFER_RECORD_OR_EOF;
523571 break;
524572 case 2:
573 case 3:
525574 InitialExpectation = FDRState::Token::BUFFER_EXTENTS;
526575 break;
527576 default:
529578 Twine("Unsupported version '") + Twine(FileHeader.Version) + "'",
530579 std::make_error_code(std::errc::executable_format_error));
531580 }
532 FDRState State{0, 0, 0, InitialExpectation, BufferSize, 0};
581 FDRState State{0, 0, 0, 0, InitialExpectation, BufferSize, 0};
533582
534583 // RecordSize will tell the loop how far to seek ahead based on the record
535584 // type that we have just read.
571620 if (!isBufferExtents)
572621 State.CurrentBufferConsumed += RecordSize;
573622 assert(State.CurrentBufferConsumed <= State.CurrentBufferSize);
574 if (FileHeader.Version == 2 &&
623 if ((FileHeader.Version == 2 || FileHeader.Version == 3) &&
575624 State.CurrentBufferSize == State.CurrentBufferConsumed) {
576625 // In Version 2 of the log, we don't need to scan to the end of the thread
577626 // buffer if we've already consumed all the bytes we need to.
620669 Records.clear();
621670 std::transform(Trace.Records.begin(), Trace.Records.end(),
622671 std::back_inserter(Records), [&](const YAMLXRayRecord &R) {
623 return XRayRecord{R.RecordType, R.CPU, R.Type, R.FuncId,
624 R.TSC, R.TId, R.CallArgs};
672 return XRayRecord{R.RecordType, R.CPU, R.Type, R.FuncId,
673 R.TSC, R.TId, R.PId, R.CallArgs};
625674 });
626675 return Error::success();
627676 }
680729 Trace T;
681730 switch (Type) {
682731 case NAIVE_FORMAT:
683 if (Version == 1 || Version == 2) {
732 if (Version == 1 || Version == 2 || Version == 3) {
684733 if (auto E = loadNaiveFormatLog(Data, T.FileHeader, T.Records))
685734 return std::move(E);
686735 } else {
691740 }
692741 break;
693742 case FLIGHT_DATA_RECORDER_FORMAT:
694 if (Version == 1 || Version == 2) {
743 if (Version == 1 || Version == 2 || Version == 3) {
695744 if (auto E = loadFDRLog(Data, T.FileHeader, T.Records))
696745 return std::move(E);
697746 } else {
0 ; RUN: llvm-xray convert %S/Inputs/basic-log-arg1-version-3.xray -f=yaml -o - | FileCheck %s
1
2 ; CHECK: ---
3 ; CHECK-NEXT: header:
4 ; CHECK-NEXT: version: 3
5 ; CHECK-NEXT: type: 0
6 ; CHECK-NEXT: constant-tsc: true
7 ; CHECK-NEXT: nonstop-tsc: true
8 ; CHECK-NEXT: cycle-frequency: 3900000000
9 ; CHECK-NEXT: records:
10 ; CHECK-NEXT: - { type: 0, func-id: 3, function: '3', cpu: 0, thread: 2590, process: 2590, kind: function-enter, tsc: 2033303630902004 }
11 ; CHECK-NEXT: - { type: 0, func-id: 3, function: '3', cpu: 0, thread: 2590, process: 2590, kind: function-exit, tsc: 2033403115246844 }
12 ; CHECK-NEXT: - { type: 0, func-id: 2, function: '2', cpu: 0, thread: 2590, process: 2590, kind: function-enter, tsc: 2033490200702516 }
13 ; CHECK-NEXT: - { type: 0, func-id: 2, function: '2', cpu: 0, thread: 2590, process: 2590, kind: function-exit, tsc: 2033504122687120 }
14 ; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', args: [ 67 ], cpu: 0, thread: 2590, process: 2590, kind: function-enter-arg, tsc: 2033505343905936 }
15 ; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', cpu: 0, thread: 2590, process: 2590, kind: function-exit, tsc: 2033505343936752 }
16 ; CHECK-NEXT: ...
0 ; RUN: llvm-xray convert %S/Inputs/basic-log-version-3.xray -f=yaml -o - | FileCheck %s
1
2 ; CHECK: ---
3 ; CHECK-NEXT: header:
4 ; CHECK-NEXT: version: 3
5 ; CHECK-NEXT: type: 0
6 ; CHECK-NEXT: constant-tsc: true
7 ; CHECK-NEXT: nonstop-tsc: true
8 ; CHECK-NEXT: cycle-frequency: 3900000000
9 ; CHECK-NEXT: records:
10 ; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', cpu: 7, thread: 25518, process: 25518, kind: function-enter, tsc: 2070767347414784 }
11 ; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', cpu: 7, thread: 25518, process: 25518, kind: function-exit, tsc: 2070767347496472 }
12 ; CHECK-NEXT: - { type: 0, func-id: 2, function: '2', cpu: 7, thread: 25518, process: 25518, kind: function-enter, tsc: 2070768324320264 }
13 ; CHECK-NEXT: - { type: 0, func-id: 2, function: '2', cpu: 7, thread: 25518, process: 25518, kind: function-exit, tsc: 2070768324344100 }
14 ; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', cpu: 7, thread: 25518, process: 25518, kind: function-enter, tsc: 2070768921602152 }
15 ; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', cpu: 7, thread: 25518, process: 25518, kind: function-exit, tsc: 2070768921625968 }
16 ; CHECK-NEXT: - { type: 0, func-id: 2, function: '2', cpu: 7, thread: 25518, process: 25518, kind: function-enter, tsc: 2070769627174140 }
17 ; CHECK-NEXT: - { type: 0, func-id: 2, function: '2', cpu: 7, thread: 25518, process: 25518, kind: function-exit, tsc: 2070769627197624 }
18 ; CHECK-NEXT: ...
0 ; RUN: llvm-xray convert %S/Inputs/fdr-log-arg1-version-3.xray -f=yaml -o - | FileCheck %s
1
2 ; CHECK: ---
3 ; CHECK-NEXT: header:
4 ; CHECK-NEXT: version: 3
5 ; CHECK-NEXT: type: 1
6 ; CHECK-NEXT: constant-tsc: true
7 ; CHECK-NEXT: nonstop-tsc: true
8 ; CHECK-NEXT: cycle-frequency: 3900000000
9 ; CHECK-NEXT: records:
10 ; CHECK-NEXT: - { type: 0, func-id: 3, function: '3', cpu: 6, thread: 2631, process: 2631, kind: function-enter, tsc: 2034042117104344 }
11 ; CHECK-NEXT: - { type: 0, func-id: 3, function: '3', cpu: 6, thread: 2631, process: 2631, kind: function-exit, tsc: 2034042117199088 }
12 ; CHECK-NEXT: - { type: 0, func-id: 2, function: '2', cpu: 6, thread: 2631, process: 2631, kind: function-enter, tsc: 2034043145686378 }
13 ; CHECK-NEXT: - { type: 0, func-id: 2, function: '2', cpu: 6, thread: 2631, process: 2631, kind: function-exit, tsc: 2034043145762200 }
14 ; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', args: [ 67 ], cpu: 6, thread: 2631, process: 2631, kind: function-enter-arg, tsc: 2034049739853430 }
15 ; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', cpu: 6, thread: 2631, process: 2631, kind: function-exit, tsc: 2034049739878154 }
16 ; CHECK-NEXT: ...
0 ; RUN: llvm-xray convert %S/Inputs/fdr-log-version-3.xray -f=yaml -o - | FileCheck %s
1
2 ; CHECK: ---
3 ; CHECK-NEXT: header:
4 ; CHECK-NEXT: version: 3
5 ; CHECK-NEXT: type: 1
6 ; CHECK-NEXT: constant-tsc: true
7 ; CHECK-NEXT: nonstop-tsc: true
8 ; CHECK-NEXT: cycle-frequency: 3900000000
9 ; CHECK-NEXT: records:
10 ; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', cpu: 4, thread: 25190, process: 25190, kind: function-enter, tsc: 2069294857657498 }
11 ; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', cpu: 4, thread: 25190, process: 25190, kind: function-exit, tsc: 2069294857707502 }
12 ; CHECK-NEXT: - { type: 0, func-id: 2, function: '2', cpu: 4, thread: 25190, process: 25190, kind: function-enter, tsc: 2069295590705912 }
13 ; CHECK-NEXT: - { type: 0, func-id: 2, function: '2', cpu: 4, thread: 25190, process: 25190, kind: function-exit, tsc: 2069295590734308 }
14 ; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', cpu: 4, thread: 25190, process: 25190, kind: function-enter, tsc: 2069296377598128 }
15 ; CHECK-NEXT: - { type: 0, func-id: 1, function: '1', cpu: 4, thread: 25190, process: 25190, kind: function-exit, tsc: 2069296377627032 }
16 ; CHECK-NEXT: ...
475475 errs()
476476 << "Error processing record: "
477477 << llvm::formatv(
478 R"({{type: {0}; cpu: {1}; record-type: {2}; function-id: {3}; tsc: {4}; thread-id: {5}}})",
478 R"({{type: {0}; cpu: {1}; record-type: {2}; function-id: {3}; tsc: {4}; thread-id: {5}; process-id: {6}}})",
479479 Record.RecordType, Record.CPU, Record.Type, Record.FuncId,
480 Record.TId)
480 Record.TSC, Record.TId, Record.PId)
481481 << '\n';
482482 for (const auto &ThreadStack : FCA.getPerThreadFunctionStack()) {
483483 errs() << "Thread ID: " << ThreadStack.first << "\n";
9090 Trace.Records.push_back({R.RecordType, R.CPU, R.Type, R.FuncId,
9191 Symbolize ? FuncIdHelper.SymbolOrNumber(R.FuncId)
9292 : llvm::to_string(R.FuncId),
93 R.TSC, R.TId, R.CallArgs});
93 R.TSC, R.TId, R.PId, R.CallArgs});
9494 }
9595 Output Out(OS, nullptr, 0);
9696 Out << Trace;
140140 Writer.write(R.FuncId);
141141 Writer.write(R.TSC);
142142 Writer.write(R.TId);
143 Writer.write(Padding4B);
143
144 if (FH.Version >= 3)
145 Writer.write(R.PId);
146 else
147 Writer.write(Padding4B);
148
144149 Writer.write(Padding4B);
145150 Writer.write(Padding4B);
146151 }
228233 return CurrentStack;
229234 }
230235
231 void writeTraceViewerRecord(raw_ostream &OS, int32_t FuncId, uint32_t TId,
232 bool Symbolize,
236 void writeTraceViewerRecord(uint16_t Version, raw_ostream &OS, int32_t FuncId,
237 uint32_t TId, uint32_t PId, bool Symbolize,
233238 const FuncIdConversionHelper &FuncIdHelper,
234239 double EventTimestampUs,
235240 const StackTrieNode &StackCursor,
236241 StringRef FunctionPhenotype) {
237242 OS << " ";
238 OS << llvm::formatv(
239 R"({ "name" : "{0}", "ph" : "{1}", "tid" : "{2}", "pid" : "1", )"
240 R"("ts" : "{3:f3}", "sf" : "{4}" })",
241 (Symbolize ? FuncIdHelper.SymbolOrNumber(FuncId)
242 : llvm::to_string(FuncId)),
243 FunctionPhenotype, TId, EventTimestampUs, StackCursor.ExtraData.id);
243 if (Version >= 3) {
244 OS << llvm::formatv(
245 R"({ "name" : "{0}", "ph" : "{1}", "tid" : "{2}", "pid" : "{3}", )"
246 R"("ts" : "{4:f4}", "sf" : "{5}" })",
247 (Symbolize ? FuncIdHelper.SymbolOrNumber(FuncId)
248 : llvm::to_string(FuncId)),
249 FunctionPhenotype, TId, PId, EventTimestampUs,
250 StackCursor.ExtraData.id);
251 } else {
252 OS << llvm::formatv(
253 R"({ "name" : "{0}", "ph" : "{1}", "tid" : "{2}", "pid" : "1", )"
254 R"("ts" : "{3:f3}", "sf" : "{4}" })",
255 (Symbolize ? FuncIdHelper.SymbolOrNumber(FuncId)
256 : llvm::to_string(FuncId)),
257 FunctionPhenotype, TId, EventTimestampUs, StackCursor.ExtraData.id);
258 }
244259 }
245260
246261 } // namespace
248263 void TraceConverter::exportAsChromeTraceEventFormat(const Trace &Records,
249264 raw_ostream &OS) {
250265 const auto &FH = Records.getFileHeader();
266 auto Version = FH.Version;
251267 auto CycleFreq = FH.CycleFrequency;
252268
253269 unsigned id_counter = 0;
281297 StackRootsByThreadId, StacksByStackId,
282298 &id_counter, NodeStore);
283299 // Each record is represented as a json dictionary with function name,
284 // type of B for begin or E for end, thread id, process id (faked),
300 // type of B for begin or E for end, thread id, process id,
285301 // timestamp in microseconds, and a stack frame id. The ids are logged
286302 // in an id dictionary after the events.
287 writeTraceViewerRecord(OS, R.FuncId, R.TId, Symbolize, FuncIdHelper,
288 EventTimestampUs, *StackCursor, "B");
303 writeTraceViewerRecord(Version, OS, R.FuncId, R.TId, R.PId, Symbolize,
304 FuncIdHelper, EventTimestampUs, *StackCursor, "B");
289305 break;
290306 case RecordTypes::EXIT:
291307 case RecordTypes::TAIL_EXIT:
296312 // (And/Or in loop termination below)
297313 StackTrieNode *PreviousCursor = nullptr;
298314 do {
299 writeTraceViewerRecord(OS, StackCursor->FuncId, R.TId, Symbolize,
300 FuncIdHelper, EventTimestampUs, *StackCursor,
301 "E");
315 writeTraceViewerRecord(Version, OS, StackCursor->FuncId, R.TId, R.PId,
316 Symbolize, FuncIdHelper, EventTimestampUs,
317 *StackCursor, "E");
302318 PreviousCursor = StackCursor;
303319 StackCursor = StackCursor->Parent;
304320 } while (PreviousCursor->FuncId != R.FuncId && StackCursor != nullptr);