llvm.org GIT mirror llvm / 8fa10fd
[XRay] Use TSC delta encoding for custom/typed events Summary: This change updates the version number for FDR logs to 5, and update the trace processing to support changes in the custom event records. In the runtime, since we're already writing down the record preamble to handle CPU migrations and TSC wraparound, we can use the same TSC delta encoding in the custom event and typed event records that we use in function event records. We do the same change to typed events (which were unsupported before this change in the trace processing) which now show up in the trace. Future changes should increase our testing coverage to make custom and typed events as first class entities in the FDR mode log processing tools. This change is also a good example of how we end up supporting new record types in the FDR mode implementation. This shows the places where new record types are added and supported. Depends on D54139. Reviewers: mboerger Subscribers: hiraditya, arphaman, jfb, llvm-commits Differential Revision: https://reviews.llvm.org/D54140 git-svn-id: https://llvm.org/svn/llvm-project/llvm/trunk@346293 91177308-0d34-0410-b5e6-96231b3b80d8 Dean Michael Berris 11 months ago
19 changed file(s) with 310 addition(s) and 13 deletion(s). Raw diff Collapse all Expand all
5353 Error visit(NewBufferRecord &) override;
5454 Error visit(EndBufferRecord &) override;
5555 Error visit(FunctionRecord &) override;
56 Error visit(CustomEventRecordV5 &) override;
57 Error visit(TypedEventRecord &) override;
5658
5759 /// The flush() function will clear out the current state of the visitor, to
5860 /// allow for explicitly flushing a block's records to the currently
4949 Error visit(NewBufferRecord &) override;
5050 Error visit(EndBufferRecord &) override;
5151 Error visit(FunctionRecord &) override;
52 Error visit(CustomEventRecordV5 &) override;
53 Error visit(TypedEventRecord &) override;
5254
5355 void reset() { CurrentState = State::Start; }
5456 };
3232 NewCPUId,
3333 TSCWrap,
3434 CustomEvent,
35 TypedEvent,
3536 Function,
3637 CallArg,
3738 EndOfBuffer,
5758 Error visit(NewBufferRecord &) override;
5859 Error visit(EndBufferRecord &) override;
5960 Error visit(FunctionRecord &) override;
61 Error visit(CustomEventRecordV5 &) override;
62 Error visit(TypedEventRecord &) override;
6063
6164 Error verify();
6265 void reset();
6565 PIDEntry,
6666 NewBuffer,
6767 EndOfBuffer,
68 TypedEvent,
6869 };
6970
7071 Type type() const override { return Type::Metadata; }
168169 int32_t size() const { return Size; }
169170 uint64_t tsc() const { return TSC; }
170171 uint16_t cpu() const { return CPU; }
172 StringRef data() const { return Data; }
173
174 Error apply(RecordVisitor &V) override;
175 };
176
177 class CustomEventRecordV5 : public MetadataRecord {
178 int32_t Size = 0;
179 int32_t Delta = 0;
180 std::string Data{};
181 friend class RecordInitializer;
182
183 public:
184 CustomEventRecordV5() = default;
185 explicit CustomEventRecordV5(int32_t S, int32_t D, std::string P)
186 : MetadataRecord(), Size(S), Delta(D), Data(std::move(P)) {}
187
188 MetadataType metadataType() const override {
189 return MetadataType::CustomEvent;
190 }
191
192 int32_t size() const { return Size; }
193 int32_t delta() const { return Delta; }
194 StringRef data() const { return Data; }
195
196 Error apply(RecordVisitor &V) override;
197 };
198
199 class TypedEventRecord : public MetadataRecord {
200 int32_t Size = 0;
201 int32_t Delta = 0;
202 uint16_t EventType = 0;
203 std::string Data{};
204 friend class RecordInitializer;
205
206 public:
207 TypedEventRecord() = default;
208 explicit TypedEventRecord(int32_t S, int32_t D, uint16_t E, std::string P)
209 : MetadataRecord(), Size(S), Delta(D), Data(std::move(P)) {}
210
211 MetadataType metadataType() const override {
212 return MetadataType::TypedEvent;
213 }
214
215 int32_t size() const { return Size; }
216 int32_t delta() const { return Delta; }
217 uint16_t eventType() const { return EventType; }
171218 StringRef data() const { return Data; }
172219
173220 Error apply(RecordVisitor &V) override;
268315 virtual Error visit(NewBufferRecord &) = 0;
269316 virtual Error visit(EndBufferRecord &) = 0;
270317 virtual Error visit(FunctionRecord &) = 0;
318 virtual Error visit(CustomEventRecordV5 &) = 0;
319 virtual Error visit(TypedEventRecord &) = 0;
271320 };
272321
273322 class RecordInitializer : public RecordVisitor {
276325 uint16_t Version;
277326
278327 public:
279 static constexpr uint16_t DefaultVersion = 4u;
328 static constexpr uint16_t DefaultVersion = 5u;
280329
281330 explicit RecordInitializer(DataExtractor &DE, uint32_t &OP, uint16_t V)
282331 : RecordVisitor(), E(DE), OffsetPtr(OP), Version(V) {}
294343 Error visit(NewBufferRecord &) override;
295344 Error visit(EndBufferRecord &) override;
296345 Error visit(FunctionRecord &) override;
346 Error visit(CustomEventRecordV5 &) override;
347 Error visit(TypedEventRecord &) override;
297348 };
298349
299350 } // namespace xray
4848 Error visit(NewBufferRecord &) override;
4949 Error visit(EndBufferRecord &) override;
5050 Error visit(FunctionRecord &) override;
51 Error visit(CustomEventRecordV5 &) override;
52 Error visit(TypedEventRecord &) override;
5153
5254 // Must be called after all the records have been processed, to handle the
5355 // most recent record generated.
4242 Error visit(NewBufferRecord &) override;
4343 Error visit(EndBufferRecord &) override;
4444 Error visit(FunctionRecord &) override;
45 Error visit(CustomEventRecordV5 &) override;
46 Error visit(TypedEventRecord &) override;
4547
4648 private:
4749 support::endian::Writer OS;
3939 Error visit(NewBufferRecord &) override;
4040 Error visit(EndBufferRecord &) override;
4141 Error visit(FunctionRecord &) override;
42 Error visit(CustomEventRecordV5 &) override;
43 Error visit(TypedEventRecord &) override;
4244 };
4345
4446 } // namespace xray
3434 }
3535
3636 Error BlockIndexer::visit(CustomEventRecord &R) {
37 CurrentBlock.Records.push_back(&R);
38 return Error::success();
39 }
40
41 Error BlockIndexer::visit(CustomEventRecordV5 &R) {
42 CurrentBlock.Records.push_back(&R);
43 return Error::success();
44 }
45
46 Error BlockIndexer::visit(TypedEventRecord &R) {
3747 CurrentBlock.Records.push_back(&R);
3848 return Error::success();
3949 }
6767 return E;
6868 }
6969
70 Error BlockPrinter::visit(CustomEventRecordV5 &R) {
71 if (CurrentState == State::Metadata)
72 OS << "\n";
73 CurrentState = State::CustomEvent;
74 OS << "* ";
75 auto E = RP.visit(R);
76 return E;
77 }
78
79 Error BlockPrinter::visit(TypedEventRecord &R) {
80 if (CurrentState == State::Metadata)
81 OS << "\n";
82 CurrentState = State::CustomEvent;
83 OS << "* ";
84 auto E = RP.visit(R);
85 return E;
86 }
87
7088 // Function call printing.
7189 Error BlockPrinter::visit(FunctionRecord &R) {
7290 if (CurrentState == State::Metadata)
4242 return "CallArg";
4343 case BlockVerifier::State::EndOfBuffer:
4444 return "EndOfBuffer";
45 case BlockVerifier::State::TypedEvent:
46 return "TypedEvent";
4547 case BlockVerifier::State::StateMax:
4648 case BlockVerifier::State::Unknown:
4749 return "Unknown";
7476 {State::NewCPUId,
7577 {mask(State::NewCPUId) | mask(State::TSCWrap) |
7678 mask(State::CustomEvent) | mask(State::Function) |
77 mask(State::EndOfBuffer)}},
79 mask(State::EndOfBuffer) | mask(State::TypedEvent)}},
7880
7981 {State::TSCWrap,
8082 {mask(State::TSCWrap) | mask(State::NewCPUId) |
8183 mask(State::CustomEvent) | mask(State::Function) |
82 mask(State::EndOfBuffer)}},
84 mask(State::EndOfBuffer) | mask(State::TypedEvent)}},
8385
8486 {State::CustomEvent,
8587 {mask(State::CustomEvent) | mask(State::TSCWrap) |
8688 mask(State::NewCPUId) | mask(State::Function) |
87 mask(State::EndOfBuffer)}},
89 mask(State::EndOfBuffer) | mask(State::TypedEvent)}},
90
91 {State::TypedEvent,
92 {mask(State::TypedEvent) | mask(State::TSCWrap) |
93 mask(State::NewCPUId) | mask(State::Function) |
94 mask(State::EndOfBuffer) | mask(State::CustomEvent)}},
8895
8996 {State::Function,
9097 {mask(State::Function) | mask(State::TSCWrap) |
9198 mask(State::NewCPUId) | mask(State::CustomEvent) |
92 mask(State::CallArg) | mask(State::EndOfBuffer)}},
99 mask(State::CallArg) | mask(State::EndOfBuffer) |
100 mask(State::TypedEvent)}},
93101
94102 {State::CallArg,
95103 {mask(State::CallArg) | mask(State::Function) |
96104 mask(State::TSCWrap) | mask(State::NewCPUId) |
97 mask(State::CustomEvent) | mask(State::EndOfBuffer)}},
105 mask(State::CustomEvent) | mask(State::EndOfBuffer) |
106 mask(State::TypedEvent)}},
98107
99108 {State::EndOfBuffer, {}}}};
100109
144153 return transition(State::CustomEvent);
145154 }
146155
156 Error BlockVerifier::visit(CustomEventRecordV5 &) {
157 return transition(State::CustomEvent);
158 }
159
160 Error BlockVerifier::visit(TypedEventRecord &) {
161 return transition(State::TypedEvent);
162 }
163
147164 Error BlockVerifier::visit(CallArgRecord &) {
148165 return transition(State::CallArg);
149166 }
168185 case State::EndOfBuffer:
169186 case State::NewCPUId:
170187 case State::CustomEvent:
188 case State::TypedEvent:
171189 case State::Function:
172190 case State::CallArg:
173191 case State::TSCWrap:
5252 case MetadataRecordKinds::WalltimeMarkerKind:
5353 return make_unique();
5454 case MetadataRecordKinds::CustomEventMarkerKind:
55 if (Header.Version >= 5)
56 return make_unique();
5557 return make_unique();
5658 case MetadataRecordKinds::CallArgumentKind:
5759 return make_unique();
5860 case MetadataRecordKinds::BufferExtentsKind:
5961 return make_unique();
6062 case MetadataRecordKinds::TypedEventMarkerKind:
61 return createStringError(std::make_error_code(std::errc::invalid_argument),
62 "Encountered an unsupported TypedEventMarker.");
63 return make_unique();
6364 case MetadataRecordKinds::PidKind:
6465 return make_unique();
6566 case MetadataRecordKinds::EnumEndMarker:
2525 Error NewBufferRecord::apply(RecordVisitor &V) { return V.visit(*this); }
2626 Error EndBufferRecord::apply(RecordVisitor &V) { return V.visit(*this); }
2727 Error FunctionRecord::apply(RecordVisitor &V) { return V.visit(*this); }
28 Error CustomEventRecordV5::apply(RecordVisitor &V) { return V.visit(*this); }
29 Error TypedEventRecord::apply(RecordVisitor &V) { return V.visit(*this); }
2830
2931 } // namespace xray
3032 } // namespace llvm
4444 CurrentRecord.PId = PID;
4545 CurrentRecord.TId = TID;
4646 CurrentRecord.Type = RecordTypes::CUSTOM_EVENT;
47 std::copy(R.data().begin(), R.data().end(),
48 std::back_inserter(CurrentRecord.Data));
49 BuildingRecord = true;
50 }
51 return Error::success();
52 }
53
54 Error TraceExpander::visit(CustomEventRecordV5 &R) {
55 resetCurrentRecord();
56 if (!IgnoringRecords) {
57 BaseTSC += R.delta();
58 CurrentRecord.TSC = BaseTSC;
59 CurrentRecord.CPU = CPUId;
60 CurrentRecord.PId = PID;
61 CurrentRecord.TId = TID;
62 CurrentRecord.Type = RecordTypes::CUSTOM_EVENT;
63 std::copy(R.data().begin(), R.data().end(),
64 std::back_inserter(CurrentRecord.Data));
65 BuildingRecord = true;
66 }
67 return Error::success();
68 }
69
70 Error TraceExpander::visit(TypedEventRecord &R) {
71 resetCurrentRecord();
72 if (!IgnoringRecords) {
73 BaseTSC += R.delta();
74 CurrentRecord.TSC = BaseTSC;
75 CurrentRecord.CPU = CPUId;
76 CurrentRecord.PId = PID;
77 CurrentRecord.TId = TID;
78 CurrentRecord.RecordType = R.eventType();
79 CurrentRecord.Type = RecordTypes::TYPED_EVENT;
4780 std::copy(R.data().begin(), R.data().end(),
4881 std::back_inserter(CurrentRecord.Data));
4982 BuildingRecord = true;
101101 return Error::success();
102102 }
103103
104 Error FDRTraceWriter::visit(CustomEventRecordV5 &R) {
105 if (auto E = writeMetadata<5u>(OS, R.size(), R.delta()))
106 return E;
107 auto D = R.data();
108 ArrayRef Bytes(D.data(), D.size());
109 OS.write(Bytes);
110 return Error::success();
111 }
112
113 Error FDRTraceWriter::visit(TypedEventRecord &R) {
114 if (auto E = writeMetadata<7u>(OS, R.size(), R.delta(), R.eventType()))
115 return E;
116 auto D = R.data();
117 ArrayRef Bytes(D.data(), D.size());
118 OS.write(Bytes);
119 return Error::success();
120 }
121
104122 Error FDRTraceWriter::visit(CallArgRecord &R) {
105123 return writeMetadata<6u>(OS, R.arg());
106124 }
6262 // Manually advance the offset pointer 16 bytes, after getting a raw memcpy
6363 // from the underlying data.
6464 OffsetPtr += 16;
65 if (FileHeader.Version < 1 || FileHeader.Version > 4)
66 return createStringError(std::make_error_code(std::errc::invalid_argument),
67 "Unsupported XRay file version: %d at offset %d",
68 FileHeader.Version, OffsetPtr);
6965 return std::move(FileHeader);
7066 }
7167
127127 std::make_error_code(std::errc::invalid_argument),
128128 "Missing CPU field at offset %d", OffsetPtr);
129129 }
130
131 assert(OffsetPtr > BeginOffset &&
132 OffsetPtr - BeginOffset <= MetadataRecord::kMetadataBodySize);
133 OffsetPtr += MetadataRecord::kMetadataBodySize - (OffsetPtr - BeginOffset);
134
135 // Next we read in a fixed chunk of data from the given offset.
136 if (!E.isValidOffsetForDataOfSize(OffsetPtr, R.Size))
137 return createStringError(
138 std::make_error_code(std::errc::bad_address),
139 "Cannot read %d bytes of custom event data from offset %d.", R.Size,
140 OffsetPtr);
141
142 std::vector Buffer;
143 Buffer.resize(R.Size);
144 if (E.getU8(&OffsetPtr, Buffer.data(), R.Size) != Buffer.data())
145 return createStringError(
146 std::make_error_code(std::errc::invalid_argument),
147 "Failed reading data into buffer of size %d at offset %d.", R.Size,
148 OffsetPtr);
149 R.Data.assign(Buffer.begin(), Buffer.end());
150 return Error::success();
151 }
152
153 Error RecordInitializer::visit(CustomEventRecordV5 &R) {
154 if (!E.isValidOffsetForDataOfSize(OffsetPtr,
155 MetadataRecord::kMetadataBodySize))
156 return createStringError(std::make_error_code(std::errc::bad_address),
157 "Invalid offset for a custom event record (%d).",
158 OffsetPtr);
159
160 auto BeginOffset = OffsetPtr;
161 auto PreReadOffset = OffsetPtr;
162
163 R.Size = E.getSigned(&OffsetPtr, sizeof(int32_t));
164 if (PreReadOffset == OffsetPtr)
165 return createStringError(
166 std::make_error_code(std::errc::invalid_argument),
167 "Cannot read a custom event record size field offset %d.", OffsetPtr);
168
169 PreReadOffset = OffsetPtr;
170 R.Delta = E.getSigned(&OffsetPtr, sizeof(int32_t));
171 if (PreReadOffset == OffsetPtr)
172 return createStringError(
173 std::make_error_code(std::errc::invalid_argument),
174 "Cannot read a custom event record TSC delta field at offset %d.",
175 OffsetPtr);
176
177 assert(OffsetPtr > BeginOffset &&
178 OffsetPtr - BeginOffset <= MetadataRecord::kMetadataBodySize);
179 OffsetPtr += MetadataRecord::kMetadataBodySize - (OffsetPtr - BeginOffset);
180
181 // Next we read in a fixed chunk of data from the given offset.
182 if (!E.isValidOffsetForDataOfSize(OffsetPtr, R.Size))
183 return createStringError(
184 std::make_error_code(std::errc::bad_address),
185 "Cannot read %d bytes of custom event data from offset %d.", R.Size,
186 OffsetPtr);
187
188 std::vector Buffer;
189 Buffer.resize(R.Size);
190 if (E.getU8(&OffsetPtr, Buffer.data(), R.Size) != Buffer.data())
191 return createStringError(
192 std::make_error_code(std::errc::invalid_argument),
193 "Failed reading data into buffer of size %d at offset %d.", R.Size,
194 OffsetPtr);
195 R.Data.assign(Buffer.begin(), Buffer.end());
196 return Error::success();
197 }
198
199 Error RecordInitializer::visit(TypedEventRecord &R) {
200 if (!E.isValidOffsetForDataOfSize(OffsetPtr,
201 MetadataRecord::kMetadataBodySize))
202 return createStringError(std::make_error_code(std::errc::bad_address),
203 "Invalid offset for a typed event record (%d).",
204 OffsetPtr);
205
206 auto BeginOffset = OffsetPtr;
207 auto PreReadOffset = OffsetPtr;
208
209 R.Size = E.getSigned(&OffsetPtr, sizeof(int32_t));
210 if (PreReadOffset == OffsetPtr)
211 return createStringError(
212 std::make_error_code(std::errc::invalid_argument),
213 "Cannot read a typed event record size field offset %d.", OffsetPtr);
214
215 PreReadOffset = OffsetPtr;
216 R.Delta = E.getSigned(&OffsetPtr, sizeof(int32_t));
217 if (PreReadOffset == OffsetPtr)
218 return createStringError(
219 std::make_error_code(std::errc::invalid_argument),
220 "Cannot read a typed event record TSC delta field at offset %d.",
221 OffsetPtr);
222
223 PreReadOffset = OffsetPtr;
224 R.EventType = E.getU16(&OffsetPtr);
225 if (PreReadOffset == OffsetPtr)
226 return createStringError(
227 std::make_error_code(std::errc::invalid_argument),
228 "Cannot read a typed event record type field at offset %d.", OffsetPtr);
130229
131230 assert(OffsetPtr > BeginOffset &&
132231 OffsetPtr - BeginOffset <= MetadataRecord::kMetadataBodySize);
3737 OS << formatv(
3838 "",
3939 R.tsc(), R.cpu(), R.size(), R.data())
40 << Delim;
41 return Error::success();
42 }
43
44 Error RecordPrinter::visit(CustomEventRecordV5 &R) {
45 OS << formatv("",
46 R.delta(), R.size(), R.data())
47 << Delim;
48 return Error::success();
49 }
50
51 Error RecordPrinter::visit(TypedEventRecord &R) {
52 OS << formatv(
53 "
54 R.delta(), R.eventType(), R.size(), R.data())
4055 << Delim;
4156 return Error::success();
4257 }
246246 /// ThreadBuffer: BufferExtents NewBuffer WallClockTime Pid NewCPUId
247247 /// FunctionSequence
248248 /// EOB: *deprecated*
249 ///
250 /// In Version 4, we make the following changes:
251 ///
252 /// CustomEventRecord now includes the CPU data.
253 ///
254 /// In Version 5, we make the following changes:
255 ///
256 /// CustomEventRecord and TypedEventRecord now use TSC delta encoding similar to
257 /// what FunctionRecord instances use, and we no longer need to include the CPU
258 /// id in the CustomEventRecord.
259 ///
249260 Error loadFDRLog(StringRef Data, bool IsLittleEndian,
250261 XRayFileHeader &FileHeader, std::vector &Records) {
251262
434445 }
435446 break;
436447 case FLIGHT_DATA_RECORDER_FORMAT:
437 if (Version >= 1 && Version <= 4) {
448 if (Version >= 1 && Version <= 5) {
438449 if (auto E = loadFDRLog(DE.getData(), DE.isLittleEndian(), T.FileHeader,
439450 T.Records))
440451 return std::move(E);
3333 .add(1)
3434 .add(RecordTypes::ENTER, 1, 1)
3535 .add(RecordTypes::EXIT, 1, 100)
36 .add(1, 4, "XRAY")
37 .add(1, 4, 2, "XRAY")
3638 .consume();
3739 auto Block1 = LogBuilder()
3840 .add(100)
4143 .add(1)
4244 .add(RecordTypes::ENTER, 1, 1)
4345 .add(RecordTypes::EXIT, 1, 100)
46 .add(1, 4, "XRAY")
47 .add(1, 4, 2, "XRAY")
4448 .consume();
4549 auto Block2 = LogBuilder()
4650 .add(100)
4953 .add(1)
5054 .add(RecordTypes::ENTER, 1, 1)
5155 .add(RecordTypes::EXIT, 1, 100)
56 .add(1, 4, "XRAY")
57 .add(1, 4, 2, "XRAY")
5258 .consume();
5359 BlockIndexer::Index Index;
5460 BlockIndexer Indexer(Index);
9197 .add(1, 2)
9298 .add(RecordTypes::ENTER, 1, 1)
9399 .add(RecordTypes::EXIT, 1, 100)
100 .add(1, 4, "XRAY")
101 .add(1, 4, 2, "XRAY")
94102 .consume();
95103 auto Block1 = LogBuilder()
96104 .add(64)
100108 .add(1, 2)
101109 .add(RecordTypes::ENTER, 1, 1)
102110 .add(RecordTypes::EXIT, 1, 100)
111 .add(1, 4, "XRAY")
112 .add(1, 4, 2, "XRAY")
103113 .consume();
104114 auto Block2 = LogBuilder()
105115 .add(64)
109119 .add(1, 2)
110120 .add(RecordTypes::ENTER, 1, 1)
111121 .add(RecordTypes::EXIT, 1, 100)
122 .add(1, 4, "XRAY")
123 .add(1, 4, 2, "XRAY")
112124 .consume();
113125
114126 // First, index the records in different blocks.