• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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