1 /*
2 * Copyright (C) 2018 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 <algorithm>
18 #include <cstddef>
19 #include <cstdint>
20 #include <cstdlib>
21 #include <cstring>
22 #include <limits>
23 #include <memory>
24 #include <utility>
25
26 #include "perfetto/base/compiler.h"
27 #include "perfetto/base/logging.h"
28 #include "perfetto/public/compiler.h"
29 #include "perfetto/trace_processor/trace_blob_view.h"
30 #include "src/trace_processor/importers/android_bugreport/android_dumpstate_event.h"
31 #include "src/trace_processor/importers/android_bugreport/android_log_event.h"
32 #include "src/trace_processor/importers/art_method/art_method_event.h"
33 #include "src/trace_processor/importers/common/parser_types.h"
34 #include "src/trace_processor/importers/common/trace_parser.h"
35 #include "src/trace_processor/importers/fuchsia/fuchsia_record.h"
36 #include "src/trace_processor/importers/gecko/gecko_event.h"
37 #include "src/trace_processor/importers/instruments/row.h"
38 #include "src/trace_processor/importers/perf/record.h"
39 #include "src/trace_processor/importers/perf_text/perf_text_event.h"
40 #include "src/trace_processor/sorter/trace_sorter.h"
41 #include "src/trace_processor/sorter/trace_token_buffer.h"
42 #include "src/trace_processor/storage/stats.h"
43 #include "src/trace_processor/types/trace_processor_context.h"
44 #include "src/trace_processor/util/bump_allocator.h"
45
46 namespace perfetto::trace_processor {
47
TraceSorter(TraceProcessorContext * context,SortingMode sorting_mode,EventHandling event_handling)48 TraceSorter::TraceSorter(TraceProcessorContext* context,
49 SortingMode sorting_mode,
50 EventHandling event_handling)
51 : sorting_mode_(sorting_mode),
52 storage_(context->storage),
53 event_handling_(event_handling) {
54 AddMachineContext(context);
55 }
56
~TraceSorter()57 TraceSorter::~TraceSorter() {
58 // If trace processor encountered a fatal error, it's possible for some events
59 // to have been pushed without evicting them by pushing to the next stage. Do
60 // that now.
61 for (auto& sorter_data : sorter_data_by_machine_) {
62 for (auto& queue : sorter_data.queues) {
63 for (const auto& event : queue.events_) {
64 ExtractAndDiscardTokenizedObject(event);
65 }
66 }
67 }
68 }
69
SetSortingMode(SortingMode sorting_mode)70 bool TraceSorter::SetSortingMode(SortingMode sorting_mode) {
71 // Early out if the new sorting mode matches the old.
72 if (sorting_mode == sorting_mode_) {
73 return true;
74 }
75 // We cannot transition back to a more relaxed mode after having left that
76 // mode.
77 if (sorting_mode_ != SortingMode::kDefault) {
78 return false;
79 }
80 // We cannot change sorting mode after having extracted one or more events.
81 if (latest_pushed_event_ts_ != std::numeric_limits<int64_t>::min()) {
82 return false;
83 }
84 sorting_mode_ = sorting_mode;
85 return true;
86 }
87
Sort(TraceTokenBuffer & buffer,bool use_slow_sorting)88 void TraceSorter::Queue::Sort(TraceTokenBuffer& buffer, bool use_slow_sorting) {
89 PERFETTO_DCHECK(needs_sorting());
90 PERFETTO_DCHECK(sort_start_idx_ < events_.size());
91
92 // If sort_min_ts_ has been set, it will no long be max_int, and so will be
93 // smaller than max_ts_.
94 PERFETTO_DCHECK(sort_min_ts_ < std::numeric_limits<int64_t>::max());
95
96 // We know that all events between [0, sort_start_idx_] are sorted. Within
97 // this range, perform a bound search and find the iterator for the min
98 // timestamp that broke the monotonicity. Re-sort from there to the end.
99 auto sort_end = events_.begin() + static_cast<ssize_t>(sort_start_idx_);
100 if (use_slow_sorting) {
101 PERFETTO_DCHECK(sort_min_ts_ <= max_ts_);
102 PERFETTO_DCHECK(std::is_sorted(events_.begin(), sort_end,
103 TimestampedEvent::SlowOperatorLess{buffer}));
104 } else {
105 PERFETTO_DCHECK(sort_min_ts_ < max_ts_);
106 PERFETTO_DCHECK(std::is_sorted(events_.begin(), sort_end));
107 }
108 auto sort_begin = std::lower_bound(events_.begin(), sort_end, sort_min_ts_,
109 &TimestampedEvent::Compare);
110 if (use_slow_sorting) {
111 std::sort(sort_begin, events_.end(),
112 TimestampedEvent::SlowOperatorLess{buffer});
113 } else {
114 std::sort(sort_begin, events_.end());
115 }
116 sort_start_idx_ = 0;
117 sort_min_ts_ = 0;
118
119 // At this point |events_| must be fully sorted
120 if (use_slow_sorting) {
121 PERFETTO_DCHECK(std::is_sorted(events_.begin(), events_.end(),
122 TimestampedEvent::SlowOperatorLess{buffer}));
123 } else {
124 PERFETTO_DCHECK(std::is_sorted(events_.begin(), events_.end()));
125 }
126 }
127
128 // Removes all the events in |queues_| that are earlier than the given
129 // packet index and moves them to the next parser stages, respecting global
130 // timestamp order. This function is a "extract min from N sorted queues", with
131 // some little cleverness: we know that events tend to be bursty, so events are
132 // not going to be randomly distributed on the N |queues_|.
133 // Upon each iteration this function finds the first two queues (if any) that
134 // have the oldest events, and extracts events from the 1st until hitting the
135 // min_ts of the 2nd. Imagine the queues are as follows:
136 //
137 // q0 {min_ts: 10 max_ts: 30}
138 // q1 {min_ts:5 max_ts: 35}
139 // q2 {min_ts: 12 max_ts: 40}
140 //
141 // We know that we can extract all events from q1 until we hit ts=10 without
142 // looking at any other queue. After hitting ts=10, we need to re-look to all of
143 // them to figure out the next min-event.
144 // There are more suitable data structures to do this (e.g. keeping a min-heap
145 // to avoid re-scanning all the queues all the times) but doesn't seem worth it.
146 // With Android traces (that have 8 CPUs) this function accounts for ~1-3% cpu
147 // time in a profiler.
SortAndExtractEventsUntilAllocId(BumpAllocator::AllocId limit_alloc_id)148 void TraceSorter::SortAndExtractEventsUntilAllocId(
149 BumpAllocator::AllocId limit_alloc_id) {
150 constexpr int64_t kTsMax = std::numeric_limits<int64_t>::max();
151 for (;;) {
152 size_t min_machine_idx = 0;
153 size_t min_queue_idx = 0; // The index of the queue with the min(ts).
154
155 // The top-2 min(ts) among all queues.
156 // queues_[min_queue_idx].events.timestamp == min_queue_ts[0].
157 int64_t min_queue_ts[2]{kTsMax, kTsMax};
158
159 // This loop identifies the queue which starts with the earliest event and
160 // also remembers the earliest event of the 2nd queue (in min_queue_ts[1]).
161 bool all_queues_empty = true;
162 for (size_t m = 0; m < sorter_data_by_machine_.size(); m++) {
163 TraceSorterData& sorter_data = sorter_data_by_machine_[m];
164 for (size_t i = 0; i < sorter_data.queues.size(); i++) {
165 auto& queue = sorter_data.queues[i];
166 if (queue.events_.empty())
167 continue;
168 PERFETTO_DCHECK(queue.max_ts_ <= append_max_ts_);
169
170 // Checking for |all_queues_empty| is necessary here as in fuzzer cases
171 // we can end up with |int64::max()| as the value here.
172 // See https://crbug.com/oss-fuzz/69164 for an example.
173 if (all_queues_empty || queue.min_ts_ < min_queue_ts[0]) {
174 min_queue_ts[1] = min_queue_ts[0];
175 min_queue_ts[0] = queue.min_ts_;
176 min_queue_idx = i;
177 min_machine_idx = m;
178 } else if (queue.min_ts_ < min_queue_ts[1]) {
179 min_queue_ts[1] = queue.min_ts_;
180 }
181 all_queues_empty = false;
182 }
183 }
184 if (all_queues_empty)
185 break;
186
187 auto& sorter_data = sorter_data_by_machine_[min_machine_idx];
188 auto& queue = sorter_data.queues[min_queue_idx];
189 auto& events = queue.events_;
190 if (queue.needs_sorting())
191 queue.Sort(token_buffer_, use_slow_sorting_);
192 PERFETTO_DCHECK(queue.min_ts_ == events.front().ts);
193
194 // Now that we identified the min-queue, extract all events from it until
195 // we hit either: (1) the min-ts of the 2nd queue or (2) the packet index
196 // limit, whichever comes first.
197 size_t num_extracted = 0;
198 for (auto& event : events) {
199 if (event.alloc_id() >= limit_alloc_id) {
200 break;
201 }
202
203 if (event.ts > min_queue_ts[1]) {
204 // We should never hit this condition on the first extraction as by
205 // the algorithm above (event.ts =) min_queue_ts[0] <= min_queue[1].
206 PERFETTO_DCHECK(num_extracted > 0);
207 break;
208 }
209
210 ++num_extracted;
211 MaybeExtractEvent(min_machine_idx, min_queue_idx, event);
212 } // for (event: events)
213
214 // The earliest event cannot be extracted without going past the limit.
215 if (!num_extracted)
216 break;
217
218 // Now remove the entries from the event buffer and update the queue-local
219 // and global time bounds.
220 events.erase_front(num_extracted);
221 events.shrink_to_fit();
222
223 // Since we likely just removed a bunch of items try to reduce the memory
224 // usage of the token buffer.
225 token_buffer_.FreeMemory();
226
227 // Update the queue timestamps to reflect the bounds after extraction.
228 if (events.empty()) {
229 queue.min_ts_ = kTsMax;
230 queue.max_ts_ = 0;
231 } else {
232 queue.min_ts_ = queue.events_.front().ts;
233 }
234 } // for(;;)
235 }
236
ParseTracePacket(TraceProcessorContext & context,const TimestampedEvent & event)237 void TraceSorter::ParseTracePacket(TraceProcessorContext& context,
238 const TimestampedEvent& event) {
239 TraceTokenBuffer::Id id = GetTokenBufferId(event);
240 switch (event.type()) {
241 case TimestampedEvent::Type::kPerfRecord:
242 context.perf_record_parser->ParsePerfRecord(
243 event.ts, token_buffer_.Extract<perf_importer::Record>(id));
244 return;
245 case TimestampedEvent::Type::kInstrumentsRow:
246 context.instruments_row_parser->ParseInstrumentsRow(
247 event.ts, token_buffer_.Extract<instruments_importer::Row>(id));
248 return;
249 case TimestampedEvent::Type::kTracePacket:
250 context.proto_trace_parser->ParseTracePacket(
251 event.ts, token_buffer_.Extract<TracePacketData>(id));
252 return;
253 case TimestampedEvent::Type::kTrackEvent:
254 context.proto_trace_parser->ParseTrackEvent(
255 event.ts, token_buffer_.Extract<TrackEventData>(id));
256 return;
257 case TimestampedEvent::Type::kFuchsiaRecord:
258 context.fuchsia_record_parser->ParseFuchsiaRecord(
259 event.ts, token_buffer_.Extract<FuchsiaRecord>(id));
260 return;
261 case TimestampedEvent::Type::kJsonValue:
262 context.json_trace_parser->ParseJsonPacket(
263 event.ts, std::move(token_buffer_.Extract<JsonEvent>(id).value));
264 return;
265 case TimestampedEvent::Type::kSpeRecord:
266 context.spe_record_parser->ParseSpeRecord(
267 event.ts, token_buffer_.Extract<TraceBlobView>(id));
268 return;
269 case TimestampedEvent::Type::kSystraceLine:
270 context.json_trace_parser->ParseSystraceLine(
271 event.ts, token_buffer_.Extract<SystraceLine>(id));
272 return;
273 case TimestampedEvent::Type::kAndroidDumpstateEvent:
274 context.android_dumpstate_event_parser->ParseAndroidDumpstateEvent(
275 event.ts, token_buffer_.Extract<AndroidDumpstateEvent>(id));
276 return;
277 case TimestampedEvent::Type::kAndroidLogEvent:
278 context.android_log_event_parser->ParseAndroidLogEvent(
279 event.ts, token_buffer_.Extract<AndroidLogEvent>(id));
280 return;
281 case TimestampedEvent::Type::kLegacyV8CpuProfileEvent:
282 context.json_trace_parser->ParseLegacyV8ProfileEvent(
283 event.ts, token_buffer_.Extract<LegacyV8CpuProfileEvent>(id));
284 return;
285 case TimestampedEvent::Type::kGeckoEvent:
286 context.gecko_trace_parser->ParseGeckoEvent(
287 event.ts, token_buffer_.Extract<gecko_importer::GeckoEvent>(id));
288 return;
289 case TimestampedEvent::Type::kArtMethodEvent:
290 context.art_method_parser->ParseArtMethodEvent(
291 event.ts, token_buffer_.Extract<art_method::ArtMethodEvent>(id));
292 return;
293 case TimestampedEvent::Type::kPerfTextEvent:
294 context.perf_text_parser->ParsePerfTextEvent(
295 event.ts,
296 token_buffer_.Extract<perf_text_importer::PerfTextEvent>(id));
297 return;
298 case TimestampedEvent::Type::kInlineSchedSwitch:
299 case TimestampedEvent::Type::kInlineSchedWaking:
300 case TimestampedEvent::Type::kEtwEvent:
301 case TimestampedEvent::Type::kFtraceEvent:
302 PERFETTO_FATAL("Invalid event type");
303 }
304 PERFETTO_FATAL("For GCC");
305 }
306
ParseEtwPacket(TraceProcessorContext & context,uint32_t cpu,const TimestampedEvent & event)307 void TraceSorter::ParseEtwPacket(TraceProcessorContext& context,
308 uint32_t cpu,
309 const TimestampedEvent& event) {
310 TraceTokenBuffer::Id id = GetTokenBufferId(event);
311 switch (static_cast<TimestampedEvent::Type>(event.event_type)) {
312 case TimestampedEvent::Type::kEtwEvent:
313 context.proto_trace_parser->ParseEtwEvent(
314 cpu, event.ts, token_buffer_.Extract<TracePacketData>(id));
315 return;
316 case TimestampedEvent::Type::kInlineSchedSwitch:
317 case TimestampedEvent::Type::kInlineSchedWaking:
318 case TimestampedEvent::Type::kFtraceEvent:
319 case TimestampedEvent::Type::kTrackEvent:
320 case TimestampedEvent::Type::kSpeRecord:
321 case TimestampedEvent::Type::kSystraceLine:
322 case TimestampedEvent::Type::kTracePacket:
323 case TimestampedEvent::Type::kPerfRecord:
324 case TimestampedEvent::Type::kInstrumentsRow:
325 case TimestampedEvent::Type::kJsonValue:
326 case TimestampedEvent::Type::kFuchsiaRecord:
327 case TimestampedEvent::Type::kAndroidDumpstateEvent:
328 case TimestampedEvent::Type::kAndroidLogEvent:
329 case TimestampedEvent::Type::kLegacyV8CpuProfileEvent:
330 case TimestampedEvent::Type::kGeckoEvent:
331 case TimestampedEvent::Type::kArtMethodEvent:
332 case TimestampedEvent::Type::kPerfTextEvent:
333 PERFETTO_FATAL("Invalid event type");
334 }
335 PERFETTO_FATAL("For GCC");
336 }
337
ParseFtracePacket(TraceProcessorContext & context,uint32_t cpu,const TimestampedEvent & event)338 void TraceSorter::ParseFtracePacket(TraceProcessorContext& context,
339 uint32_t cpu,
340 const TimestampedEvent& event) {
341 TraceTokenBuffer::Id id = GetTokenBufferId(event);
342 switch (static_cast<TimestampedEvent::Type>(event.event_type)) {
343 case TimestampedEvent::Type::kInlineSchedSwitch:
344 context.proto_trace_parser->ParseInlineSchedSwitch(
345 cpu, event.ts, token_buffer_.Extract<InlineSchedSwitch>(id));
346 return;
347 case TimestampedEvent::Type::kInlineSchedWaking:
348 context.proto_trace_parser->ParseInlineSchedWaking(
349 cpu, event.ts, token_buffer_.Extract<InlineSchedWaking>(id));
350 return;
351 case TimestampedEvent::Type::kFtraceEvent:
352 context.proto_trace_parser->ParseFtraceEvent(
353 cpu, event.ts, token_buffer_.Extract<TracePacketData>(id));
354 return;
355 case TimestampedEvent::Type::kEtwEvent:
356 case TimestampedEvent::Type::kTrackEvent:
357 case TimestampedEvent::Type::kSpeRecord:
358 case TimestampedEvent::Type::kSystraceLine:
359 case TimestampedEvent::Type::kTracePacket:
360 case TimestampedEvent::Type::kPerfRecord:
361 case TimestampedEvent::Type::kInstrumentsRow:
362 case TimestampedEvent::Type::kJsonValue:
363 case TimestampedEvent::Type::kFuchsiaRecord:
364 case TimestampedEvent::Type::kAndroidDumpstateEvent:
365 case TimestampedEvent::Type::kAndroidLogEvent:
366 case TimestampedEvent::Type::kLegacyV8CpuProfileEvent:
367 case TimestampedEvent::Type::kGeckoEvent:
368 case TimestampedEvent::Type::kArtMethodEvent:
369 case TimestampedEvent::Type::kPerfTextEvent:
370 PERFETTO_FATAL("Invalid event type");
371 }
372 PERFETTO_FATAL("For GCC");
373 }
374
ExtractAndDiscardTokenizedObject(const TimestampedEvent & event)375 void TraceSorter::ExtractAndDiscardTokenizedObject(
376 const TimestampedEvent& event) {
377 TraceTokenBuffer::Id id = GetTokenBufferId(event);
378 switch (static_cast<TimestampedEvent::Type>(event.event_type)) {
379 case TimestampedEvent::Type::kTracePacket:
380 case TimestampedEvent::Type::kFtraceEvent:
381 case TimestampedEvent::Type::kEtwEvent:
382 base::ignore_result(token_buffer_.Extract<TracePacketData>(id));
383 return;
384 case TimestampedEvent::Type::kTrackEvent:
385 base::ignore_result(token_buffer_.Extract<TrackEventData>(id));
386 return;
387 case TimestampedEvent::Type::kFuchsiaRecord:
388 base::ignore_result(token_buffer_.Extract<FuchsiaRecord>(id));
389 return;
390 case TimestampedEvent::Type::kJsonValue:
391 base::ignore_result(token_buffer_.Extract<JsonEvent>(id));
392 return;
393 case TimestampedEvent::Type::kSpeRecord:
394 base::ignore_result(token_buffer_.Extract<TraceBlobView>(id));
395 return;
396 case TimestampedEvent::Type::kSystraceLine:
397 base::ignore_result(token_buffer_.Extract<SystraceLine>(id));
398 return;
399 case TimestampedEvent::Type::kInlineSchedSwitch:
400 base::ignore_result(token_buffer_.Extract<InlineSchedSwitch>(id));
401 return;
402 case TimestampedEvent::Type::kInlineSchedWaking:
403 base::ignore_result(token_buffer_.Extract<InlineSchedWaking>(id));
404 return;
405 case TimestampedEvent::Type::kPerfRecord:
406 base::ignore_result(token_buffer_.Extract<perf_importer::Record>(id));
407 return;
408 case TimestampedEvent::Type::kInstrumentsRow:
409 base::ignore_result(token_buffer_.Extract<instruments_importer::Row>(id));
410 return;
411 case TimestampedEvent::Type::kAndroidDumpstateEvent:
412 base::ignore_result(token_buffer_.Extract<AndroidDumpstateEvent>(id));
413 return;
414 case TimestampedEvent::Type::kAndroidLogEvent:
415 base::ignore_result(token_buffer_.Extract<AndroidLogEvent>(id));
416 return;
417 case TimestampedEvent::Type::kLegacyV8CpuProfileEvent:
418 base::ignore_result(token_buffer_.Extract<LegacyV8CpuProfileEvent>(id));
419 return;
420 case TimestampedEvent::Type::kGeckoEvent:
421 base::ignore_result(
422 token_buffer_.Extract<gecko_importer::GeckoEvent>(id));
423 return;
424 case TimestampedEvent::Type::kArtMethodEvent:
425 base::ignore_result(
426 token_buffer_.Extract<art_method::ArtMethodEvent>(id));
427 return;
428 case TimestampedEvent::Type::kPerfTextEvent:
429 base::ignore_result(
430 token_buffer_.Extract<perf_text_importer::PerfTextEvent>(id));
431 return;
432 }
433 PERFETTO_FATAL("For GCC");
434 }
435
MaybeExtractEvent(size_t min_machine_idx,size_t queue_idx,const TimestampedEvent & event)436 void TraceSorter::MaybeExtractEvent(size_t min_machine_idx,
437 size_t queue_idx,
438 const TimestampedEvent& event) {
439 auto* machine_context =
440 sorter_data_by_machine_[min_machine_idx].machine_context;
441 int64_t timestamp = event.ts;
442 if (timestamp < latest_pushed_event_ts_) {
443 storage_->IncrementStats(stats::sorter_push_event_out_of_order);
444 ExtractAndDiscardTokenizedObject(event);
445 return;
446 }
447
448 latest_pushed_event_ts_ = std::max(latest_pushed_event_ts_, timestamp);
449
450 if (PERFETTO_UNLIKELY(event_handling_ == EventHandling::kSortAndDrop)) {
451 // Parse* would extract this event and push it to the next stage. Since we
452 // are skipping that, just extract and discard it.
453 ExtractAndDiscardTokenizedObject(event);
454 return;
455 }
456 PERFETTO_DCHECK(event_handling_ == EventHandling::kSortAndPush);
457
458 if (queue_idx == 0) {
459 ParseTracePacket(*machine_context, event);
460 } else {
461 // Ftrace queues start at offset 1. So queues_[1] = cpu[0] and so on.
462 uint32_t cpu = static_cast<uint32_t>(queue_idx - 1);
463 auto event_type = static_cast<TimestampedEvent::Type>(event.event_type);
464
465 if (event_type == TimestampedEvent::Type::kEtwEvent) {
466 ParseEtwPacket(*machine_context, static_cast<uint32_t>(cpu), event);
467 } else {
468 ParseFtracePacket(*machine_context, cpu, event);
469 }
470 }
471 }
472
473 } // namespace perfetto::trace_processor
474