1 /*
2 * Copyright (C) 2024 The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17 #include "src/trace_processor/importers/instruments/instruments_xml_tokenizer.h"
18
19 #include <cctype>
20 #include <map>
21
22 #include <expat.h>
23 #include <stdint.h>
24
25 #include "perfetto/base/status.h"
26 #include "perfetto/ext/base/status_or.h"
27 #include "perfetto/public/fnv1a.h"
28 #include "protos/perfetto/trace/clock_snapshot.pbzero.h"
29 #include "src/trace_processor/importers/common/clock_tracker.h"
30 #include "src/trace_processor/importers/common/stack_profile_tracker.h"
31 #include "src/trace_processor/importers/instruments/row.h"
32 #include "src/trace_processor/importers/instruments/row_data_tracker.h"
33 #include "src/trace_processor/sorter/trace_sorter.h"
34
35 #if !PERFETTO_BUILDFLAG(PERFETTO_TP_INSTRUMENTS)
36 #error \
37 "This file should not be built when enable_perfetto_trace_processor_mac_instruments=false"
38 #endif
39
40 namespace perfetto::trace_processor::instruments_importer {
41
42 namespace {
43
MakeTrimmed(const char * chars,int len)44 std::string MakeTrimmed(const char* chars, int len) {
45 while (len > 0 && std::isspace(*chars)) {
46 chars++;
47 len--;
48 }
49 while (len > 0 && std::isspace(chars[len - 1])) {
50 len--;
51 }
52 return std::string(chars, static_cast<size_t>(len));
53 }
54
55 } // namespace
56
57 // The Instruments XML tokenizer reads instruments traces exported with:
58 //
59 // xctrace export --input /path/to/profile.trace --xpath
60 // '//trace-toc/run/data/table[@schema="os-signpost and
61 // @category="PointsOfInterest"] |
62 // //trace-toc/run/data/table[@schema="time-sample"]'
63 //
64 // This exports two tables:
65 // 1. Points of interest signposts
66 // 2. Time samples
67 //
68 // The first is used for clock synchronization -- perfetto emits signpost events
69 // during tracing which allow synchronization of the xctrace clock (relative to
70 // start of profiling) with the perfetto boottime clock. The second contains
71 // the samples themselves.
72 //
73 // The expected format of the rows in the clock sync table is:
74 //
75 // <row>
76 // <event-time>1234</event-time>
77 // <subsystem>dev.perfetto.clock_sync</subsystem>
78 // <os-log-metadata>
79 // <uint64>5678</uint64>
80 // </os-log-metadata>
81 // </row>
82 //
83 // There may be other rows with other data (from other subsystems), and
84 // additional data in the row (such as thread data and other metadata) -- this
85 // can be safely ignored.
86 //
87 // The expected format of the rows in the time sample table is:
88 //
89 // <row>
90 // <sample-time>1234</sample-time>
91 // <thread fmt="Thread name">
92 // <tid>1</tid>
93 // <process fmt="Process name">
94 // <pid>1<pid>
95 // </process>
96 // </thread>
97 // <core>0</core>
98 // <backtrace>
99 // <frame addr="0x120001234">
100 // <binary
101 // name="MyBinary" UUID="01234567-89ABC-CDEF-0123-456789ABCDEF"
102 // load-addr="0x120000000" path="/path/to/MyBinary.app/MyBinary" />
103 // </frame>
104 // ... more frames ...
105 // </row>
106 //
107 // Here we do not expect other rows with other data -- every row should have a
108 // backtrace, and we use the presence of a backtrace to distinguish time samples
109 // and clock sync eventst. However, there can be additional data in the row
110 // (such as other metadata) -- this can be safely ignored.
111 //
112 // In addition, the XML format annotates elements with ids, to later reuse the
113 // same data by id without needing to repeat its contents. For example, you
114 // might have thread data for a sample:
115 //
116 // <thread id="11" fmt="My Thread"><tid id="12">10</tid>...</thread>
117 //
118 // and subsequent samples on that thread will simply have
119 //
120 // <thread ref="11" />
121 //
122 // This means that most elements have to have their pertinent data cached by id,
123 // including any data store in child elements (which themselves also have to
124 // be cached by id, like the <tid> in the example above).
125 //
126 // This importer reads the XML data using a streaming XML parser, which means
127 // it has to maintain some parsing state (such as the current stack of tags, or
128 // the current element for which we are reading data).
129 class InstrumentsXmlTokenizer::Impl {
130 public:
Impl(TraceProcessorContext * context)131 explicit Impl(TraceProcessorContext* context)
132 : context_(context), data_(RowDataTracker::GetOrCreate(context_)) {
133 parser_ = XML_ParserCreate(nullptr);
134 XML_SetElementHandler(parser_, ElementStart, ElementEnd);
135 XML_SetCharacterDataHandler(parser_, CharacterData);
136 XML_SetUserData(parser_, this);
137
138 const char* subsystem = "dev.perfetto.instruments_clock";
139 clock_ = static_cast<ClockTracker::ClockId>(
140 PerfettoFnv1a(subsystem, strlen(subsystem)) | 0x80000000);
141
142 // Use the above clock if we can, in case there is no other trace and
143 // no clock sync events.
144 context_->clock_tracker->SetTraceTimeClock(clock_);
145 }
~Impl()146 ~Impl() { XML_ParserFree(parser_); }
147
Parse(TraceBlobView view)148 base::Status Parse(TraceBlobView view) {
149 const char* data = reinterpret_cast<const char*>(view.data());
150 size_t length = view.length();
151 while (length > 0) {
152 // Handle the data in chunks of at most 32MB. Don't use std::min, to
153 // be robust against length > 2GB.
154 static constexpr int kMaxChunkSize = 32 * 1024 * 1024;
155 int chunk_size = kMaxChunkSize;
156 if (length < kMaxChunkSize) {
157 chunk_size = static_cast<int>(length);
158 }
159 void* buffer;
160 // Allocate an XML parser buffer -- libexpat insists on reading
161 // from a buffer it owns, rather than a user provided one.
162 while (!(buffer = XML_GetBuffer(parser_, chunk_size))) {
163 // Be robust against XML_GetBuffer failing to allocate the chunk size,
164 // and retry with smaller chunk sizes.
165 chunk_size /= 2;
166 if (chunk_size < 1024) {
167 return base::ErrStatus(
168 "XML parse error at line %lu: failed to allocate buffer\n",
169 XML_GetCurrentLineNumber(parser_));
170 }
171 }
172 // Copy the data into libexpat's buffer, and parse it.
173 memcpy(buffer, data, static_cast<size_t>(chunk_size));
174 length -= static_cast<size_t>(chunk_size);
175 data += chunk_size;
176 if (!XML_ParseBuffer(parser_, chunk_size, false)) {
177 return base::ErrStatus("XML parse error at line %lu: %s\n",
178 XML_GetCurrentLineNumber(parser_),
179 XML_ErrorString(XML_GetErrorCode(parser_)));
180 }
181 }
182 return base::OkStatus();
183 }
184
End()185 base::Status End() {
186 if (!XML_Parse(parser_, nullptr, 0, true)) {
187 return base::ErrStatus("XML parse error at end, line %lu: %s\n",
188 XML_GetCurrentLineNumber(parser_),
189 XML_ErrorString(XML_GetErrorCode(parser_)));
190 }
191 return base::OkStatus();
192 }
193
194 private:
ElementStart(void * data,const char * el,const char ** attr)195 static void ElementStart(void* data, const char* el, const char** attr) {
196 reinterpret_cast<Impl*>(data)->ElementStart(el, attr);
197 }
ElementEnd(void * data,const char * el)198 static void ElementEnd(void* data, const char* el) {
199 reinterpret_cast<Impl*>(data)->ElementEnd(el);
200 }
CharacterData(void * data,const char * chars,int len)201 static void CharacterData(void* data, const char* chars, int len) {
202 reinterpret_cast<Impl*>(data)->CharacterData(chars, len);
203 }
204
ElementStart(const char * el,const char ** attrs)205 void ElementStart(const char* el, const char** attrs) {
206 tag_stack_.emplace_back(el);
207 std::string_view tag_name = tag_stack_.back();
208
209 if (tag_name == "row") {
210 current_row_ = Row{};
211 } else if (tag_name == "thread") {
212 MaybeCachedRef<ThreadId> thread_lookup =
213 GetOrInsertByRef(attrs, thread_ref_to_thread_);
214 if (thread_lookup.is_new) {
215 auto new_thread = data_.NewThread();
216 thread_lookup.ref = new_thread.id;
217
218 for (int i = 2; attrs[i]; i += 2) {
219 std::string key(attrs[i]);
220 if (key == "fmt") {
221 new_thread.ptr->fmt = InternString(attrs[i + 1]);
222 }
223 }
224
225 current_new_thread_ = new_thread.id;
226 }
227 current_row_.thread = thread_lookup.ref;
228 } else if (tag_name == "process") {
229 MaybeCachedRef<ProcessId> process_lookup =
230 GetOrInsertByRef(attrs, process_ref_to_process_);
231 if (process_lookup.is_new) {
232 // Can only be processing a new process when processing a new thread.
233 PERFETTO_DCHECK(current_new_thread_ != kNullId);
234 auto new_process = data_.NewProcess();
235 process_lookup.ref = new_process.id;
236
237 for (int i = 2; attrs[i]; i += 2) {
238 std::string key(attrs[i]);
239 if (key == "fmt") {
240 new_process.ptr->fmt = InternString(attrs[i + 1]);
241 }
242 }
243
244 current_new_process_ = new_process.id;
245 }
246 if (current_new_thread_) {
247 data_.GetThread(current_new_thread_)->process = process_lookup.ref;
248 }
249 } else if (tag_name == "core") {
250 MaybeCachedRef<uint32_t> core_id_lookup =
251 GetOrInsertByRef(attrs, core_ref_to_core_);
252 if (core_id_lookup.is_new) {
253 current_new_core_id_ = &core_id_lookup.ref;
254 } else {
255 current_row_.core_id = core_id_lookup.ref;
256 }
257 } else if (tag_name == "sample-time" || tag_name == "event-time") {
258 // Share time lookup logic between sample times and event times, including
259 // updating the current row's sample time for both.
260 MaybeCachedRef<int64_t> time_lookup =
261 GetOrInsertByRef(attrs, sample_time_ref_to_time_);
262 if (time_lookup.is_new) {
263 current_time_ref_ = &time_lookup.ref;
264 } else {
265 current_row_.timestamp_ = time_lookup.ref;
266 }
267 } else if (tag_name == "subsystem") {
268 MaybeCachedRef<std::string> subsystem_lookup =
269 GetOrInsertByRef(attrs, subsystem_ref_to_subsystem_);
270 current_subsystem_ref_ = &subsystem_lookup.ref;
271 } else if (tag_name == "uint64") {
272 // The only uint64 we care about is the one for the clock sync, which is
273 // expected to contain exactly one uint64 value -- we'll
274 // map all uint64 to a single value and check against the subsystem
275 // when the row is closed.
276 MaybeCachedRef<uint64_t> uint64_lookup =
277 GetOrInsertByRef(attrs, os_log_metadata_or_uint64_ref_to_uint64_);
278 if (uint64_lookup.is_new) {
279 current_uint64_ref_ = &uint64_lookup.ref;
280 } else {
281 if (current_os_log_metadata_uint64_ref_) {
282 // Update the os-log-metadata's uint64 value with this uint64 value.
283 *current_os_log_metadata_uint64_ref_ = uint64_lookup.ref;
284 }
285 }
286 } else if (tag_name == "os-log-metadata") {
287 // The only os-log-metadata we care about is the one with the single
288 // uint64 clock sync value, so also map this to uint64 values with its own
289 // id.
290 MaybeCachedRef<uint64_t> uint64_lookup =
291 GetOrInsertByRef(attrs, os_log_metadata_or_uint64_ref_to_uint64_);
292 current_os_log_metadata_uint64_ref_ = &uint64_lookup.ref;
293 } else if (tag_name == "backtrace") {
294 MaybeCachedRef<BacktraceId> backtrace_lookup =
295 GetOrInsertByRef(attrs, backtrace_ref_to_backtrace_);
296 if (backtrace_lookup.is_new) {
297 backtrace_lookup.ref = data_.NewBacktrace().id;
298 }
299 current_row_.backtrace = backtrace_lookup.ref;
300 } else if (tag_name == "frame") {
301 MaybeCachedRef<BacktraceFrameId> frame_lookup =
302 GetOrInsertByRef(attrs, frame_ref_to_frame_);
303 if (frame_lookup.is_new) {
304 IdPtr<Frame> new_frame = data_.NewFrame();
305 frame_lookup.ref = new_frame.id;
306 for (int i = 2; attrs[i]; i += 2) {
307 std::string key(attrs[i]);
308 if (key == "addr") {
309 new_frame.ptr->addr = strtoll(attrs[i + 1], nullptr, 16);
310 } else if (key == "name") {
311 new_frame.ptr->name = std::string(attrs[i + 1]);
312 }
313 }
314 current_new_frame_ = new_frame.id;
315 }
316 data_.GetBacktrace(current_row_.backtrace)
317 ->frames.push_back(frame_lookup.ref);
318 } else if (tag_name == "binary") {
319 // Can only be processing a binary when processing a new frame.
320 PERFETTO_DCHECK(current_new_frame_ != kNullId);
321
322 MaybeCachedRef<BinaryId> binary_lookup =
323 GetOrInsertByRef(attrs, binary_ref_to_binary_);
324 if (binary_lookup.is_new) {
325 auto new_binary = data_.NewBinary();
326 binary_lookup.ref = new_binary.id;
327 for (int i = 2; attrs[i]; i += 2) {
328 std::string key(attrs[i]);
329 if (key == "path") {
330 new_binary.ptr->path = std::string(attrs[i + 1]);
331 } else if (key == "UUID") {
332 new_binary.ptr->uuid =
333 BuildId::FromHex(base::StringView(attrs[i + 1]));
334 } else if (key == "load-addr") {
335 new_binary.ptr->load_addr = strtoll(attrs[i + 1], nullptr, 16);
336 }
337 }
338 new_binary.ptr->max_addr = new_binary.ptr->load_addr;
339 }
340 PERFETTO_DCHECK(data_.GetFrame(current_new_frame_)->binary == kNullId);
341 data_.GetFrame(current_new_frame_)->binary = binary_lookup.ref;
342 }
343 }
344
ElementEnd(const char * el)345 void ElementEnd(const char* el) {
346 PERFETTO_DCHECK(el == tag_stack_.back());
347 std::string tag_name = std::move(tag_stack_.back());
348 tag_stack_.pop_back();
349
350 if (tag_name == "row") {
351 if (current_row_.backtrace) {
352 // Rows with backtraces are assumed to be time samples.
353 base::StatusOr<int64_t> trace_ts =
354 ToTraceTimestamp(current_row_.timestamp_);
355 if (!trace_ts.ok()) {
356 PERFETTO_DLOG("Skipping timestamp %" PRId64 ", no clock snapshot yet",
357 current_row_.timestamp_);
358 } else {
359 context_->sorter->PushInstrumentsRow(*trace_ts,
360 std::move(current_row_));
361 }
362 } else if (current_subsystem_ref_ != nullptr) {
363 // Rows without backtraces are assumed to be signpost events -- filter
364 // these for `dev.perfetto.clock_sync` events.
365 if (*current_subsystem_ref_ == "dev.perfetto.clock_sync") {
366 PERFETTO_DCHECK(current_os_log_metadata_uint64_ref_ != nullptr);
367 uint64_t clock_sync_timestamp = *current_os_log_metadata_uint64_ref_;
368 if (latest_clock_sync_timestamp_ > clock_sync_timestamp) {
369 PERFETTO_DLOG("Skipping timestamp %" PRId64
370 ", non-monotonic sync deteced",
371 current_row_.timestamp_);
372 } else {
373 latest_clock_sync_timestamp_ = clock_sync_timestamp;
374 auto status = context_->clock_tracker->AddSnapshot(
375 {{clock_, current_row_.timestamp_},
376 {protos::pbzero::ClockSnapshot::Clock::BOOTTIME,
377 static_cast<int64_t>(latest_clock_sync_timestamp_)}});
378 if (!status.ok()) {
379 PERFETTO_FATAL("Error adding clock snapshot: %s",
380 status.status().c_message());
381 }
382 }
383 }
384 current_subsystem_ref_ = nullptr;
385 current_os_log_metadata_uint64_ref_ = nullptr;
386 current_uint64_ref_ = nullptr;
387 }
388 } else if (current_new_frame_ != kNullId && tag_name == "frame") {
389 Frame* frame = data_.GetFrame(current_new_frame_);
390 if (frame->binary) {
391 Binary* binary = data_.GetBinary(frame->binary);
392 // We don't know what the binary's mapping end is, but we know that the
393 // current frame is inside of it, so use that.
394 PERFETTO_DCHECK(frame->addr > binary->load_addr);
395 if (frame->addr > binary->max_addr) {
396 binary->max_addr = frame->addr;
397 }
398 }
399 current_new_frame_ = kNullId;
400 } else if (current_new_thread_ != kNullId && tag_name == "thread") {
401 current_new_thread_ = kNullId;
402 } else if (current_new_process_ != kNullId && tag_name == "process") {
403 current_new_process_ = kNullId;
404 } else if (current_new_core_id_ != nullptr && tag_name == "core") {
405 current_new_core_id_ = nullptr;
406 }
407 }
408
CharacterData(const char * chars,int len)409 void CharacterData(const char* chars, int len) {
410 std::string_view tag_name = tag_stack_.back();
411 if (current_time_ref_ != nullptr &&
412 (tag_name == "sample-time" || tag_name == "event-time")) {
413 std::string s = MakeTrimmed(chars, len);
414 current_row_.timestamp_ = *current_time_ref_ = stoll(s);
415 current_time_ref_ = nullptr;
416 } else if (current_new_thread_ != kNullId && tag_name == "tid") {
417 std::string s = MakeTrimmed(chars, len);
418 data_.GetThread(current_new_thread_)->tid = stoi(s);
419 } else if (current_new_process_ != kNullId && tag_name == "pid") {
420 std::string s = MakeTrimmed(chars, len);
421 data_.GetProcess(current_new_process_)->pid = stoi(s);
422 } else if (current_new_core_id_ != nullptr && tag_name == "core") {
423 std::string s = MakeTrimmed(chars, len);
424 *current_new_core_id_ = static_cast<uint32_t>(stoul(s));
425 } else if (current_subsystem_ref_ != nullptr && tag_name == "subsystem") {
426 std::string s = MakeTrimmed(chars, len);
427 *current_subsystem_ref_ = s;
428 } else if (current_uint64_ref_ != nullptr &&
429 current_os_log_metadata_uint64_ref_ != nullptr &&
430 tag_name == "uint64") {
431 std::string s = MakeTrimmed(chars, len);
432 *current_os_log_metadata_uint64_ref_ = *current_uint64_ref_ = stoull(s);
433 }
434 }
435
ToTraceTimestamp(int64_t time)436 base::StatusOr<int64_t> ToTraceTimestamp(int64_t time) {
437 base::StatusOr<int64_t> trace_ts =
438 context_->clock_tracker->ToTraceTime(clock_, time);
439
440 if (PERFETTO_LIKELY(trace_ts.ok())) {
441 latest_timestamp_ = std::max(latest_timestamp_, *trace_ts);
442 }
443
444 return trace_ts;
445 }
446
InternString(base::StringView string_view)447 StringId InternString(base::StringView string_view) {
448 return context_->storage->InternString(string_view);
449 }
InternString(const char * string)450 StringId InternString(const char* string) {
451 return InternString(base::StringView(string));
452 }
InternString(const char * data,size_t len)453 StringId InternString(const char* data, size_t len) {
454 return InternString(base::StringView(data, len));
455 }
456
457 template <typename Value>
458 struct MaybeCachedRef {
459 Value& ref;
460 bool is_new;
461 };
462 // Implement the element caching mechanism. Either insert an element by its
463 // id attribute into the given map, or look up the element in the cache by its
464 // ref attribute. The returned value is a reference into the map, to allow
465 // in-place modification.
466 template <typename Value>
GetOrInsertByRef(const char ** attrs,std::map<unsigned long,Value> & map)467 MaybeCachedRef<Value> GetOrInsertByRef(const char** attrs,
468 std::map<unsigned long, Value>& map) {
469 PERFETTO_DCHECK(attrs[0] != nullptr);
470 PERFETTO_DCHECK(attrs[1] != nullptr);
471 const char* key = attrs[0];
472 // The id or ref attribute has to be the first attribute on the element.
473 PERFETTO_DCHECK(strcmp(key, "ref") == 0 || strcmp(key, "id") == 0);
474 unsigned long id = strtoul(attrs[1], nullptr, 10);
475 // If the first attribute key is `id`, then this is a new entry in the
476 // cache -- otherwise, for lookup by ref, it should already exist.
477 bool is_new = strcmp(key, "id") == 0;
478 PERFETTO_DCHECK(is_new == (map.find(id) == map.end()));
479 return {map[id], is_new};
480 }
481
482 TraceProcessorContext* context_;
483 RowDataTracker& data_;
484
485 XML_Parser parser_;
486 std::vector<std::string> tag_stack_;
487 int64_t latest_timestamp_;
488
489 // These maps store the cached element data. These currently have to be
490 // std::map, because they require pointer stability under insertion,
491 // as the various `current_foo_` pointers below point directly into the map
492 // data.
493 //
494 // TODO(leszeks): Relax this pointer stability requirement, and use
495 // base::FlatHashMap.
496 // TODO(leszeks): Consider merging these into a single map from ID to
497 // a variant (or similar).
498 std::map<unsigned long, ThreadId> thread_ref_to_thread_;
499 std::map<unsigned long, ProcessId> process_ref_to_process_;
500 std::map<unsigned long, uint32_t> core_ref_to_core_;
501 std::map<unsigned long, int64_t> sample_time_ref_to_time_;
502 std::map<unsigned long, BinaryId> binary_ref_to_binary_;
503 std::map<unsigned long, BacktraceFrameId> frame_ref_to_frame_;
504 std::map<unsigned long, BacktraceId> backtrace_ref_to_backtrace_;
505 std::map<unsigned long, std::string> subsystem_ref_to_subsystem_;
506 std::map<unsigned long, uint64_t> os_log_metadata_or_uint64_ref_to_uint64_;
507
508 Row current_row_;
509 int64_t* current_time_ref_ = nullptr;
510 ThreadId current_new_thread_ = kNullId;
511 ProcessId current_new_process_ = kNullId;
512 uint32_t* current_new_core_id_ = nullptr;
513 BacktraceFrameId current_new_frame_ = kNullId;
514
515 ClockTracker::ClockId clock_;
516 std::string* current_subsystem_ref_ = nullptr;
517 uint64_t* current_os_log_metadata_uint64_ref_ = nullptr;
518 uint64_t* current_uint64_ref_ = nullptr;
519 uint64_t latest_clock_sync_timestamp_ = 0;
520 };
521
InstrumentsXmlTokenizer(TraceProcessorContext * context)522 InstrumentsXmlTokenizer::InstrumentsXmlTokenizer(TraceProcessorContext* context)
523 : impl_(new Impl(context)) {}
~InstrumentsXmlTokenizer()524 InstrumentsXmlTokenizer::~InstrumentsXmlTokenizer() {
525 delete impl_;
526 }
527
Parse(TraceBlobView view)528 base::Status InstrumentsXmlTokenizer::Parse(TraceBlobView view) {
529 return impl_->Parse(std::move(view));
530 }
531
NotifyEndOfFile()532 [[nodiscard]] base::Status InstrumentsXmlTokenizer::NotifyEndOfFile() {
533 return impl_->End();
534 }
535
536 } // namespace perfetto::trace_processor::instruments_importer
537