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 "src/trace_processor/importers/proto/proto_trace_reader.h"
18
19 #include "perfetto/base/logging.h"
20 #include "perfetto/ext/base/string_view.h"
21 #include "perfetto/protozero/scattered_heap_buffer.h"
22 #include "perfetto/trace_processor/trace_blob.h"
23 #include "src/trace_processor/importers/common/args_tracker.h"
24 #include "src/trace_processor/importers/common/args_translation_table.h"
25 #include "src/trace_processor/importers/common/clock_tracker.h"
26 #include "src/trace_processor/importers/common/event_tracker.h"
27 #include "src/trace_processor/importers/common/flow_tracker.h"
28 #include "src/trace_processor/importers/common/metadata_tracker.h"
29 #include "src/trace_processor/importers/common/process_tracker.h"
30 #include "src/trace_processor/importers/common/slice_tracker.h"
31 #include "src/trace_processor/importers/common/track_tracker.h"
32 #include "src/trace_processor/importers/ftrace/sched_event_tracker.h"
33 #include "src/trace_processor/importers/proto/additional_modules.h"
34 #include "src/trace_processor/importers/proto/default_modules.h"
35 #include "src/trace_processor/importers/proto/proto_trace_parser.h"
36 #include "src/trace_processor/importers/proto/stack_profile_tracker.h"
37 #include "src/trace_processor/sorter/trace_sorter.h"
38 #include "src/trace_processor/storage/metadata.h"
39 #include "src/trace_processor/storage/trace_storage.h"
40 #include "src/trace_processor/util/descriptors.h"
41 #include "test/gtest_and_gmock.h"
42
43 #include "protos/perfetto/common/builtin_clock.pbzero.h"
44 #include "protos/perfetto/common/sys_stats_counters.pbzero.h"
45 #include "protos/perfetto/config/trace_config.pbzero.h"
46 #include "protos/perfetto/trace/android/packages_list.pbzero.h"
47 #include "protos/perfetto/trace/chrome/chrome_benchmark_metadata.pbzero.h"
48 #include "protos/perfetto/trace/chrome/chrome_trace_event.pbzero.h"
49 #include "protos/perfetto/trace/clock_snapshot.pbzero.h"
50 #include "protos/perfetto/trace/ftrace/ftrace.pbzero.h"
51 #include "protos/perfetto/trace/ftrace/ftrace_event.pbzero.h"
52 #include "protos/perfetto/trace/ftrace/ftrace_event_bundle.pbzero.h"
53 #include "protos/perfetto/trace/ftrace/generic.pbzero.h"
54 #include "protos/perfetto/trace/ftrace/power.pbzero.h"
55 #include "protos/perfetto/trace/ftrace/sched.pbzero.h"
56 #include "protos/perfetto/trace/ftrace/task.pbzero.h"
57 #include "protos/perfetto/trace/interned_data/interned_data.pbzero.h"
58 #include "protos/perfetto/trace/profiling/profile_packet.pbzero.h"
59 #include "protos/perfetto/trace/ps/process_tree.pbzero.h"
60 #include "protos/perfetto/trace/sys_stats/sys_stats.pbzero.h"
61 #include "protos/perfetto/trace/trace.pbzero.h"
62 #include "protos/perfetto/trace/trace_packet.pbzero.h"
63 #include "protos/perfetto/trace/trace_uuid.pbzero.h"
64 #include "protos/perfetto/trace/track_event/chrome_thread_descriptor.pbzero.h"
65 #include "protos/perfetto/trace/track_event/counter_descriptor.pbzero.h"
66 #include "protos/perfetto/trace/track_event/debug_annotation.pbzero.h"
67 #include "protos/perfetto/trace/track_event/log_message.pbzero.h"
68 #include "protos/perfetto/trace/track_event/process_descriptor.pbzero.h"
69 #include "protos/perfetto/trace/track_event/source_location.pbzero.h"
70 #include "protos/perfetto/trace/track_event/task_execution.pbzero.h"
71 #include "protos/perfetto/trace/track_event/thread_descriptor.pbzero.h"
72 #include "protos/perfetto/trace/track_event/track_descriptor.pbzero.h"
73 #include "protos/perfetto/trace/track_event/track_event.pbzero.h"
74
75 namespace perfetto {
76 namespace trace_processor {
77 namespace {
78
79 using ::testing::_;
80 using ::testing::Args;
81 using ::testing::AtLeast;
82 using ::testing::DoAll;
83 using ::testing::ElementsAreArray;
84 using ::testing::Eq;
85 using ::testing::HasSubstr;
86 using ::testing::IgnoreResult;
87 using ::testing::InSequence;
88 using ::testing::Invoke;
89 using ::testing::InvokeArgument;
90 using ::testing::NiceMock;
91 using ::testing::Pointwise;
92 using ::testing::Return;
93 using ::testing::ReturnRef;
94 using ::testing::UnorderedElementsAreArray;
95
96 namespace {
97 MATCHER_P(DoubleEq, exp, "Double matcher that satisfies -Wfloat-equal") {
98 // The IEEE standard says that any comparison operation involving
99 // a NAN must return false.
100 double d_exp = exp;
101 double d_arg = arg;
102 if (isnan(d_exp) || isnan(d_arg))
103 return false;
104 return fabs(d_arg - d_exp) < 1e-128;
105 }
106 } // namespace
107
108 class MockSchedEventTracker : public SchedEventTracker {
109 public:
MockSchedEventTracker(TraceProcessorContext * context)110 explicit MockSchedEventTracker(TraceProcessorContext* context)
111 : SchedEventTracker(context) {}
112
113 MOCK_METHOD(void,
114 PushSchedSwitch,
115 (uint32_t cpu,
116 int64_t timestamp,
117 uint32_t prev_pid,
118 base::StringView prev_comm,
119 int32_t prev_prio,
120 int64_t prev_state,
121 uint32_t next_pid,
122 base::StringView next_comm,
123 int32_t next_prio),
124 (override));
125 };
126
127 class MockEventTracker : public EventTracker {
128 public:
MockEventTracker(TraceProcessorContext * context)129 explicit MockEventTracker(TraceProcessorContext* context)
130 : EventTracker(context) {}
131 ~MockEventTracker() override = default;
132
133 MOCK_METHOD(void,
134 PushSchedSwitch,
135 (uint32_t cpu,
136 int64_t timestamp,
137 uint32_t prev_pid,
138 base::StringView prev_comm,
139 int32_t prev_prio,
140 int64_t prev_state,
141 uint32_t next_pid,
142 base::StringView next_comm,
143 int32_t next_prio));
144
145 MOCK_METHOD(std::optional<CounterId>,
146 PushCounter,
147 (int64_t timestamp, double value, TrackId track_id),
148 (override));
149 };
150
151 class MockProcessTracker : public ProcessTracker {
152 public:
MockProcessTracker(TraceProcessorContext * context)153 explicit MockProcessTracker(TraceProcessorContext* context)
154 : ProcessTracker(context) {}
155
156 MOCK_METHOD(UniquePid,
157 SetProcessMetadata,
158 (uint32_t pid,
159 std::optional<uint32_t> ppid,
160 base::StringView process_name,
161 base::StringView cmdline),
162 (override));
163
164 MOCK_METHOD(UniqueTid,
165 UpdateThreadName,
166 (uint32_t tid,
167 StringId thread_name_id,
168 ThreadNamePriority priority),
169 (override));
170 MOCK_METHOD(void,
171 UpdateThreadNameByUtid,
172 (UniqueTid utid,
173 StringId thread_name_id,
174 ThreadNamePriority priority),
175 (override));
176 MOCK_METHOD(UniqueTid,
177 UpdateThread,
178 (uint32_t tid, uint32_t tgid),
179 (override));
180
181 MOCK_METHOD(UniquePid, GetOrCreateProcess, (uint32_t pid), (override));
182 MOCK_METHOD(void,
183 SetProcessNameIfUnset,
184 (UniquePid upid, StringId process_name_id),
185 (override));
186 };
187
188 class MockBoundInserter : public ArgsTracker::BoundInserter {
189 public:
MockBoundInserter()190 MockBoundInserter()
191 : ArgsTracker::BoundInserter(&tracker_, nullptr, 0u), tracker_(nullptr) {
192 ON_CALL(*this, AddArg(_, _, _, _)).WillByDefault(ReturnRef(*this));
193 }
194
195 MOCK_METHOD(ArgsTracker::BoundInserter&,
196 AddArg,
197 (StringId flat_key,
198 StringId key,
199 Variadic v,
200 ArgsTracker::UpdatePolicy update_policy),
201 (override));
202
203 private:
204 ArgsTracker tracker_;
205 };
206
207 class MockSliceTracker : public SliceTracker {
208 public:
MockSliceTracker(TraceProcessorContext * context)209 explicit MockSliceTracker(TraceProcessorContext* context)
210 : SliceTracker(context) {}
211
212 MOCK_METHOD(std::optional<SliceId>,
213 Begin,
214 (int64_t timestamp,
215 TrackId track_id,
216 StringId cat,
217 StringId name,
218 SetArgsCallback args_callback),
219 (override));
220 MOCK_METHOD(std::optional<SliceId>,
221 End,
222 (int64_t timestamp,
223 TrackId track_id,
224 StringId cat,
225 StringId name,
226 SetArgsCallback args_callback),
227 (override));
228 MOCK_METHOD(std::optional<SliceId>,
229 Scoped,
230 (int64_t timestamp,
231 TrackId track_id,
232 StringId cat,
233 StringId name,
234 int64_t duration,
235 SetArgsCallback args_callback),
236 (override));
237 MOCK_METHOD(std::optional<SliceId>,
238 StartSlice,
239 (int64_t timestamp,
240 TrackId track_id,
241 SetArgsCallback args_callback,
242 std::function<SliceId()> inserter),
243 (override));
244 };
245
246 class ProtoTraceParserTest : public ::testing::Test {
247 public:
ProtoTraceParserTest()248 ProtoTraceParserTest() {
249 storage_ = new TraceStorage();
250 context_.storage.reset(storage_);
251 context_.track_tracker.reset(new TrackTracker(&context_));
252 context_.global_args_tracker.reset(
253 new GlobalArgsTracker(context_.storage.get()));
254 context_.global_stack_profile_tracker.reset(
255 new GlobalStackProfileTracker());
256 context_.args_tracker.reset(new ArgsTracker(&context_));
257 context_.args_translation_table.reset(new ArgsTranslationTable(storage_));
258 context_.metadata_tracker.reset(
259 new MetadataTracker(context_.storage.get()));
260 event_ = new MockEventTracker(&context_);
261 context_.event_tracker.reset(event_);
262 sched_ = new MockSchedEventTracker(&context_);
263 context_.sched_tracker.reset(sched_);
264 process_ = new NiceMock<MockProcessTracker>(&context_);
265 context_.process_tracker.reset(process_);
266 slice_ = new NiceMock<MockSliceTracker>(&context_);
267 context_.slice_tracker.reset(slice_);
268 context_.slice_translation_table.reset(new SliceTranslationTable(storage_));
269 clock_ = new ClockTracker(&context_);
270 context_.clock_tracker.reset(clock_);
271 context_.flow_tracker.reset(new FlowTracker(&context_));
272 context_.sorter.reset(new TraceSorter(&context_, CreateParser(),
273 TraceSorter::SortingMode::kFullSort));
274 context_.descriptor_pool_.reset(new DescriptorPool());
275
276 RegisterDefaultModules(&context_);
277 RegisterAdditionalModules(&context_);
278 }
279
ResetTraceBuffers()280 void ResetTraceBuffers() { trace_.Reset(); }
281
SetUp()282 void SetUp() override { ResetTraceBuffers(); }
283
Tokenize()284 util::Status Tokenize() {
285 trace_->Finalize();
286 std::vector<uint8_t> trace_bytes = trace_.SerializeAsArray();
287 std::unique_ptr<uint8_t[]> raw_trace(new uint8_t[trace_bytes.size()]);
288 memcpy(raw_trace.get(), trace_bytes.data(), trace_bytes.size());
289 context_.chunk_reader.reset(new ProtoTraceReader(&context_));
290 auto status = context_.chunk_reader->Parse(TraceBlobView(
291 TraceBlob::TakeOwnership(std::move(raw_trace), trace_bytes.size())));
292
293 ResetTraceBuffers();
294 return status;
295 }
296
HasArg(ArgSetId set_id,StringId key_id,Variadic value)297 bool HasArg(ArgSetId set_id, StringId key_id, Variadic value) {
298 const auto& args = storage_->arg_table();
299 RowMap rm = args.FilterToRowMap({args.arg_set_id().eq(set_id)});
300 bool found = false;
301 for (auto it = rm.IterateRows(); it; it.Next()) {
302 if (args.key()[it.index()] == key_id) {
303 EXPECT_EQ(args.flat_key()[it.index()], key_id);
304 if (storage_->GetArgValue(it.index()) == value) {
305 found = true;
306 break;
307 }
308 }
309 }
310 return found;
311 }
312
313 protected:
CreateParser()314 std::unique_ptr<TraceParser> CreateParser() {
315 return std::unique_ptr<TraceParser>(new ProtoTraceParser(&context_));
316 }
317
318 protozero::HeapBuffered<protos::pbzero::Trace> trace_;
319 TraceProcessorContext context_;
320 MockEventTracker* event_;
321 MockSchedEventTracker* sched_;
322 MockProcessTracker* process_;
323 MockSliceTracker* slice_;
324 ClockTracker* clock_;
325 TraceStorage* storage_;
326 };
327
328 // TODO(eseckler): Refactor these into a new file for ftrace tests.
329
TEST_F(ProtoTraceParserTest,LoadSingleEvent)330 TEST_F(ProtoTraceParserTest, LoadSingleEvent) {
331 auto* bundle = trace_->add_packet()->set_ftrace_events();
332 bundle->set_cpu(10);
333
334 auto* event = bundle->add_event();
335 event->set_timestamp(1000);
336 event->set_pid(12);
337
338 static const char kProc1Name[] = "proc1";
339 static const char kProc2Name[] = "proc2";
340 auto* sched_switch = event->set_sched_switch();
341 sched_switch->set_prev_pid(10);
342 sched_switch->set_prev_comm(kProc2Name);
343 sched_switch->set_prev_prio(256);
344 sched_switch->set_prev_state(32);
345 sched_switch->set_next_comm(kProc1Name);
346 sched_switch->set_next_pid(100);
347 sched_switch->set_next_prio(1024);
348
349 EXPECT_CALL(*sched_,
350 PushSchedSwitch(10, 1000, 10, base::StringView(kProc2Name), 256,
351 32, 100, base::StringView(kProc1Name), 1024));
352 Tokenize();
353 context_.sorter->ExtractEventsForced();
354 }
355
TEST_F(ProtoTraceParserTest,LoadEventsIntoRaw)356 TEST_F(ProtoTraceParserTest, LoadEventsIntoRaw) {
357 auto* bundle = trace_->add_packet()->set_ftrace_events();
358 bundle->set_cpu(10);
359
360 // This event is unknown and will only appear in
361 // raw events table.
362 auto* event = bundle->add_event();
363 event->set_timestamp(1000);
364 event->set_pid(12);
365 auto* task = event->set_task_newtask();
366 task->set_pid(123);
367 static const char task_newtask[] = "task_newtask";
368 task->set_comm(task_newtask);
369 task->set_clone_flags(12);
370 task->set_oom_score_adj(15);
371
372 // This event has specific parsing logic, but will
373 // also appear in raw events table.
374 event = bundle->add_event();
375 event->set_timestamp(1001);
376 event->set_pid(12);
377 auto* print = event->set_print();
378 print->set_ip(20);
379 static const char buf_value[] = "This is a print event";
380 print->set_buf(buf_value);
381
382 EXPECT_CALL(*process_, GetOrCreateProcess(123));
383
384 Tokenize();
385 context_.sorter->ExtractEventsForced();
386
387 const auto& raw = context_.storage->raw_table();
388 ASSERT_EQ(raw.row_count(), 2u);
389 const auto& args = context_.storage->arg_table();
390 ASSERT_EQ(args.row_count(), 6u);
391 // Order is by row and then by StringIds.
392 ASSERT_EQ(args.key()[0], context_.storage->InternString("comm"));
393 ASSERT_EQ(args.key()[1], context_.storage->InternString("pid"));
394 ASSERT_EQ(args.key()[2], context_.storage->InternString("oom_score_adj"));
395 ASSERT_EQ(args.key()[3], context_.storage->InternString("clone_flags"));
396 ASSERT_EQ(args.key()[4], context_.storage->InternString("ip"));
397 ASSERT_EQ(args.key()[5], context_.storage->InternString("buf"));
398 ASSERT_STREQ(args.string_value().GetString(0).c_str(), task_newtask);
399 ASSERT_EQ(args.int_value()[1], 123);
400 ASSERT_EQ(args.int_value()[2], 15);
401 ASSERT_EQ(args.int_value()[3], 12);
402 ASSERT_EQ(args.int_value()[4], 20);
403 ASSERT_STREQ(args.string_value().GetString(5).c_str(), buf_value);
404
405 // TODO(hjd): Add test ftrace event with all field types
406 // and test here.
407 }
408
TEST_F(ProtoTraceParserTest,LoadGenericFtrace)409 TEST_F(ProtoTraceParserTest, LoadGenericFtrace) {
410 auto* packet = trace_->add_packet();
411 packet->set_timestamp(100);
412
413 auto* bundle = packet->set_ftrace_events();
414 bundle->set_cpu(4);
415
416 auto* ftrace = bundle->add_event();
417 ftrace->set_timestamp(100);
418 ftrace->set_pid(10);
419
420 auto* generic = ftrace->set_generic();
421 generic->set_event_name("Test");
422
423 auto* field = generic->add_field();
424 field->set_name("meta1");
425 field->set_str_value("value1");
426
427 field = generic->add_field();
428 field->set_name("meta2");
429 field->set_int_value(-2);
430
431 field = generic->add_field();
432 field->set_name("meta3");
433 field->set_uint_value(3);
434
435 Tokenize();
436 context_.sorter->ExtractEventsForced();
437
438 const auto& raw = storage_->raw_table();
439
440 ASSERT_EQ(raw.row_count(), 1u);
441 ASSERT_EQ(raw.ts()[raw.row_count() - 1], 100);
442 ASSERT_EQ(storage_->thread_table().tid()[raw.utid()[raw.row_count() - 1]],
443 10u);
444 ASSERT_EQ(raw.name().GetString(raw.row_count() - 1), "Test");
445
446 auto set_id = raw.arg_set_id()[raw.row_count() - 1];
447
448 const auto& args = storage_->arg_table();
449 RowMap rm = args.FilterToRowMap({args.arg_set_id().eq(set_id)});
450
451 auto row = rm.Get(0);
452
453 ASSERT_EQ(args.key().GetString(row), "meta1");
454 ASSERT_EQ(args.string_value().GetString(row++), "value1");
455
456 ASSERT_EQ(args.key().GetString(row), "meta2");
457 ASSERT_EQ(args.int_value()[row++], -2);
458
459 ASSERT_EQ(args.key().GetString(row), "meta3");
460 ASSERT_EQ(args.int_value()[row++], 3);
461 }
462
TEST_F(ProtoTraceParserTest,LoadMultipleEvents)463 TEST_F(ProtoTraceParserTest, LoadMultipleEvents) {
464 auto* bundle = trace_->add_packet()->set_ftrace_events();
465 bundle->set_cpu(10);
466
467 auto* event = bundle->add_event();
468 event->set_timestamp(1000);
469 event->set_pid(12);
470
471 static const char kProcName1[] = "proc1";
472 static const char kProcName2[] = "proc2";
473 auto* sched_switch = event->set_sched_switch();
474 sched_switch->set_prev_pid(10);
475 sched_switch->set_prev_comm(kProcName2);
476 sched_switch->set_prev_prio(256);
477 sched_switch->set_prev_state(32);
478 sched_switch->set_next_comm(kProcName1);
479 sched_switch->set_next_pid(100);
480 sched_switch->set_next_prio(1024);
481
482 event = bundle->add_event();
483 event->set_timestamp(1001);
484 event->set_pid(12);
485
486 sched_switch = event->set_sched_switch();
487 sched_switch->set_prev_pid(100);
488 sched_switch->set_prev_comm(kProcName1);
489 sched_switch->set_prev_prio(256);
490 sched_switch->set_prev_state(32);
491 sched_switch->set_next_comm(kProcName2);
492 sched_switch->set_next_pid(10);
493 sched_switch->set_next_prio(512);
494
495 EXPECT_CALL(*sched_,
496 PushSchedSwitch(10, 1000, 10, base::StringView(kProcName2), 256,
497 32, 100, base::StringView(kProcName1), 1024));
498
499 EXPECT_CALL(*sched_,
500 PushSchedSwitch(10, 1001, 100, base::StringView(kProcName1), 256,
501 32, 10, base::StringView(kProcName2), 512));
502
503 Tokenize();
504 context_.sorter->ExtractEventsForced();
505 }
506
TEST_F(ProtoTraceParserTest,LoadMultiplePackets)507 TEST_F(ProtoTraceParserTest, LoadMultiplePackets) {
508 auto* bundle = trace_->add_packet()->set_ftrace_events();
509 bundle->set_cpu(10);
510
511 auto* event = bundle->add_event();
512 event->set_timestamp(1000);
513 event->set_pid(12);
514
515 static const char kProcName1[] = "proc1";
516 static const char kProcName2[] = "proc2";
517 auto* sched_switch = event->set_sched_switch();
518 sched_switch->set_prev_pid(10);
519 sched_switch->set_prev_comm(kProcName2);
520 sched_switch->set_prev_prio(256);
521 sched_switch->set_prev_state(32);
522 sched_switch->set_next_comm(kProcName1);
523 sched_switch->set_next_pid(100);
524 sched_switch->set_next_prio(1024);
525
526 bundle = trace_->add_packet()->set_ftrace_events();
527 bundle->set_cpu(10);
528
529 event = bundle->add_event();
530 event->set_timestamp(1001);
531 event->set_pid(12);
532
533 sched_switch = event->set_sched_switch();
534 sched_switch->set_prev_pid(100);
535 sched_switch->set_prev_comm(kProcName1);
536 sched_switch->set_prev_prio(256);
537 sched_switch->set_prev_state(32);
538 sched_switch->set_next_comm(kProcName2);
539 sched_switch->set_next_pid(10);
540 sched_switch->set_next_prio(512);
541
542 EXPECT_CALL(*sched_,
543 PushSchedSwitch(10, 1000, 10, base::StringView(kProcName2), 256,
544 32, 100, base::StringView(kProcName1), 1024));
545
546 EXPECT_CALL(*sched_,
547 PushSchedSwitch(10, 1001, 100, base::StringView(kProcName1), 256,
548 32, 10, base::StringView(kProcName2), 512));
549 Tokenize();
550 context_.sorter->ExtractEventsForced();
551 }
552
TEST_F(ProtoTraceParserTest,RepeatedLoadSinglePacket)553 TEST_F(ProtoTraceParserTest, RepeatedLoadSinglePacket) {
554 auto* bundle = trace_->add_packet()->set_ftrace_events();
555 bundle->set_cpu(10);
556 auto* event = bundle->add_event();
557 event->set_timestamp(1000);
558 event->set_pid(12);
559 static const char kProcName1[] = "proc1";
560 static const char kProcName2[] = "proc2";
561 auto* sched_switch = event->set_sched_switch();
562 sched_switch->set_prev_pid(10);
563 sched_switch->set_prev_comm(kProcName2);
564 sched_switch->set_prev_prio(256);
565 sched_switch->set_prev_state(32);
566 sched_switch->set_next_comm(kProcName1);
567 sched_switch->set_next_pid(100);
568 sched_switch->set_next_prio(1024);
569 EXPECT_CALL(*sched_,
570 PushSchedSwitch(10, 1000, 10, base::StringView(kProcName2), 256,
571 32, 100, base::StringView(kProcName1), 1024));
572 Tokenize();
573 context_.sorter->ExtractEventsForced();
574
575 bundle = trace_->add_packet()->set_ftrace_events();
576 bundle->set_cpu(10);
577 event = bundle->add_event();
578 event->set_timestamp(1001);
579 event->set_pid(12);
580 sched_switch = event->set_sched_switch();
581 sched_switch->set_prev_pid(100);
582 sched_switch->set_prev_comm(kProcName1);
583 sched_switch->set_prev_prio(256);
584 sched_switch->set_prev_state(32);
585 sched_switch->set_next_comm(kProcName2);
586 sched_switch->set_next_pid(10);
587 sched_switch->set_next_prio(512);
588
589 EXPECT_CALL(*sched_,
590 PushSchedSwitch(10, 1001, 100, base::StringView(kProcName1), 256,
591 32, 10, base::StringView(kProcName2), 512));
592 Tokenize();
593 context_.sorter->ExtractEventsForced();
594 }
595
TEST_F(ProtoTraceParserTest,LoadCpuFreq)596 TEST_F(ProtoTraceParserTest, LoadCpuFreq) {
597 auto* bundle = trace_->add_packet()->set_ftrace_events();
598 bundle->set_cpu(12);
599 auto* event = bundle->add_event();
600 event->set_timestamp(1000);
601 event->set_pid(12);
602 auto* cpu_freq = event->set_cpu_frequency();
603 cpu_freq->set_cpu_id(10);
604 cpu_freq->set_state(2000);
605
606 EXPECT_CALL(*event_, PushCounter(1000, DoubleEq(2000), TrackId{0}));
607 Tokenize();
608 context_.sorter->ExtractEventsForced();
609
610 EXPECT_EQ(context_.storage->cpu_counter_track_table().cpu()[0], 10u);
611 }
612
TEST_F(ProtoTraceParserTest,LoadCpuFreqKHz)613 TEST_F(ProtoTraceParserTest, LoadCpuFreqKHz) {
614 auto* packet = trace_->add_packet();
615 uint64_t ts = 1000;
616 packet->set_timestamp(ts);
617 auto* bundle = packet->set_sys_stats();
618 bundle->add_cpufreq_khz(2650000u);
619 bundle->add_cpufreq_khz(3698200u);
620
621 EXPECT_CALL(*event_, PushCounter(static_cast<int64_t>(ts), DoubleEq(2650000u),
622 TrackId{0u}));
623 EXPECT_CALL(*event_, PushCounter(static_cast<int64_t>(ts), DoubleEq(3698200u),
624 TrackId{1u}));
625 Tokenize();
626 context_.sorter->ExtractEventsForced();
627
628 EXPECT_EQ(context_.storage->track_table().row_count(), 2u);
629 EXPECT_EQ(context_.storage->cpu_counter_track_table().row_count(), 2u);
630
631 auto row = context_.storage->cpu_counter_track_table().FindById(TrackId(0));
632 EXPECT_EQ(context_.storage->GetString(row->name()), "cpufreq");
633 EXPECT_EQ(row->cpu(), 0u);
634
635 row = context_.storage->cpu_counter_track_table().FindById(TrackId(1));
636 EXPECT_EQ(row->cpu(), 1u);
637 }
638
TEST_F(ProtoTraceParserTest,LoadMemInfo)639 TEST_F(ProtoTraceParserTest, LoadMemInfo) {
640 auto* packet = trace_->add_packet();
641 uint64_t ts = 1000;
642 packet->set_timestamp(ts);
643 auto* bundle = packet->set_sys_stats();
644 auto* meminfo = bundle->add_meminfo();
645 meminfo->set_key(protos::pbzero::MEMINFO_MEM_TOTAL);
646 uint32_t value = 10;
647 meminfo->set_value(value);
648
649 EXPECT_CALL(*event_, PushCounter(static_cast<int64_t>(ts),
650 DoubleEq(value * 1024.0), TrackId{1u}));
651 Tokenize();
652 context_.sorter->ExtractEventsForced();
653
654 EXPECT_EQ(context_.storage->track_table().row_count(), 2u);
655 }
656
TEST_F(ProtoTraceParserTest,LoadVmStats)657 TEST_F(ProtoTraceParserTest, LoadVmStats) {
658 auto* packet = trace_->add_packet();
659 uint64_t ts = 1000;
660 packet->set_timestamp(ts);
661 auto* bundle = packet->set_sys_stats();
662 auto* meminfo = bundle->add_vmstat();
663 meminfo->set_key(protos::pbzero::VMSTAT_COMPACT_SUCCESS);
664 uint32_t value = 10;
665 meminfo->set_value(value);
666
667 EXPECT_CALL(*event_, PushCounter(static_cast<int64_t>(ts), DoubleEq(value),
668 TrackId{1u}));
669 Tokenize();
670 context_.sorter->ExtractEventsForced();
671
672 EXPECT_EQ(context_.storage->track_table().row_count(), 2u);
673 }
674
TEST_F(ProtoTraceParserTest,LoadProcessPacket)675 TEST_F(ProtoTraceParserTest, LoadProcessPacket) {
676 auto* tree = trace_->add_packet()->set_process_tree();
677 auto* process = tree->add_processes();
678 static const char kProcName1[] = "proc1";
679
680 process->add_cmdline(kProcName1);
681 process->set_pid(1);
682 process->set_ppid(3);
683
684 EXPECT_CALL(*process_,
685 SetProcessMetadata(1, Eq(3u), base::StringView(kProcName1),
686 base::StringView(kProcName1)));
687 Tokenize();
688 context_.sorter->ExtractEventsForced();
689 }
690
TEST_F(ProtoTraceParserTest,LoadProcessPacket_FirstCmdline)691 TEST_F(ProtoTraceParserTest, LoadProcessPacket_FirstCmdline) {
692 auto* tree = trace_->add_packet()->set_process_tree();
693 auto* process = tree->add_processes();
694 static const char kProcName1[] = "proc1";
695 static const char kProcName2[] = "proc2";
696
697 process->add_cmdline(kProcName1);
698 process->add_cmdline(kProcName2);
699 process->set_pid(1);
700 process->set_ppid(3);
701
702 EXPECT_CALL(*process_,
703 SetProcessMetadata(1, Eq(3u), base::StringView(kProcName1),
704 base::StringView("proc1 proc2")));
705 Tokenize();
706 context_.sorter->ExtractEventsForced();
707 }
708
TEST_F(ProtoTraceParserTest,LoadThreadPacket)709 TEST_F(ProtoTraceParserTest, LoadThreadPacket) {
710 auto* tree = trace_->add_packet()->set_process_tree();
711 auto* thread = tree->add_threads();
712 thread->set_tid(1);
713 thread->set_tgid(2);
714
715 EXPECT_CALL(*process_, UpdateThread(1, 2));
716 Tokenize();
717 context_.sorter->ExtractEventsForced();
718 }
719
TEST_F(ProtoTraceParserTest,ProcessNameFromProcessDescriptor)720 TEST_F(ProtoTraceParserTest, ProcessNameFromProcessDescriptor) {
721 {
722 auto* packet = trace_->add_packet();
723 packet->set_trusted_packet_sequence_id(1);
724 packet->set_incremental_state_cleared(true);
725 auto* process_desc = packet->set_process_descriptor();
726 process_desc->set_pid(15);
727 process_desc->set_process_name("OldProcessName");
728 }
729 {
730 auto* packet = trace_->add_packet();
731 packet->set_trusted_packet_sequence_id(1);
732 packet->set_incremental_state_cleared(true);
733 auto* process_desc = packet->set_process_descriptor();
734 process_desc->set_pid(15);
735 process_desc->set_process_name("NewProcessName");
736 }
737 {
738 auto* packet = trace_->add_packet();
739 packet->set_trusted_packet_sequence_id(2);
740 packet->set_incremental_state_cleared(true);
741 auto* process_desc = packet->set_process_descriptor();
742 process_desc->set_pid(16);
743 process_desc->set_process_name("DifferentProcessName");
744 }
745
746 EXPECT_CALL(*process_, GetOrCreateProcess(15))
747 .WillRepeatedly(testing::Return(1u));
748 EXPECT_CALL(*process_, GetOrCreateProcess(16)).WillOnce(testing::Return(2u));
749
750 EXPECT_CALL(*process_, SetProcessNameIfUnset(
751 1u, storage_->InternString("OldProcessName")));
752 // Packet with same thread, but different name should update the name.
753 EXPECT_CALL(*process_, SetProcessNameIfUnset(
754 1u, storage_->InternString("NewProcessName")));
755 EXPECT_CALL(*process_,
756 SetProcessNameIfUnset(
757 2u, storage_->InternString("DifferentProcessName")));
758
759 Tokenize();
760 context_.sorter->ExtractEventsForced();
761 }
762
TEST_F(ProtoTraceParserTest,ThreadNameFromThreadDescriptor)763 TEST_F(ProtoTraceParserTest, ThreadNameFromThreadDescriptor) {
764 {
765 auto* packet = trace_->add_packet();
766 packet->set_trusted_packet_sequence_id(1);
767 packet->set_incremental_state_cleared(true);
768 auto* thread_desc = packet->set_thread_descriptor();
769 thread_desc->set_pid(15);
770 thread_desc->set_tid(16);
771 thread_desc->set_reference_timestamp_us(1000);
772 thread_desc->set_reference_thread_time_us(2000);
773 thread_desc->set_thread_name("OldThreadName");
774 }
775 {
776 auto* packet = trace_->add_packet();
777 packet->set_trusted_packet_sequence_id(1);
778 packet->set_incremental_state_cleared(true);
779 auto* thread_desc = packet->set_thread_descriptor();
780 thread_desc->set_pid(15);
781 thread_desc->set_tid(16);
782 thread_desc->set_reference_timestamp_us(1000);
783 thread_desc->set_reference_thread_time_us(2000);
784 thread_desc->set_thread_name("NewThreadName");
785 }
786 {
787 auto* packet = trace_->add_packet();
788 packet->set_trusted_packet_sequence_id(2);
789 packet->set_incremental_state_cleared(true);
790 auto* thread_desc = packet->set_thread_descriptor();
791 thread_desc->set_pid(15);
792 thread_desc->set_tid(11);
793 thread_desc->set_reference_timestamp_us(1000);
794 thread_desc->set_reference_thread_time_us(2000);
795 thread_desc->set_thread_name("DifferentThreadName");
796 }
797
798 EXPECT_CALL(*process_, UpdateThread(16, 15))
799 .WillRepeatedly(testing::Return(1u));
800 EXPECT_CALL(*process_, UpdateThread(11, 15)).WillOnce(testing::Return(2u));
801
802 EXPECT_CALL(*process_, UpdateThreadNameByUtid(
803 1u, storage_->InternString("OldThreadName"),
804 ThreadNamePriority::kTrackDescriptor));
805 // Packet with same thread, but different name should update the name.
806 EXPECT_CALL(*process_, UpdateThreadNameByUtid(
807 1u, storage_->InternString("NewThreadName"),
808 ThreadNamePriority::kTrackDescriptor));
809 EXPECT_CALL(*process_, UpdateThreadNameByUtid(
810 2u, storage_->InternString("DifferentThreadName"),
811 ThreadNamePriority::kTrackDescriptor));
812
813 Tokenize();
814 context_.sorter->ExtractEventsForced();
815 }
816
TEST_F(ProtoTraceParserTest,TrackEventWithoutInternedData)817 TEST_F(ProtoTraceParserTest, TrackEventWithoutInternedData) {
818 {
819 auto* packet = trace_->add_packet();
820 packet->set_trusted_packet_sequence_id(1);
821 packet->set_incremental_state_cleared(true);
822 auto* thread_desc = packet->set_thread_descriptor();
823 thread_desc->set_pid(15);
824 thread_desc->set_tid(16);
825 thread_desc->set_reference_timestamp_us(1000);
826 thread_desc->set_reference_thread_time_us(2000);
827 }
828 {
829 auto* packet = trace_->add_packet();
830 packet->set_trusted_packet_sequence_id(1);
831 auto* event = packet->set_track_event();
832 event->set_timestamp_delta_us(10); // absolute: 1010.
833 event->set_thread_time_delta_us(5); // absolute: 2005.
834 event->add_category_iids(1);
835 auto* legacy_event = event->set_legacy_event();
836 legacy_event->set_name_iid(1);
837 legacy_event->set_phase('B');
838 }
839 {
840 auto* packet = trace_->add_packet();
841 packet->set_trusted_packet_sequence_id(1);
842 auto* event = packet->set_track_event();
843 event->set_timestamp_delta_us(10); // absolute: 1020.
844 event->set_thread_time_delta_us(5); // absolute: 2010.
845 event->add_category_iids(1);
846 auto* legacy_event = event->set_legacy_event();
847 legacy_event->set_name_iid(1);
848 legacy_event->set_phase('E');
849 }
850 {
851 auto* packet = trace_->add_packet();
852 packet->set_trusted_packet_sequence_id(1);
853 auto* event = packet->set_track_event();
854 event->set_timestamp_absolute_us(1005);
855 event->set_thread_time_absolute_us(2003);
856 event->add_category_iids(2);
857 event->add_category_iids(3);
858 auto* legacy_event = event->set_legacy_event();
859 legacy_event->set_name_iid(2);
860 legacy_event->set_phase('X');
861 legacy_event->set_duration_us(23); // absolute end: 1028.
862 legacy_event->set_thread_duration_us(12); // absolute end: 2015.
863 }
864
865 Tokenize();
866
867 EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
868
869 tables::ThreadTable::Row row(16);
870 row.upid = 1u;
871 storage_->mutable_thread_table()->Insert(row);
872
873 MockBoundInserter inserter;
874
875 StringId unknown_cat = storage_->InternString("unknown(1)");
876
877 constexpr TrackId track{0u};
878 constexpr TrackId thread_time_track{1u};
879
880 InSequence in_sequence; // Below slices should be sorted by timestamp.
881 // Only the begin thread time can be imported into the counter table.
882 EXPECT_CALL(*event_, PushCounter(1005000, testing::DoubleEq(2003000),
883 thread_time_track));
884 EXPECT_CALL(*slice_, StartSlice(1005000, track, _, _))
885 .WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()),
886 InvokeArgument<2>(&inserter), Return(SliceId(0u))));
887 EXPECT_CALL(*event_, PushCounter(1010000, testing::DoubleEq(2005000),
888 thread_time_track));
889 EXPECT_CALL(*slice_, StartSlice(1010000, track, _, _))
890 .WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()),
891 InvokeArgument<2>(&inserter), Return(SliceId(1u))));
892 EXPECT_CALL(*event_, PushCounter(1020000, testing::DoubleEq(2010000),
893 thread_time_track));
894 EXPECT_CALL(*slice_, End(1020000, track, unknown_cat, kNullStringId, _))
895 .WillOnce(DoAll(InvokeArgument<4>(&inserter), Return(SliceId(1u))));
896
897 context_.sorter->ExtractEventsForced();
898
899 EXPECT_EQ(storage_->slice_table().row_count(), 2u);
900 auto id_0 = storage_->slice_table().id().IndexOf(SliceId(0u));
901 EXPECT_TRUE(id_0);
902 EXPECT_EQ(storage_->slice_table().thread_ts()[*id_0], 2003000);
903 EXPECT_EQ(storage_->slice_table().thread_dur()[*id_0], 12000);
904 auto id_1 = storage_->slice_table().id().IndexOf(SliceId(1u));
905 EXPECT_TRUE(id_1);
906 EXPECT_EQ(storage_->slice_table().thread_ts()[*id_1], 2005000);
907 EXPECT_EQ(storage_->slice_table().thread_dur()[*id_1], 5000);
908 }
909
TEST_F(ProtoTraceParserTest,TrackEventWithoutInternedDataWithTypes)910 TEST_F(ProtoTraceParserTest, TrackEventWithoutInternedDataWithTypes) {
911 {
912 auto* packet = trace_->add_packet();
913 packet->set_trusted_packet_sequence_id(1);
914 packet->set_incremental_state_cleared(true);
915 auto* thread_desc = packet->set_thread_descriptor();
916 thread_desc->set_pid(15);
917 thread_desc->set_tid(16);
918 thread_desc->set_reference_timestamp_us(1000);
919 thread_desc->set_reference_thread_time_us(2000);
920 }
921 {
922 auto* packet = trace_->add_packet();
923 packet->set_trusted_packet_sequence_id(1);
924 auto* event = packet->set_track_event();
925 event->set_timestamp_delta_us(10); // absolute: 1010.
926 event->set_thread_time_delta_us(5); // absolute: 2005.
927 event->add_category_iids(1);
928 event->set_type(protos::pbzero::TrackEvent::TYPE_SLICE_BEGIN);
929 auto* legacy_event = event->set_legacy_event();
930 legacy_event->set_name_iid(1);
931 }
932 {
933 auto* packet = trace_->add_packet();
934 packet->set_trusted_packet_sequence_id(1);
935 auto* event = packet->set_track_event();
936 event->set_timestamp_delta_us(10); // absolute: 1020.
937 event->set_thread_time_delta_us(5); // absolute: 2010.
938 event->add_category_iids(1);
939 event->set_type(protos::pbzero::TrackEvent::TYPE_SLICE_END);
940 auto* legacy_event = event->set_legacy_event();
941 legacy_event->set_name_iid(1);
942 }
943 {
944 auto* packet = trace_->add_packet();
945 packet->set_trusted_packet_sequence_id(1);
946 auto* event = packet->set_track_event();
947 event->set_timestamp_absolute_us(1015);
948 event->set_thread_time_absolute_us(2007);
949 event->add_category_iids(2);
950 event->set_type(protos::pbzero::TrackEvent::TYPE_INSTANT);
951 auto* legacy_event = event->set_legacy_event();
952 legacy_event->set_name_iid(2);
953 }
954
955 Tokenize();
956
957 EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
958
959 tables::ThreadTable::Row row(16);
960 row.upid = 1u;
961 storage_->mutable_thread_table()->Insert(row);
962
963 MockBoundInserter inserter;
964
965 StringId unknown_cat1 = storage_->InternString("unknown(1)");
966
967 constexpr TrackId track{0u};
968 constexpr TrackId thread_time_track{1u};
969
970 InSequence in_sequence; // Below slices should be sorted by timestamp.
971 EXPECT_CALL(*event_, PushCounter(1010000, testing::DoubleEq(2005000),
972 thread_time_track));
973 EXPECT_CALL(*slice_, StartSlice(1010000, track, _, _))
974 .WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()),
975 InvokeArgument<2>(&inserter), Return(SliceId(0u))));
976 EXPECT_CALL(*event_, PushCounter(1015000, testing::DoubleEq(2007000),
977 thread_time_track));
978 EXPECT_CALL(*slice_, StartSlice(1015000, track, _, _))
979 .WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()),
980 InvokeArgument<2>(&inserter), Return(SliceId(1u))));
981 EXPECT_CALL(*event_, PushCounter(1020000, testing::DoubleEq(2010000),
982 thread_time_track));
983 EXPECT_CALL(*slice_, End(1020000, track, unknown_cat1, kNullStringId, _))
984 .WillOnce(DoAll(InvokeArgument<4>(&inserter), Return(SliceId(0u))));
985
986 context_.sorter->ExtractEventsForced();
987
988 EXPECT_EQ(storage_->slice_table().row_count(), 2u);
989 auto id_0 = storage_->slice_table().id().IndexOf(SliceId(0u));
990 EXPECT_TRUE(id_0);
991 EXPECT_EQ(storage_->slice_table().thread_ts()[*id_0], 2005000);
992 EXPECT_EQ(storage_->slice_table().thread_dur()[*id_0], 5000);
993 auto id_1 = storage_->slice_table().id().IndexOf(SliceId(1u));
994 EXPECT_TRUE(id_1);
995 EXPECT_EQ(storage_->slice_table().thread_ts()[*id_1], 2007000);
996 EXPECT_EQ(storage_->slice_table().thread_dur()[*id_1], 0);
997 }
998
TEST_F(ProtoTraceParserTest,TrackEventWithInternedData)999 TEST_F(ProtoTraceParserTest, TrackEventWithInternedData) {
1000 {
1001 auto* packet = trace_->add_packet();
1002 packet->set_trusted_packet_sequence_id(1);
1003 packet->set_incremental_state_cleared(true);
1004 auto* thread_desc = packet->set_thread_descriptor();
1005 thread_desc->set_pid(15);
1006 thread_desc->set_tid(16);
1007 thread_desc->set_reference_timestamp_us(1000);
1008 thread_desc->set_reference_thread_time_us(2000);
1009 thread_desc->set_reference_thread_instruction_count(3000);
1010 }
1011 {
1012 auto* packet = trace_->add_packet();
1013 packet->set_trusted_packet_sequence_id(1);
1014 auto* event = packet->set_track_event();
1015 event->set_timestamp_delta_us(10); // absolute: 1010.
1016 event->set_thread_time_delta_us(5); // absolute: 2005.
1017 event->set_thread_instruction_count_delta(20); // absolute: 3020.
1018 event->add_category_iids(1);
1019 auto* legacy_event = event->set_legacy_event();
1020 legacy_event->set_name_iid(1);
1021 legacy_event->set_phase('B');
1022
1023 auto* interned_data = packet->set_interned_data();
1024 auto cat1 = interned_data->add_event_categories();
1025 cat1->set_iid(1);
1026 cat1->set_name("cat1");
1027 auto ev1 = interned_data->add_event_names();
1028 ev1->set_iid(1);
1029 ev1->set_name("ev1");
1030 }
1031 {
1032 auto* packet = trace_->add_packet();
1033 packet->set_trusted_packet_sequence_id(1);
1034 auto* event = packet->set_track_event();
1035 event->set_timestamp_absolute_us(1040);
1036 event->set_thread_time_absolute_us(2030);
1037 event->set_thread_instruction_count_absolute(3100);
1038 event->add_category_iids(1);
1039 auto* legacy_event = event->set_legacy_event();
1040 legacy_event->set_name_iid(1);
1041 legacy_event->set_phase('I');
1042 }
1043 {
1044 auto* packet = trace_->add_packet();
1045 packet->set_trusted_packet_sequence_id(1);
1046 auto* event = packet->set_track_event();
1047 event->set_timestamp_absolute_us(1050);
1048 event->add_category_iids(1);
1049 auto* legacy_event = event->set_legacy_event();
1050 legacy_event->set_name_iid(1);
1051 legacy_event->set_phase('i');
1052 legacy_event->set_instant_event_scope(
1053 protos::pbzero::TrackEvent::LegacyEvent::SCOPE_PROCESS);
1054 }
1055 {
1056 auto* packet = trace_->add_packet();
1057 packet->set_trusted_packet_sequence_id(1);
1058 auto* event = packet->set_track_event();
1059 event->set_timestamp_delta_us(10); // absolute: 1020.
1060 event->set_thread_time_delta_us(5); // absolute: 2010.
1061 event->set_thread_instruction_count_delta(20); // absolute: 3040.
1062 event->add_category_iids(1);
1063 auto* legacy_event = event->set_legacy_event();
1064 legacy_event->set_name_iid(1);
1065 legacy_event->set_phase('E');
1066 }
1067 {
1068 auto* packet = trace_->add_packet();
1069 packet->set_trusted_packet_sequence_id(1);
1070 auto* event = packet->set_track_event();
1071 event->set_timestamp_absolute_us(1005);
1072 event->set_thread_time_absolute_us(2003);
1073 event->set_thread_instruction_count_absolute(3010);
1074 event->add_category_iids(2);
1075 event->add_category_iids(3);
1076 auto* legacy_event = event->set_legacy_event();
1077 legacy_event->set_name_iid(4);
1078 legacy_event->set_phase('X');
1079 legacy_event->set_duration_us(23); // absolute end: 1028.
1080 legacy_event->set_thread_duration_us(12); // absolute end: 2015.
1081 legacy_event->set_thread_instruction_delta(50); // absolute end: 3060.
1082 legacy_event->set_bind_id(9999);
1083 legacy_event->set_flow_direction(
1084 protos::pbzero::TrackEvent::LegacyEvent::FLOW_OUT);
1085
1086 auto* interned_data = packet->set_interned_data();
1087 auto cat2 = interned_data->add_event_categories();
1088 cat2->set_iid(2);
1089 cat2->set_name("cat2");
1090 auto cat3 = interned_data->add_event_categories();
1091 cat3->set_iid(3);
1092 cat3->set_name("cat3");
1093 auto ev2 = interned_data->add_event_names();
1094 ev2->set_iid(4);
1095 ev2->set_name("ev2");
1096 }
1097
1098 {
1099 auto* packet = trace_->add_packet();
1100 packet->set_trusted_packet_sequence_id(1);
1101 auto* thread_desc = packet->set_thread_descriptor();
1102 thread_desc->set_pid(15);
1103 thread_desc->set_tid(16);
1104 auto* event = packet->set_track_event();
1105 event->set_timestamp_absolute_us(1005);
1106 event->add_category_iids(2);
1107 auto* legacy_event = event->set_legacy_event();
1108 legacy_event->set_name_iid(4);
1109 legacy_event->set_phase('t');
1110 legacy_event->set_unscoped_id(220);
1111 }
1112
1113 {
1114 auto* packet = trace_->add_packet();
1115 packet->set_trusted_packet_sequence_id(1);
1116 auto* thread_desc = packet->set_thread_descriptor();
1117 thread_desc->set_pid(15);
1118 thread_desc->set_tid(16);
1119 auto* event = packet->set_track_event();
1120 event->set_timestamp_absolute_us(1005);
1121 event->add_category_iids(2);
1122 auto* legacy_event = event->set_legacy_event();
1123 legacy_event->set_name_iid(4);
1124 legacy_event->set_phase('f');
1125 legacy_event->set_unscoped_id(330);
1126 legacy_event->set_bind_to_enclosing(false);
1127 }
1128
1129 Tokenize();
1130
1131 EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
1132
1133 tables::ThreadTable::Row row(16);
1134 row.upid = 2u;
1135 storage_->mutable_thread_table()->Insert(row);
1136
1137 constexpr TrackId thread_1_track{0u};
1138 constexpr TrackId thread_time_track{1u};
1139 constexpr TrackId thread_instruction_count_track{2u};
1140 constexpr TrackId process_2_track{3u};
1141
1142 StringId cat_1 = storage_->InternString("cat1");
1143 StringId ev_1 = storage_->InternString("ev1");
1144
1145 InSequence in_sequence; // Below slices should be sorted by timestamp.
1146
1147 MockBoundInserter inserter;
1148 // Only the begin timestamp counters can be imported into the counter table.
1149 EXPECT_CALL(*event_, PushCounter(1005000, testing::DoubleEq(2003000),
1150 thread_time_track));
1151 EXPECT_CALL(*event_, PushCounter(1005000, testing::DoubleEq(3010),
1152 thread_instruction_count_track));
1153 EXPECT_CALL(*slice_, StartSlice(1005000, thread_1_track, _, _))
1154 .WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()),
1155 InvokeArgument<2>(&inserter), Return(SliceId(0u))));
1156
1157 EXPECT_CALL(*event_, PushCounter(1010000, testing::DoubleEq(2005000),
1158 thread_time_track));
1159 EXPECT_CALL(*event_, PushCounter(1010000, testing::DoubleEq(3020),
1160 thread_instruction_count_track));
1161 EXPECT_CALL(*slice_, StartSlice(1010000, thread_1_track, _, _))
1162 .WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()),
1163 InvokeArgument<2>(&inserter), Return(SliceId(1u))));
1164
1165 EXPECT_CALL(*event_, PushCounter(1020000, testing::DoubleEq(2010000),
1166 thread_time_track));
1167 EXPECT_CALL(*event_, PushCounter(1020000, testing::DoubleEq(3040),
1168 thread_instruction_count_track));
1169 EXPECT_CALL(*slice_, End(1020000, thread_1_track, cat_1, ev_1, _))
1170 .WillOnce(DoAll(InvokeArgument<4>(&inserter), Return(SliceId(1u))));
1171
1172 EXPECT_CALL(*event_, PushCounter(1040000, testing::DoubleEq(2030000),
1173 thread_time_track));
1174 EXPECT_CALL(*event_, PushCounter(1040000, testing::DoubleEq(3100),
1175 thread_instruction_count_track));
1176 EXPECT_CALL(*slice_, StartSlice(1040000, thread_1_track, _, _))
1177 .WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()),
1178 InvokeArgument<2>(&inserter), Return(SliceId(2u))));
1179
1180 EXPECT_CALL(*slice_, Scoped(1050000, process_2_track, cat_1, ev_1, 0, _))
1181 .WillOnce(DoAll(InvokeArgument<5>(&inserter), Return(SliceId(3u))));
1182 // Second slice should have a legacy_event.passthrough_utid arg.
1183 EXPECT_CALL(inserter, AddArg(_, _, Variadic::UnsignedInteger(1u), _));
1184
1185 context_.sorter->ExtractEventsForced();
1186
1187 EXPECT_EQ(storage_->slice_table().row_count(), 3u);
1188 auto id_0 = storage_->slice_table().id().IndexOf(SliceId(0u));
1189 EXPECT_TRUE(id_0);
1190 EXPECT_EQ(storage_->slice_table().thread_ts()[*id_0], 2003000);
1191 EXPECT_EQ(storage_->slice_table().thread_dur()[*id_0], 12000);
1192 EXPECT_EQ(storage_->slice_table().thread_instruction_count()[*id_0], 3010);
1193 EXPECT_EQ(storage_->slice_table().thread_instruction_delta()[*id_0], 50);
1194 auto id_1 = storage_->slice_table().id().IndexOf(SliceId(1u));
1195 EXPECT_TRUE(id_1);
1196 EXPECT_EQ(storage_->slice_table().thread_ts()[*id_1], 2005000);
1197 EXPECT_EQ(storage_->slice_table().thread_dur()[*id_1], 5000);
1198 EXPECT_EQ(storage_->slice_table().thread_instruction_count()[*id_1], 3020);
1199 EXPECT_EQ(storage_->slice_table().thread_instruction_delta()[*id_1], 20);
1200 auto id_2 = storage_->slice_table().id().IndexOf(SliceId(2u));
1201 EXPECT_TRUE(id_2);
1202 EXPECT_EQ(storage_->slice_table().thread_ts()[*id_2], 2030000);
1203 EXPECT_EQ(storage_->slice_table().thread_dur()[*id_2], 0);
1204 EXPECT_EQ(storage_->slice_table().thread_instruction_count()[*id_2], 3100);
1205 EXPECT_EQ(storage_->slice_table().thread_instruction_delta()[*id_2], 0);
1206 }
1207
TEST_F(ProtoTraceParserTest,TrackEventAsyncEvents)1208 TEST_F(ProtoTraceParserTest, TrackEventAsyncEvents) {
1209 {
1210 auto* packet = trace_->add_packet();
1211 packet->set_trusted_packet_sequence_id(1);
1212 packet->set_incremental_state_cleared(true);
1213 auto* thread_desc = packet->set_thread_descriptor();
1214 thread_desc->set_pid(15);
1215 thread_desc->set_tid(16);
1216 thread_desc->set_reference_timestamp_us(1000);
1217 thread_desc->set_reference_thread_time_us(2000);
1218 thread_desc->set_reference_thread_instruction_count(3000);
1219 }
1220 {
1221 auto* packet = trace_->add_packet();
1222 packet->set_trusted_packet_sequence_id(1);
1223 auto* event = packet->set_track_event();
1224 event->set_timestamp_delta_us(10); // absolute: 1010.
1225 event->set_thread_time_delta_us(5); // absolute: 2005.
1226 event->set_thread_instruction_count_delta(20); // absolute: 3020.
1227 event->add_category_iids(1);
1228 auto* legacy_event = event->set_legacy_event();
1229 legacy_event->set_name_iid(1);
1230 legacy_event->set_phase('b');
1231 legacy_event->set_global_id(10);
1232 legacy_event->set_use_async_tts(true);
1233
1234 auto* interned_data = packet->set_interned_data();
1235 auto cat1 = interned_data->add_event_categories();
1236 cat1->set_iid(1);
1237 cat1->set_name("cat1");
1238 auto ev1 = interned_data->add_event_names();
1239 ev1->set_iid(1);
1240 ev1->set_name("ev1");
1241 }
1242 {
1243 auto* packet = trace_->add_packet();
1244 packet->set_trusted_packet_sequence_id(1);
1245 auto* event = packet->set_track_event();
1246 event->set_timestamp_delta_us(10); // absolute: 1020.
1247 event->set_thread_time_delta_us(5); // absolute: 2010.
1248 event->set_thread_instruction_count_delta(20); // absolute: 3040.
1249 event->add_category_iids(1);
1250 auto* legacy_event = event->set_legacy_event();
1251 legacy_event->set_name_iid(1);
1252 legacy_event->set_phase('e');
1253 legacy_event->set_global_id(10);
1254 legacy_event->set_use_async_tts(true);
1255 }
1256 {
1257 auto* packet = trace_->add_packet();
1258 packet->set_trusted_packet_sequence_id(1);
1259 auto* event = packet->set_track_event();
1260 event->set_timestamp_absolute_us(1015);
1261 event->add_category_iids(1);
1262 auto* legacy_event = event->set_legacy_event();
1263 legacy_event->set_name_iid(2);
1264 legacy_event->set_phase('n');
1265 legacy_event->set_global_id(10);
1266
1267 auto* interned_data = packet->set_interned_data();
1268 auto ev2 = interned_data->add_event_names();
1269 ev2->set_iid(2);
1270 ev2->set_name("ev2");
1271 }
1272 {
1273 // Different category but same global_id -> separate track.
1274 auto* packet = trace_->add_packet();
1275 packet->set_trusted_packet_sequence_id(1);
1276 auto* event = packet->set_track_event();
1277 event->set_timestamp_absolute_us(1018);
1278 event->add_category_iids(2);
1279 auto* legacy_event = event->set_legacy_event();
1280 legacy_event->set_name_iid(2);
1281 legacy_event->set_phase('n');
1282 legacy_event->set_global_id(15);
1283
1284 auto* interned_data = packet->set_interned_data();
1285 auto cat2 = interned_data->add_event_categories();
1286 cat2->set_iid(2);
1287 cat2->set_name("cat2");
1288 }
1289 {
1290 auto* packet = trace_->add_packet();
1291 packet->set_trusted_packet_sequence_id(1);
1292 auto* event = packet->set_track_event();
1293 event->set_timestamp_absolute_us(1030);
1294 event->add_category_iids(2);
1295 auto* legacy_event = event->set_legacy_event();
1296 legacy_event->set_name_iid(2);
1297 legacy_event->set_phase('n');
1298 legacy_event->set_local_id(15);
1299 legacy_event->set_id_scope("scope1");
1300 }
1301
1302 Tokenize();
1303
1304 EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
1305
1306 tables::ThreadTable::Row row(16);
1307 row.upid = 1u;
1308 storage_->mutable_thread_table()->Insert(row);
1309
1310 StringId cat_1 = storage_->InternString("cat1");
1311 StringId ev_1 = storage_->InternString("ev1");
1312 StringId cat_2 = storage_->InternString("cat2");
1313 StringId ev_2 = storage_->InternString("ev2");
1314
1315 TrackId thread_time_track{2u};
1316 TrackId thread_instruction_count_track{3u};
1317
1318 InSequence in_sequence; // Below slices should be sorted by timestamp.
1319
1320 EXPECT_CALL(*event_, PushCounter(1010000, testing::DoubleEq(2005000),
1321 thread_time_track));
1322 EXPECT_CALL(*event_, PushCounter(1010000, testing::DoubleEq(3020),
1323 thread_instruction_count_track));
1324 EXPECT_CALL(*slice_, Begin(1010000, TrackId{1}, cat_1, ev_1, _))
1325 .WillOnce(Return(SliceId(0u)));
1326 EXPECT_CALL(*slice_, Scoped(1015000, TrackId{1}, cat_1, ev_2, 0, _));
1327 EXPECT_CALL(*slice_, Scoped(1018000, TrackId{4}, cat_2, ev_2, 0, _));
1328 EXPECT_CALL(*event_, PushCounter(1020000, testing::DoubleEq(2010000),
1329 thread_time_track));
1330 EXPECT_CALL(*event_, PushCounter(1020000, testing::DoubleEq(3040),
1331 thread_instruction_count_track));
1332 EXPECT_CALL(*slice_, End(1020000, TrackId{1}, cat_1, ev_1, _))
1333 .WillOnce(Return(SliceId(SliceId(0u))));
1334 EXPECT_CALL(*slice_, Scoped(1030000, TrackId{5}, cat_2, ev_2, 0, _));
1335
1336 context_.sorter->ExtractEventsForced();
1337
1338 // First track is for the thread; second first async, third and fourth for
1339 // thread time and instruction count, others are the async event tracks.
1340 EXPECT_EQ(storage_->track_table().row_count(), 6u);
1341 EXPECT_EQ(storage_->track_table().name()[1], ev_1);
1342 EXPECT_EQ(storage_->track_table().name()[4], ev_2);
1343 EXPECT_EQ(storage_->track_table().name()[5], ev_2);
1344
1345 EXPECT_EQ(storage_->process_track_table().row_count(), 3u);
1346 EXPECT_EQ(storage_->process_track_table().upid()[0], 1u);
1347 EXPECT_EQ(storage_->process_track_table().upid()[1], 1u);
1348 EXPECT_EQ(storage_->process_track_table().upid()[2], 1u);
1349
1350 EXPECT_EQ(storage_->virtual_track_slices().slice_count(), 1u);
1351 EXPECT_EQ(storage_->virtual_track_slices().slice_ids()[0], SliceId(0u));
1352 EXPECT_EQ(storage_->virtual_track_slices().thread_timestamp_ns()[0], 2005000);
1353 EXPECT_EQ(storage_->virtual_track_slices().thread_duration_ns()[0], 5000);
1354 EXPECT_EQ(storage_->virtual_track_slices().thread_instruction_counts()[0],
1355 3020);
1356 EXPECT_EQ(storage_->virtual_track_slices().thread_instruction_deltas()[0],
1357 20);
1358 }
1359
1360 // TODO(eseckler): Also test instant events on separate tracks.
TEST_F(ProtoTraceParserTest,TrackEventWithTrackDescriptors)1361 TEST_F(ProtoTraceParserTest, TrackEventWithTrackDescriptors) {
1362 // Sequence 1.
1363 {
1364 auto* packet = trace_->add_packet();
1365 packet->set_trusted_packet_sequence_id(1);
1366 packet->set_incremental_state_cleared(true);
1367 packet->set_timestamp(1000000);
1368 auto* track_desc = packet->set_track_descriptor();
1369 track_desc->set_uuid(1234);
1370 track_desc->set_name("Thread track 1");
1371 auto* thread_desc = track_desc->set_thread();
1372 thread_desc->set_pid(15);
1373 thread_desc->set_tid(16);
1374 auto* chrome_thread = track_desc->set_chrome_thread();
1375 chrome_thread->set_thread_type(
1376 protos::pbzero::ChromeThreadDescriptor::THREAD_SAMPLING_PROFILER);
1377 }
1378 {
1379 auto* packet = trace_->add_packet();
1380 packet->set_trusted_packet_sequence_id(1);
1381 packet->set_timestamp(1000000);
1382 auto* track_desc = packet->set_track_descriptor();
1383 track_desc->set_uuid(5678);
1384 track_desc->set_name("Async track 1");
1385 }
1386 {
1387 // Async event started on "Async track 1".
1388 auto* packet = trace_->add_packet();
1389 packet->set_trusted_packet_sequence_id(1);
1390 packet->set_timestamp(1010000);
1391 auto* event = packet->set_track_event();
1392 event->set_track_uuid(5678);
1393 event->set_thread_time_absolute_us(2005);
1394 event->set_thread_instruction_count_absolute(3020);
1395 event->add_category_iids(1);
1396 event->set_name_iid(1);
1397 event->set_type(protos::pbzero::TrackEvent::TYPE_SLICE_BEGIN);
1398 auto* legacy_event = event->set_legacy_event();
1399 legacy_event->set_use_async_tts(true);
1400
1401 auto* interned_data = packet->set_interned_data();
1402 auto cat1 = interned_data->add_event_categories();
1403 cat1->set_iid(1);
1404 cat1->set_name("cat1");
1405 auto ev1 = interned_data->add_event_names();
1406 ev1->set_iid(1);
1407 ev1->set_name("ev1");
1408 }
1409 {
1410 // Instant event on "Thread track 1".
1411 auto* packet = trace_->add_packet();
1412 packet->set_trusted_packet_sequence_id(1);
1413 packet->set_timestamp(1015000);
1414 auto* event = packet->set_track_event();
1415 event->set_track_uuid(1234);
1416 event->set_thread_time_absolute_us(2007);
1417 event->add_category_iids(2);
1418 event->set_name_iid(2);
1419 event->set_type(protos::pbzero::TrackEvent::TYPE_INSTANT);
1420
1421 auto* interned_data = packet->set_interned_data();
1422 auto cat1 = interned_data->add_event_categories();
1423 cat1->set_iid(2);
1424 cat1->set_name("cat2");
1425 auto ev1 = interned_data->add_event_names();
1426 ev1->set_iid(2);
1427 ev1->set_name("ev2");
1428 }
1429
1430 // Sequence 2.
1431 {
1432 auto* packet = trace_->add_packet();
1433 packet->set_trusted_packet_sequence_id(2);
1434 packet->set_incremental_state_cleared(true);
1435 packet->set_timestamp(1000000);
1436 auto* track_desc = packet->set_track_descriptor();
1437 track_desc->set_uuid(4321);
1438 track_desc->set_name("Thread track 2");
1439 auto* thread_desc = track_desc->set_thread();
1440 thread_desc->set_pid(15);
1441 thread_desc->set_tid(17);
1442 }
1443 {
1444 // Async event completed on "Async track 1".
1445 auto* packet = trace_->add_packet();
1446 packet->set_trusted_packet_sequence_id(2);
1447 packet->set_timestamp(1020000);
1448 auto* event = packet->set_track_event();
1449 event->set_track_uuid(5678);
1450 event->set_thread_time_absolute_us(2010);
1451 event->set_thread_instruction_count_absolute(3040);
1452 event->set_type(protos::pbzero::TrackEvent::TYPE_SLICE_END);
1453 auto* legacy_event = event->set_legacy_event();
1454 legacy_event->set_use_async_tts(true);
1455 }
1456 {
1457 // Instant event on "Thread track 2".
1458 auto* packet = trace_->add_packet();
1459 packet->set_trusted_packet_sequence_id(2);
1460 packet->set_timestamp(1016000);
1461 auto* event = packet->set_track_event();
1462 event->set_track_uuid(4321);
1463 event->set_thread_time_absolute_us(2008);
1464 event->add_category_iids(1);
1465 event->set_name_iid(1);
1466 event->set_type(protos::pbzero::TrackEvent::TYPE_INSTANT);
1467
1468 auto* interned_data = packet->set_interned_data();
1469 auto cat1 = interned_data->add_event_categories();
1470 cat1->set_iid(1);
1471 cat1->set_name("cat3");
1472 auto ev1 = interned_data->add_event_names();
1473 ev1->set_iid(1);
1474 ev1->set_name("ev3");
1475 }
1476
1477 EXPECT_CALL(*process_,
1478 UpdateThreadNameByUtid(
1479 1u, storage_->InternString("StackSamplingProfiler"),
1480 ThreadNamePriority::kTrackDescriptorThreadType));
1481 EXPECT_CALL(*process_,
1482 UpdateThreadNameByUtid(2u, kNullStringId,
1483 ThreadNamePriority::kTrackDescriptor));
1484 EXPECT_CALL(*process_,
1485 UpdateThreadNameByUtid(1u, kNullStringId,
1486 ThreadNamePriority::kTrackDescriptor));
1487 EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
1488 EXPECT_CALL(*process_, UpdateThread(17, 15)).WillRepeatedly(Return(2u));
1489
1490 tables::ThreadTable::Row t1(16);
1491 t1.upid = 1u;
1492 storage_->mutable_thread_table()->Insert(t1);
1493
1494 tables::ThreadTable::Row t2(16);
1495 t2.upid = 2u;
1496 storage_->mutable_thread_table()->Insert(t2);
1497
1498 Tokenize();
1499
1500 StringId cat_1 = storage_->InternString("cat1");
1501 StringId ev_1 = storage_->InternString("ev1");
1502
1503 InSequence in_sequence; // Below slices should be sorted by timestamp.
1504
1505 EXPECT_CALL(*slice_, Begin(1010000, TrackId{1}, cat_1, ev_1, _))
1506 .WillOnce(Return(SliceId(2u)));
1507
1508 EXPECT_CALL(*event_,
1509 PushCounter(1015000, testing::DoubleEq(2007000), TrackId{3}));
1510 EXPECT_CALL(*slice_, StartSlice(1015000, TrackId{0}, _, _))
1511 .WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()), Return(SliceId(0u))));
1512
1513 EXPECT_CALL(*event_,
1514 PushCounter(1016000, testing::DoubleEq(2008000), TrackId{4}));
1515 EXPECT_CALL(*slice_, StartSlice(1016000, TrackId{2}, _, _))
1516 .WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()), Return(SliceId(1u))));
1517
1518 EXPECT_CALL(*slice_,
1519 End(1020000, TrackId{1}, kNullStringId, kNullStringId, _))
1520 .WillOnce(Return(SliceId(2u)));
1521
1522 context_.sorter->ExtractEventsForced();
1523
1524 // First track is "Thread track 1"; second is "Async track 1", third is global
1525 // default track (parent of async track), fourth is "Thread track 2", fifth &
1526 // sixth are thread time tracks for thread 1 and 2.
1527 EXPECT_EQ(storage_->track_table().row_count(), 5u);
1528 EXPECT_EQ(storage_->track_table().name().GetString(0), "Thread track 1");
1529 EXPECT_EQ(storage_->track_table().name().GetString(1), "Async track 1");
1530 EXPECT_EQ(storage_->track_table().name().GetString(2), "Thread track 2");
1531 EXPECT_EQ(storage_->thread_track_table().row_count(), 2u);
1532 EXPECT_EQ(storage_->thread_track_table().utid()[0], 1u);
1533 EXPECT_EQ(storage_->thread_track_table().utid()[1], 2u);
1534
1535 EXPECT_EQ(storage_->virtual_track_slices().slice_count(), 1u);
1536 EXPECT_EQ(storage_->virtual_track_slices().slice_ids()[0], SliceId(2u));
1537 EXPECT_EQ(storage_->virtual_track_slices().thread_timestamp_ns()[0], 2005000);
1538 EXPECT_EQ(storage_->virtual_track_slices().thread_duration_ns()[0], 5000);
1539 EXPECT_EQ(storage_->virtual_track_slices().thread_instruction_counts()[0],
1540 3020);
1541 EXPECT_EQ(storage_->virtual_track_slices().thread_instruction_deltas()[0],
1542 20);
1543
1544 EXPECT_EQ(storage_->slice_table().row_count(), 2u);
1545 auto id_0 = storage_->slice_table().id().IndexOf(SliceId(0u));
1546 EXPECT_TRUE(id_0);
1547 EXPECT_EQ(storage_->slice_table().thread_ts()[*id_0], 2007000);
1548 EXPECT_EQ(storage_->slice_table().thread_dur()[*id_0], 0);
1549 // There was no thread instructions in the packets above.
1550 EXPECT_FALSE(storage_->slice_table().thread_instruction_count()[*id_0]);
1551 EXPECT_FALSE(storage_->slice_table().thread_instruction_delta()[*id_0]);
1552 auto id_1 = storage_->slice_table().id().IndexOf(SliceId(1u));
1553 EXPECT_TRUE(id_1);
1554 EXPECT_EQ(storage_->slice_table().thread_ts()[*id_1], 2008000);
1555 EXPECT_EQ(storage_->slice_table().thread_dur()[*id_1], 0);
1556 EXPECT_FALSE(storage_->slice_table().thread_instruction_count()[*id_1]);
1557 EXPECT_FALSE(storage_->slice_table().thread_instruction_delta()[*id_1]);
1558 }
1559
TEST_F(ProtoTraceParserTest,TrackEventWithResortedCounterDescriptor)1560 TEST_F(ProtoTraceParserTest, TrackEventWithResortedCounterDescriptor) {
1561 // Descriptors with timestamps after the event below. They will be tokenized
1562 // in the order they appear here, but then resorted before parsing to appear
1563 // after the events below.
1564 {
1565 auto* packet = trace_->add_packet();
1566 packet->set_trusted_packet_sequence_id(1);
1567 packet->set_incremental_state_cleared(true);
1568 packet->set_timestamp(3000);
1569 auto* track_desc = packet->set_track_descriptor();
1570 track_desc->set_uuid(1);
1571 auto* thread_desc = track_desc->set_thread();
1572 thread_desc->set_pid(5);
1573 thread_desc->set_tid(1);
1574 thread_desc->set_thread_name("t1");
1575 // Default to track for "t1" and an extra counter for thread time.
1576 auto* track_event_defaults =
1577 packet->set_trace_packet_defaults()->set_track_event_defaults();
1578 track_event_defaults->set_track_uuid(1);
1579 // Thread-time counter track defined below.
1580 track_event_defaults->add_extra_counter_track_uuids(10);
1581 }
1582 {
1583 auto* packet = trace_->add_packet();
1584 packet->set_trusted_packet_sequence_id(1);
1585 packet->set_timestamp(3000);
1586 auto* track_desc = packet->set_track_descriptor();
1587 track_desc->set_uuid(10);
1588 track_desc->set_parent_uuid(1);
1589 auto* counter = track_desc->set_counter();
1590 counter->set_type(
1591 protos::pbzero::CounterDescriptor::COUNTER_THREAD_TIME_NS);
1592 counter->set_unit_multiplier(1000); // provided in us.
1593 counter->set_is_incremental(true);
1594 }
1595 {
1596 // Event with timestamps before the descriptors above. The thread time
1597 // counter values should still be imported as counter values and as args for
1598 // JSON export. Should appear on default track "t1" with
1599 // extra_counter_values for "c1".
1600 auto* packet = trace_->add_packet();
1601 packet->set_trusted_packet_sequence_id(1);
1602 packet->set_sequence_flags(
1603 protos::pbzero::TracePacket::SEQ_NEEDS_INCREMENTAL_STATE);
1604 packet->set_timestamp(1000);
1605 auto* event = packet->set_track_event();
1606 event->add_categories("cat1");
1607 event->set_name("ev1");
1608 event->set_type(protos::pbzero::TrackEvent::TYPE_SLICE_BEGIN);
1609 event->add_extra_counter_values(1000); // absolute: 1000000.
1610 }
1611 {
1612 // End for "ev1".
1613 auto* packet = trace_->add_packet();
1614 packet->set_trusted_packet_sequence_id(1);
1615 packet->set_timestamp(1100);
1616 auto* event = packet->set_track_event();
1617 event->set_type(protos::pbzero::TrackEvent::TYPE_SLICE_END);
1618 event->add_extra_counter_values(10); // absolute: 1010000.
1619 }
1620
1621 EXPECT_CALL(*process_, UpdateThread(1, 5)).WillRepeatedly(Return(1u));
1622
1623 tables::ThreadTable::Row t1(16);
1624 t1.upid = 1u;
1625 storage_->mutable_thread_table()->Insert(t1);
1626
1627 Tokenize();
1628
1629 InSequence in_sequence; // Below slices should be sorted by timestamp.
1630
1631 EXPECT_CALL(*event_,
1632 PushCounter(1000, testing::DoubleEq(1000000), TrackId{1}));
1633 EXPECT_CALL(*slice_, StartSlice(1000, TrackId{0}, _, _))
1634 .WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()), Return(SliceId(0u))));
1635
1636 EXPECT_CALL(*event_,
1637 PushCounter(1100, testing::DoubleEq(1010000), TrackId{1}));
1638 EXPECT_CALL(*slice_, End(1100, TrackId{0}, kNullStringId, kNullStringId, _))
1639 .WillOnce(Return(SliceId(0u)));
1640
1641 EXPECT_CALL(*process_,
1642 UpdateThreadNameByUtid(1u, storage_->InternString("t1"),
1643 ThreadNamePriority::kTrackDescriptor));
1644
1645 context_.sorter->ExtractEventsForced();
1646
1647 // First track is thread time track, second is "t1".
1648 EXPECT_EQ(storage_->track_table().row_count(), 2u);
1649 EXPECT_EQ(storage_->thread_track_table().row_count(), 1u);
1650 EXPECT_EQ(storage_->thread_track_table().utid()[0], 1u);
1651
1652 // Counter values should also be imported into thread slices.
1653 EXPECT_EQ(storage_->slice_table().row_count(), 1u);
1654 auto id_0 = storage_->slice_table().id().IndexOf(SliceId(0u));
1655 EXPECT_TRUE(id_0);
1656 EXPECT_EQ(storage_->slice_table().thread_ts()[*id_0], 1000000);
1657 EXPECT_EQ(storage_->slice_table().thread_dur()[*id_0], 10000);
1658 }
1659
TEST_F(ProtoTraceParserTest,TrackEventWithoutIncrementalStateReset)1660 TEST_F(ProtoTraceParserTest, TrackEventWithoutIncrementalStateReset) {
1661 {
1662 auto* packet = trace_->add_packet();
1663 packet->set_trusted_packet_sequence_id(1);
1664 auto* thread_desc = packet->set_thread_descriptor();
1665 thread_desc->set_pid(15);
1666 thread_desc->set_tid(16);
1667 thread_desc->set_reference_timestamp_us(1000);
1668 thread_desc->set_reference_thread_time_us(2000);
1669 }
1670 {
1671 // Event should be discarded because delta timestamps require valid
1672 // incremental state + thread descriptor.
1673 auto* packet = trace_->add_packet();
1674 packet->set_trusted_packet_sequence_id(1);
1675 auto* event = packet->set_track_event();
1676 event->set_timestamp_delta_us(10); // absolute: 1010.
1677 event->set_thread_time_delta_us(5); // absolute: 2005.
1678 event->add_category_iids(1);
1679 auto* legacy_event = event->set_legacy_event();
1680 legacy_event->set_name_iid(1);
1681 legacy_event->set_phase('B');
1682 }
1683 {
1684 // Event should be discarded because it specifies
1685 // SEQ_NEEDS_INCREMENTAL_STATE.
1686 auto* packet = trace_->add_packet();
1687 packet->set_timestamp(2000000);
1688 packet->set_trusted_packet_sequence_id(1);
1689 packet->set_sequence_flags(
1690 protos::pbzero::TracePacket::SEQ_NEEDS_INCREMENTAL_STATE);
1691 auto* event = packet->set_track_event();
1692 event->add_categories("cat");
1693 event->set_name("ev1");
1694 event->set_type(protos::pbzero::TrackEvent::TYPE_INSTANT);
1695 }
1696 {
1697 // Event should be accepted because it does not specify
1698 // SEQ_NEEDS_INCREMENTAL_STATE and uses absolute timestamps.
1699 auto* packet = trace_->add_packet();
1700 packet->set_timestamp(2100000);
1701 packet->set_trusted_packet_sequence_id(1);
1702 auto* event = packet->set_track_event();
1703 event->add_categories("cat1");
1704 event->set_name("ev2");
1705 event->set_type(protos::pbzero::TrackEvent::TYPE_INSTANT);
1706 }
1707
1708 Tokenize();
1709
1710 StringId cat1 = storage_->InternString("cat1");
1711 StringId ev2 = storage_->InternString("ev2");
1712
1713 EXPECT_CALL(*slice_, Scoped(2100000, TrackId{0}, cat1, ev2, 0, _))
1714 .WillOnce(Return(SliceId(0u)));
1715 context_.sorter->ExtractEventsForced();
1716 }
1717
TEST_F(ProtoTraceParserTest,TrackEventWithoutThreadDescriptor)1718 TEST_F(ProtoTraceParserTest, TrackEventWithoutThreadDescriptor) {
1719 {
1720 // Event should be discarded because it specifies delta timestamps and no
1721 // thread descriptor was seen yet.
1722 auto* packet = trace_->add_packet();
1723 packet->set_trusted_packet_sequence_id(1);
1724 packet->set_incremental_state_cleared(true);
1725 auto* event = packet->set_track_event();
1726 event->set_timestamp_delta_us(10);
1727 event->set_thread_time_delta_us(5);
1728 event->add_category_iids(1);
1729 auto* legacy_event = event->set_legacy_event();
1730 legacy_event->set_name_iid(1);
1731 legacy_event->set_phase('B');
1732 }
1733 {
1734 // Events that specify SEQ_NEEDS_INCREMENTAL_STATE should be accepted even
1735 // if there's no valid thread descriptor.
1736 auto* packet = trace_->add_packet();
1737 packet->set_timestamp(2000000);
1738 packet->set_trusted_packet_sequence_id(1);
1739 packet->set_sequence_flags(
1740 protos::pbzero::TracePacket::SEQ_NEEDS_INCREMENTAL_STATE);
1741 auto* event = packet->set_track_event();
1742 event->add_categories("cat1");
1743 event->set_name("ev1");
1744 event->set_type(protos::pbzero::TrackEvent::TYPE_INSTANT);
1745 }
1746
1747 Tokenize();
1748
1749 StringId cat1 = storage_->InternString("cat1");
1750 StringId ev1 = storage_->InternString("ev1");
1751
1752 EXPECT_CALL(*slice_, Scoped(2000000, TrackId{0}, cat1, ev1, 0, _))
1753 .WillOnce(Return(SliceId(0u)));
1754 context_.sorter->ExtractEventsForced();
1755 }
1756
TEST_F(ProtoTraceParserTest,TrackEventWithDataLoss)1757 TEST_F(ProtoTraceParserTest, TrackEventWithDataLoss) {
1758 {
1759 auto* packet = trace_->add_packet();
1760 packet->set_trusted_packet_sequence_id(1);
1761 packet->set_incremental_state_cleared(true);
1762 auto* thread_desc = packet->set_thread_descriptor();
1763 thread_desc->set_pid(15);
1764 thread_desc->set_tid(16);
1765 thread_desc->set_reference_timestamp_us(1000);
1766 }
1767 {
1768 auto* packet = trace_->add_packet();
1769 packet->set_trusted_packet_sequence_id(1);
1770 auto* event = packet->set_track_event();
1771 event->set_timestamp_delta_us(10); // absolute: 1010.
1772 event->add_category_iids(1);
1773 auto* legacy_event = event->set_legacy_event();
1774 legacy_event->set_name_iid(1);
1775 legacy_event->set_phase('B');
1776 }
1777 {
1778 // Event should be dropped because data loss occurred before.
1779 auto* packet = trace_->add_packet();
1780 packet->set_trusted_packet_sequence_id(1);
1781 packet->set_previous_packet_dropped(true); // Data loss occurred.
1782 auto* event = packet->set_track_event();
1783 event->set_timestamp_delta_us(10);
1784 event->add_category_iids(1);
1785 auto* legacy_event = event->set_legacy_event();
1786 legacy_event->set_name_iid(1);
1787 legacy_event->set_phase('E');
1788 }
1789 {
1790 // Event should be dropped because incremental state is invalid.
1791 auto* packet = trace_->add_packet();
1792 packet->set_trusted_packet_sequence_id(1);
1793 auto* event = packet->set_track_event();
1794 event->set_timestamp_delta_us(10);
1795 event->add_category_iids(1);
1796 auto* legacy_event = event->set_legacy_event();
1797 legacy_event->set_name_iid(1);
1798 legacy_event->set_phase('E');
1799 }
1800 {
1801 // Event should be dropped because no new thread descriptor was seen yet.
1802 auto* packet = trace_->add_packet();
1803 packet->set_trusted_packet_sequence_id(1);
1804 packet->set_incremental_state_cleared(true);
1805 auto* event = packet->set_track_event();
1806 event->set_timestamp_delta_us(10);
1807 event->add_category_iids(1);
1808 auto* legacy_event = event->set_legacy_event();
1809 legacy_event->set_name_iid(1);
1810 legacy_event->set_phase('E');
1811 }
1812 {
1813 auto* packet = trace_->add_packet();
1814 packet->set_trusted_packet_sequence_id(1);
1815 auto* thread_desc = packet->set_thread_descriptor();
1816 thread_desc->set_pid(15);
1817 thread_desc->set_tid(16);
1818 thread_desc->set_reference_timestamp_us(2000);
1819 }
1820 {
1821 auto* packet = trace_->add_packet();
1822 packet->set_trusted_packet_sequence_id(1);
1823 auto* event = packet->set_track_event();
1824 event->set_timestamp_delta_us(10); // absolute: 2010.
1825 event->add_category_iids(1);
1826 auto* legacy_event = event->set_legacy_event();
1827 legacy_event->set_name_iid(1);
1828 legacy_event->set_phase('E');
1829 }
1830
1831 Tokenize();
1832
1833 EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
1834
1835 tables::ThreadTable::Row row(16);
1836 row.upid = 1u;
1837 storage_->mutable_thread_table()->Insert(row);
1838
1839 StringId unknown_cat = storage_->InternString("unknown(1)");
1840 constexpr TrackId track{0u};
1841 InSequence in_sequence; // Below slices should be sorted by timestamp.
1842 EXPECT_CALL(*slice_, StartSlice(1010000, track, _, _));
1843 EXPECT_CALL(*slice_, End(2010000, track, unknown_cat, kNullStringId, _));
1844
1845 context_.sorter->ExtractEventsForced();
1846 }
1847
TEST_F(ProtoTraceParserTest,TrackEventMultipleSequences)1848 TEST_F(ProtoTraceParserTest, TrackEventMultipleSequences) {
1849 {
1850 auto* packet = trace_->add_packet();
1851 packet->set_trusted_packet_sequence_id(1);
1852 packet->set_incremental_state_cleared(true);
1853 auto* thread_desc = packet->set_thread_descriptor();
1854 thread_desc->set_pid(15);
1855 thread_desc->set_tid(16);
1856 thread_desc->set_reference_timestamp_us(1000);
1857 }
1858 {
1859 auto* packet = trace_->add_packet();
1860 packet->set_trusted_packet_sequence_id(1);
1861 auto* event = packet->set_track_event();
1862 event->set_timestamp_delta_us(10); // absolute: 1010.
1863 event->add_category_iids(1);
1864 auto* legacy_event = event->set_legacy_event();
1865 legacy_event->set_name_iid(1);
1866 legacy_event->set_phase('B');
1867
1868 auto* interned_data = packet->set_interned_data();
1869 auto cat1 = interned_data->add_event_categories();
1870 cat1->set_iid(1);
1871 cat1->set_name("cat1");
1872 auto ev1 = interned_data->add_event_names();
1873 ev1->set_iid(1);
1874 ev1->set_name("ev1");
1875 }
1876 {
1877 auto* packet = trace_->add_packet();
1878 packet->set_trusted_packet_sequence_id(2);
1879 packet->set_incremental_state_cleared(true);
1880 auto* thread_desc = packet->set_thread_descriptor();
1881 thread_desc->set_pid(15);
1882 thread_desc->set_tid(17);
1883 thread_desc->set_reference_timestamp_us(995);
1884 }
1885 {
1886 auto* packet = trace_->add_packet();
1887 packet->set_trusted_packet_sequence_id(2);
1888 auto* event = packet->set_track_event();
1889 event->set_timestamp_delta_us(10); // absolute: 1005.
1890 event->add_category_iids(1);
1891 auto* legacy_event = event->set_legacy_event();
1892 legacy_event->set_name_iid(1);
1893 legacy_event->set_phase('B');
1894
1895 auto* interned_data = packet->set_interned_data();
1896 auto cat1 = interned_data->add_event_categories();
1897 cat1->set_iid(1);
1898 cat1->set_name("cat1");
1899 auto ev2 = interned_data->add_event_names();
1900 ev2->set_iid(1);
1901 ev2->set_name("ev2");
1902 }
1903 {
1904 auto* packet = trace_->add_packet();
1905 packet->set_trusted_packet_sequence_id(1);
1906 auto* event = packet->set_track_event();
1907 event->set_timestamp_delta_us(10); // absolute: 1020.
1908 event->add_category_iids(1);
1909 auto* legacy_event = event->set_legacy_event();
1910 legacy_event->set_name_iid(1);
1911 legacy_event->set_phase('E');
1912 }
1913 {
1914 auto* packet = trace_->add_packet();
1915 packet->set_trusted_packet_sequence_id(2);
1916 auto* event = packet->set_track_event();
1917 event->set_timestamp_delta_us(10); // absolute: 1015.
1918 event->add_category_iids(1);
1919 auto* legacy_event = event->set_legacy_event();
1920 legacy_event->set_name_iid(1);
1921 legacy_event->set_phase('E');
1922 }
1923
1924 Tokenize();
1925
1926 EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
1927 EXPECT_CALL(*process_, UpdateThread(17, 15)).WillRepeatedly(Return(2u));
1928
1929 tables::ThreadTable::Row t1(16);
1930 t1.upid = 1u;
1931 storage_->mutable_thread_table()->Insert(t1);
1932
1933 tables::ThreadTable::Row t2(17);
1934 t2.upid = 1u;
1935 storage_->mutable_thread_table()->Insert(t2);
1936
1937 StringId cat_1 = storage_->InternString("cat1");
1938 StringId ev_2 = storage_->InternString("ev2");
1939 StringId ev_1 = storage_->InternString("ev1");
1940
1941 constexpr TrackId thread_2_track{0u};
1942 constexpr TrackId thread_1_track{1u};
1943 InSequence in_sequence; // Below slices should be sorted by timestamp.
1944
1945 EXPECT_CALL(*slice_, StartSlice(1005000, thread_2_track, _, _));
1946 EXPECT_CALL(*slice_, StartSlice(1010000, thread_1_track, _, _));
1947 EXPECT_CALL(*slice_, End(1015000, thread_2_track, cat_1, ev_2, _));
1948 EXPECT_CALL(*slice_, End(1020000, thread_1_track, cat_1, ev_1, _));
1949
1950 context_.sorter->ExtractEventsForced();
1951 }
1952
TEST_F(ProtoTraceParserTest,TrackEventWithDebugAnnotations)1953 TEST_F(ProtoTraceParserTest, TrackEventWithDebugAnnotations) {
1954 MockBoundInserter inserter;
1955
1956 {
1957 auto* packet = trace_->add_packet();
1958 packet->set_trusted_packet_sequence_id(1);
1959 packet->set_incremental_state_cleared(true);
1960 auto* thread_desc = packet->set_thread_descriptor();
1961 thread_desc->set_pid(15);
1962 thread_desc->set_tid(16);
1963 thread_desc->set_reference_timestamp_us(1000);
1964 }
1965 {
1966 auto* packet = trace_->add_packet();
1967 packet->set_trusted_packet_sequence_id(1);
1968 auto* event = packet->set_track_event();
1969 event->set_timestamp_delta_us(10); // absolute: 1010.
1970 event->add_category_iids(1);
1971 auto* annotation1 = event->add_debug_annotations();
1972 annotation1->set_name_iid(1);
1973 annotation1->set_uint_value(10u);
1974 auto* annotation2 = event->add_debug_annotations();
1975 annotation2->set_name_iid(2);
1976 auto* nested = annotation2->set_nested_value();
1977 nested->set_nested_type(protos::pbzero::DebugAnnotation::NestedValue::DICT);
1978 nested->add_dict_keys("child1");
1979 nested->add_dict_keys("child2");
1980 auto* child1 = nested->add_dict_values();
1981 child1->set_nested_type(
1982 protos::pbzero::DebugAnnotation::NestedValue::UNSPECIFIED);
1983 child1->set_bool_value(true);
1984 auto* child2 = nested->add_dict_values();
1985 child2->set_nested_type(
1986 protos::pbzero::DebugAnnotation::NestedValue::ARRAY);
1987 auto* child21 = child2->add_array_values();
1988 child21->set_nested_type(
1989 protos::pbzero::DebugAnnotation::NestedValue::UNSPECIFIED);
1990 child21->set_string_value("child21");
1991 auto* child22 = child2->add_array_values();
1992 child22->set_nested_type(
1993 protos::pbzero::DebugAnnotation::NestedValue::UNSPECIFIED);
1994 child22->set_double_value(2.2);
1995 auto* child23 = child2->add_array_values();
1996 child23->set_nested_type(
1997 protos::pbzero::DebugAnnotation::NestedValue::UNSPECIFIED);
1998 child23->set_int_value(23);
1999 auto* legacy_event = event->set_legacy_event();
2000 legacy_event->set_name_iid(1);
2001 legacy_event->set_phase('B');
2002
2003 auto* interned_data = packet->set_interned_data();
2004 auto cat1 = interned_data->add_event_categories();
2005 cat1->set_iid(1);
2006 cat1->set_name("cat1");
2007 auto ev1 = interned_data->add_event_names();
2008 ev1->set_iid(1);
2009 ev1->set_name("ev1");
2010 auto an1 = interned_data->add_debug_annotation_names();
2011 an1->set_iid(1);
2012 an1->set_name("an1");
2013 auto an2 = interned_data->add_debug_annotation_names();
2014 an2->set_iid(2);
2015 an2->set_name("an2");
2016 }
2017 {
2018 auto* packet = trace_->add_packet();
2019 packet->set_trusted_packet_sequence_id(1);
2020 auto* event = packet->set_track_event();
2021 event->set_timestamp_delta_us(10); // absolute: 1020.
2022 event->add_category_iids(1);
2023 auto* annotation3 = event->add_debug_annotations();
2024 annotation3->set_name_iid(3);
2025 annotation3->set_int_value(-3);
2026 auto* annotation4 = event->add_debug_annotations();
2027 annotation4->set_name_iid(4);
2028 annotation4->set_bool_value(true);
2029 auto* annotation5 = event->add_debug_annotations();
2030 annotation5->set_name_iid(5);
2031 annotation5->set_double_value(-5.5);
2032 auto* annotation6 = event->add_debug_annotations();
2033 annotation6->set_name_iid(6);
2034 annotation6->set_pointer_value(20u);
2035 auto* annotation7 = event->add_debug_annotations();
2036 annotation7->set_name_iid(7);
2037 annotation7->set_string_value("val7");
2038 auto* annotation8 = event->add_debug_annotations();
2039 annotation8->set_name_iid(8);
2040 annotation8->set_legacy_json_value(
2041 "{\"val8\": {\"a\": 42, \"b\": \"val8b\"}, \"arr8\": [1, 2, 3]}");
2042 auto* annotation9 = event->add_debug_annotations();
2043 annotation9->set_name_iid(9);
2044 annotation9->set_int_value(15);
2045 auto* legacy_event = event->set_legacy_event();
2046 legacy_event->set_name_iid(1);
2047 legacy_event->set_phase('E');
2048
2049 auto* interned_data = packet->set_interned_data();
2050 auto an3 = interned_data->add_debug_annotation_names();
2051 an3->set_iid(3);
2052 an3->set_name("an3");
2053 auto an4 = interned_data->add_debug_annotation_names();
2054 an4->set_iid(4);
2055 an4->set_name("an4");
2056 auto an5 = interned_data->add_debug_annotation_names();
2057 an5->set_iid(5);
2058 an5->set_name("an5");
2059 auto an6 = interned_data->add_debug_annotation_names();
2060 an6->set_iid(6);
2061 an6->set_name("an6");
2062 auto an7 = interned_data->add_debug_annotation_names();
2063 an7->set_iid(7);
2064 an7->set_name("an7");
2065 auto an8 = interned_data->add_debug_annotation_names();
2066 an8->set_iid(8);
2067 an8->set_name("an8");
2068 auto an9 = interned_data->add_debug_annotation_names();
2069 an9->set_iid(9);
2070 an9->set_name("an8.foo");
2071 }
2072
2073 Tokenize();
2074
2075 EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
2076
2077 tables::ThreadTable::Row row(16);
2078 row.upid = 1u;
2079 storage_->mutable_thread_table()->Insert(row);
2080
2081 StringId cat_1 = storage_->InternString("cat1");
2082 StringId ev_1 = storage_->InternString("ev1");
2083 StringId debug_an_1 = storage_->InternString("debug.an1");
2084 StringId debug_an_2_child_1 = storage_->InternString("debug.an2.child1");
2085 StringId debug_an_2_child_2 = storage_->InternString("debug.an2.child2");
2086 StringId debug_an_2_child_2_0 = storage_->InternString("debug.an2.child2[0]");
2087 StringId child21 = storage_->InternString("child21");
2088 StringId debug_an_2_child_2_1 = storage_->InternString("debug.an2.child2[1]");
2089 StringId debug_an_2_child_2_2 = storage_->InternString("debug.an2.child2[2]");
2090 StringId debug_an_3 = storage_->InternString("debug.an3");
2091 StringId debug_an_4 = storage_->InternString("debug.an4");
2092 StringId debug_an_5 = storage_->InternString("debug.an5");
2093 StringId debug_an_6 = storage_->InternString("debug.an6");
2094 StringId debug_an_7 = storage_->InternString("debug.an7");
2095 StringId val_7 = storage_->InternString("val7");
2096 StringId debug_an_8_val8_a = storage_->InternString("debug.an8.val8.a");
2097 StringId debug_an_8_val8_b = storage_->InternString("debug.an8.val8.b");
2098 StringId val_8b = storage_->InternString("val8b");
2099 StringId debug_an_8_arr8 = storage_->InternString("debug.an8.arr8");
2100 StringId debug_an_8_arr8_0 = storage_->InternString("debug.an8.arr8[0]");
2101 StringId debug_an_8_arr8_1 = storage_->InternString("debug.an8.arr8[1]");
2102 StringId debug_an_8_arr8_2 = storage_->InternString("debug.an8.arr8[2]");
2103 StringId debug_an_8_foo = storage_->InternString("debug.an8_foo");
2104
2105 constexpr TrackId track{0u};
2106
2107 EXPECT_CALL(*slice_, StartSlice(1010000, track, _, _))
2108 .WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()),
2109 InvokeArgument<2>(&inserter), Return(SliceId(0u))));
2110 EXPECT_CALL(inserter, AddArg(debug_an_1, debug_an_1,
2111 Variadic::UnsignedInteger(10u), _));
2112
2113 EXPECT_CALL(inserter, AddArg(debug_an_2_child_1, debug_an_2_child_1,
2114 Variadic::Boolean(true), _));
2115
2116 EXPECT_CALL(inserter, AddArg(debug_an_2_child_2, debug_an_2_child_2_0,
2117 Variadic::String(child21), _));
2118
2119 EXPECT_CALL(inserter, AddArg(debug_an_2_child_2, debug_an_2_child_2_1,
2120 Variadic::Real(2.2), _));
2121
2122 EXPECT_CALL(inserter, AddArg(debug_an_2_child_2, debug_an_2_child_2_2,
2123 Variadic::Integer(23), _));
2124
2125 EXPECT_CALL(*slice_, End(1020000, track, cat_1, ev_1, _))
2126 .WillOnce(DoAll(InvokeArgument<4>(&inserter), Return(SliceId(0u))));
2127
2128 EXPECT_CALL(inserter,
2129 AddArg(debug_an_3, debug_an_3, Variadic::Integer(-3), _));
2130 EXPECT_CALL(inserter,
2131 AddArg(debug_an_4, debug_an_4, Variadic::Boolean(true), _));
2132 EXPECT_CALL(inserter,
2133 AddArg(debug_an_5, debug_an_5, Variadic::Real(-5.5), _));
2134 EXPECT_CALL(inserter,
2135 AddArg(debug_an_6, debug_an_6, Variadic::Pointer(20u), _));
2136 EXPECT_CALL(inserter,
2137 AddArg(debug_an_7, debug_an_7, Variadic::String(val_7), _));
2138 EXPECT_CALL(inserter, AddArg(debug_an_8_val8_a, debug_an_8_val8_a,
2139 Variadic::Integer(42), _));
2140 EXPECT_CALL(inserter, AddArg(debug_an_8_val8_b, debug_an_8_val8_b,
2141 Variadic::String(val_8b), _));
2142 EXPECT_CALL(inserter, AddArg(debug_an_8_arr8, debug_an_8_arr8_0,
2143 Variadic::Integer(1), _));
2144 EXPECT_CALL(inserter, AddArg(debug_an_8_arr8, debug_an_8_arr8_1,
2145 Variadic::Integer(2), _));
2146 EXPECT_CALL(inserter, AddArg(debug_an_8_arr8, debug_an_8_arr8_2,
2147 Variadic::Integer(3), _));
2148 EXPECT_CALL(inserter,
2149 AddArg(debug_an_8_foo, debug_an_8_foo, Variadic::Integer(15), _));
2150
2151 context_.sorter->ExtractEventsForced();
2152 }
2153
TEST_F(ProtoTraceParserTest,TrackEventWithTaskExecution)2154 TEST_F(ProtoTraceParserTest, TrackEventWithTaskExecution) {
2155 {
2156 auto* packet = trace_->add_packet();
2157 packet->set_trusted_packet_sequence_id(1);
2158 packet->set_incremental_state_cleared(true);
2159 auto* thread_desc = packet->set_thread_descriptor();
2160 thread_desc->set_pid(15);
2161 thread_desc->set_tid(16);
2162 thread_desc->set_reference_timestamp_us(1000);
2163 }
2164 {
2165 auto* packet = trace_->add_packet();
2166 packet->set_trusted_packet_sequence_id(1);
2167 auto* event = packet->set_track_event();
2168 event->set_timestamp_delta_us(10); // absolute: 1010.
2169 event->add_category_iids(1);
2170 auto* task_execution = event->set_task_execution();
2171 task_execution->set_posted_from_iid(1);
2172 auto* legacy_event = event->set_legacy_event();
2173 legacy_event->set_name_iid(1);
2174 legacy_event->set_phase('B');
2175
2176 auto* interned_data = packet->set_interned_data();
2177 auto cat1 = interned_data->add_event_categories();
2178 cat1->set_iid(1);
2179 cat1->set_name("cat1");
2180 auto ev1 = interned_data->add_event_names();
2181 ev1->set_iid(1);
2182 ev1->set_name("ev1");
2183 auto loc1 = interned_data->add_source_locations();
2184 loc1->set_iid(1);
2185 loc1->set_file_name("file1");
2186 loc1->set_function_name("func1");
2187 loc1->set_line_number(42);
2188 }
2189
2190 Tokenize();
2191
2192 EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
2193
2194 tables::ThreadTable::Row row(16);
2195 row.upid = 1u;
2196 storage_->mutable_thread_table()->Insert(row);
2197
2198 constexpr TrackId track{0u};
2199
2200 StringId file_1 = storage_->InternString("file1");
2201 StringId func_1 = storage_->InternString("func1");
2202
2203 InSequence in_sequence; // Below slices should be sorted by timestamp.
2204
2205 MockBoundInserter inserter;
2206 EXPECT_CALL(*slice_, StartSlice(1010000, track, _, _))
2207 .WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()),
2208 InvokeArgument<2>(&inserter), Return(SliceId(0u))));
2209 EXPECT_CALL(inserter, AddArg(_, _, Variadic::String(file_1), _));
2210 EXPECT_CALL(inserter, AddArg(_, _, Variadic::String(func_1), _));
2211 EXPECT_CALL(inserter, AddArg(_, _, Variadic::UnsignedInteger(42), _));
2212
2213 context_.sorter->ExtractEventsForced();
2214 }
2215
TEST_F(ProtoTraceParserTest,TrackEventWithLogMessage)2216 TEST_F(ProtoTraceParserTest, TrackEventWithLogMessage) {
2217 {
2218 auto* packet = trace_->add_packet();
2219 packet->set_trusted_packet_sequence_id(1);
2220 packet->set_incremental_state_cleared(true);
2221 auto* thread_desc = packet->set_thread_descriptor();
2222 thread_desc->set_pid(15);
2223 thread_desc->set_tid(16);
2224 thread_desc->set_reference_timestamp_us(1000);
2225 }
2226 {
2227 auto* packet = trace_->add_packet();
2228 packet->set_trusted_packet_sequence_id(1);
2229 auto* event = packet->set_track_event();
2230 event->set_timestamp_delta_us(10); // absolute: 1010.
2231 event->add_category_iids(1);
2232
2233 auto* log_message = event->set_log_message();
2234 log_message->set_body_iid(1);
2235 log_message->set_source_location_iid(1);
2236
2237 auto* legacy_event = event->set_legacy_event();
2238 legacy_event->set_name_iid(1);
2239 legacy_event->set_phase('I');
2240
2241 auto* interned_data = packet->set_interned_data();
2242 auto cat1 = interned_data->add_event_categories();
2243 cat1->set_iid(1);
2244 cat1->set_name("cat1");
2245
2246 auto ev1 = interned_data->add_event_names();
2247 ev1->set_iid(1);
2248 ev1->set_name("ev1");
2249
2250 auto body = interned_data->add_log_message_body();
2251 body->set_iid(1);
2252 body->set_body("body1");
2253
2254 auto loc1 = interned_data->add_source_locations();
2255 loc1->set_iid(1);
2256 loc1->set_file_name("file1");
2257 loc1->set_function_name("func1");
2258 loc1->set_line_number(1);
2259 }
2260
2261 Tokenize();
2262
2263 EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
2264
2265 tables::ThreadTable::Row row(16);
2266 row.upid = 1u;
2267 storage_->mutable_thread_table()->Insert(row);
2268
2269 StringId body_1 = storage_->InternString("body1");
2270 StringId file_1 = storage_->InternString("file1");
2271 StringId func_1 = storage_->InternString("func1");
2272 StringId source_location_id = storage_->InternString("file1:1");
2273
2274 constexpr TrackId track{0};
2275 InSequence in_sequence; // Below slices should be sorted by timestamp.
2276
2277 MockBoundInserter inserter;
2278 EXPECT_CALL(*slice_, StartSlice(1010000, track, _, _))
2279 .WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()),
2280 InvokeArgument<2>(&inserter), Return(SliceId(0u))));
2281
2282 // Call with logMessageBody (body1 in this case).
2283 EXPECT_CALL(inserter, AddArg(_, _, Variadic::String(body_1), _));
2284 EXPECT_CALL(inserter, AddArg(_, _, Variadic::String(file_1), _));
2285 EXPECT_CALL(inserter, AddArg(_, _, Variadic::String(func_1), _));
2286 EXPECT_CALL(inserter, AddArg(_, _, Variadic::Integer(1), _));
2287
2288 context_.sorter->ExtractEventsForced();
2289
2290 EXPECT_GT(context_.storage->android_log_table().row_count(), 0u);
2291 EXPECT_EQ(context_.storage->android_log_table().ts()[0], 1010000);
2292 EXPECT_EQ(context_.storage->android_log_table().msg()[0], body_1);
2293 EXPECT_EQ(context_.storage->android_log_table().tag()[0], source_location_id);
2294 }
2295
TEST_F(ProtoTraceParserTest,TrackEventParseLegacyEventIntoRawTable)2296 TEST_F(ProtoTraceParserTest, TrackEventParseLegacyEventIntoRawTable) {
2297 {
2298 auto* packet = trace_->add_packet();
2299 packet->set_trusted_packet_sequence_id(1);
2300 packet->set_incremental_state_cleared(true);
2301 auto* thread_desc = packet->set_thread_descriptor();
2302 thread_desc->set_pid(15);
2303 thread_desc->set_tid(16);
2304 thread_desc->set_reference_timestamp_us(1000);
2305 thread_desc->set_reference_thread_time_us(2000);
2306 }
2307 {
2308 auto* packet = trace_->add_packet();
2309 packet->set_trusted_packet_sequence_id(1);
2310 auto* event = packet->set_track_event();
2311 event->set_timestamp_delta_us(10); // absolute: 1010.
2312 event->set_thread_time_delta_us(5); // absolute: 2005.
2313 event->add_category_iids(1);
2314
2315 auto* legacy_event = event->set_legacy_event();
2316 legacy_event->set_name_iid(1);
2317 // Represents a phase that isn't parsed into regular trace processor tables.
2318 legacy_event->set_phase('?');
2319 legacy_event->set_duration_us(23);
2320 legacy_event->set_thread_duration_us(15);
2321 legacy_event->set_global_id(99u);
2322 legacy_event->set_id_scope("scope1");
2323 legacy_event->set_use_async_tts(true);
2324
2325 auto* annotation1 = event->add_debug_annotations();
2326 annotation1->set_name_iid(1);
2327 annotation1->set_uint_value(10u);
2328
2329 auto* interned_data = packet->set_interned_data();
2330 auto cat1 = interned_data->add_event_categories();
2331 cat1->set_iid(1);
2332 cat1->set_name("cat1");
2333 auto ev1 = interned_data->add_event_names();
2334 ev1->set_iid(1);
2335 ev1->set_name("ev1");
2336 auto an1 = interned_data->add_debug_annotation_names();
2337 an1->set_iid(1);
2338 an1->set_name("an1");
2339 }
2340
2341 Tokenize();
2342
2343 EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
2344 // Only the begin thread time can be imported into the counter table.
2345 EXPECT_CALL(*event_,
2346 PushCounter(1010000, testing::DoubleEq(2005000), TrackId{1}));
2347
2348 tables::ThreadTable::Row row(16);
2349 row.upid = 1u;
2350 storage_->mutable_thread_table()->Insert(row);
2351
2352 StringId cat_1 = storage_->InternString("cat1");
2353 StringId ev_1 = storage_->InternString("ev1");
2354 StringId scope_1 = storage_->InternString("scope1");
2355 StringId question = storage_->InternString("?");
2356 StringId debug_an_1 = storage_->InternString("debug.an1");
2357
2358 context_.sorter->ExtractEventsForced();
2359
2360 ::testing::Mock::VerifyAndClearExpectations(storage_);
2361
2362 // Verify raw_table and args contents.
2363 const auto& raw_table = storage_->raw_table();
2364 EXPECT_EQ(raw_table.row_count(), 1u);
2365 EXPECT_EQ(raw_table.ts()[0], 1010000);
2366 EXPECT_EQ(raw_table.name()[0],
2367 storage_->InternString("track_event.legacy_event"));
2368 EXPECT_EQ(raw_table.cpu()[0], 0u);
2369 EXPECT_EQ(raw_table.utid()[0], 1u);
2370 EXPECT_EQ(raw_table.arg_set_id()[0], 1u);
2371
2372 EXPECT_GE(storage_->arg_table().row_count(), 10u);
2373
2374 EXPECT_TRUE(HasArg(1u, storage_->InternString("legacy_event.category"),
2375 Variadic::String(cat_1)));
2376 EXPECT_TRUE(HasArg(1u, storage_->InternString("legacy_event.name"),
2377 Variadic::String(ev_1)));
2378 EXPECT_TRUE(HasArg(1u, storage_->InternString("legacy_event.phase"),
2379 Variadic::String(question)));
2380 EXPECT_TRUE(HasArg(1u, storage_->InternString("legacy_event.duration_ns"),
2381 Variadic::Integer(23000)));
2382 EXPECT_TRUE(HasArg(1u,
2383 storage_->InternString("legacy_event.thread_timestamp_ns"),
2384 Variadic::Integer(2005000)));
2385 EXPECT_TRUE(HasArg(1u,
2386 storage_->InternString("legacy_event.thread_duration_ns"),
2387 Variadic::Integer(15000)));
2388 EXPECT_TRUE(HasArg(1u, storage_->InternString("legacy_event.use_async_tts"),
2389 Variadic::Boolean(true)));
2390 EXPECT_TRUE(HasArg(1u, storage_->InternString("legacy_event.global_id"),
2391 Variadic::UnsignedInteger(99u)));
2392 EXPECT_TRUE(HasArg(1u, storage_->InternString("legacy_event.id_scope"),
2393 Variadic::String(scope_1)));
2394 EXPECT_TRUE(HasArg(1u, debug_an_1, Variadic::UnsignedInteger(10u)));
2395 }
2396
TEST_F(ProtoTraceParserTest,TrackEventLegacyTimestampsWithClockSnapshot)2397 TEST_F(ProtoTraceParserTest, TrackEventLegacyTimestampsWithClockSnapshot) {
2398 clock_->AddSnapshot({{protos::pbzero::BUILTIN_CLOCK_BOOTTIME, 0},
2399 {protos::pbzero::BUILTIN_CLOCK_MONOTONIC, 1000000}});
2400
2401 {
2402 auto* packet = trace_->add_packet();
2403 packet->set_trusted_packet_sequence_id(1);
2404 packet->set_incremental_state_cleared(true);
2405 auto* thread_desc = packet->set_thread_descriptor();
2406 thread_desc->set_pid(15);
2407 thread_desc->set_tid(16);
2408 thread_desc->set_reference_timestamp_us(1000); // MONOTONIC.
2409 }
2410 {
2411 auto* packet = trace_->add_packet();
2412 packet->set_trusted_packet_sequence_id(1);
2413 auto* event = packet->set_track_event();
2414 event->set_timestamp_delta_us(10); // absolute: 1010 (mon), 10 (boot).
2415 event->add_category_iids(1);
2416 event->set_type(protos::pbzero::TrackEvent::TYPE_SLICE_BEGIN);
2417 auto* legacy_event = event->set_legacy_event();
2418 legacy_event->set_name_iid(1);
2419 }
2420
2421 Tokenize();
2422
2423 EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
2424
2425 tables::ThreadTable::Row row(16);
2426 row.upid = 1u;
2427 storage_->mutable_thread_table()->Insert(row);
2428
2429 constexpr TrackId track{0u};
2430 InSequence in_sequence; // Below slices should be sorted by timestamp.
2431
2432 // Timestamp should be adjusted to trace time (BOOTTIME).
2433 EXPECT_CALL(*slice_, StartSlice(10000, track, _, _));
2434
2435 context_.sorter->ExtractEventsForced();
2436 }
2437
TEST_F(ProtoTraceParserTest,ParseEventWithClockIdButWithoutClockSnapshot)2438 TEST_F(ProtoTraceParserTest, ParseEventWithClockIdButWithoutClockSnapshot) {
2439 {
2440 auto* packet = trace_->add_packet();
2441 packet->set_timestamp(1000);
2442 packet->set_timestamp_clock_id(3);
2443 packet->set_trusted_packet_sequence_id(1);
2444 auto* bundle = packet->set_chrome_events();
2445 auto* metadata = bundle->add_metadata();
2446 metadata->set_name("test");
2447 metadata->set_int_value(23);
2448 }
2449
2450 util::Status status = Tokenize();
2451 EXPECT_TRUE(status.ok());
2452 context_.sorter->ExtractEventsForced();
2453
2454 // Metadata should have created a raw event.
2455 const auto& raw_table = storage_->raw_table();
2456 EXPECT_EQ(raw_table.row_count(), 1u);
2457 }
2458
TEST_F(ProtoTraceParserTest,ParseChromeMetadataEventIntoRawTable)2459 TEST_F(ProtoTraceParserTest, ParseChromeMetadataEventIntoRawTable) {
2460 static const char kStringName[] = "string_name";
2461 static const char kStringValue[] = "string_value";
2462 static const char kIntName[] = "int_name";
2463 static const int kIntValue = 123;
2464
2465 {
2466 auto* packet = trace_->add_packet();
2467 packet->set_timestamp(1000);
2468 packet->set_timestamp_clock_id(3);
2469 packet->set_trusted_packet_sequence_id(1);
2470 auto* bundle = packet->set_chrome_events();
2471 auto* metadata = bundle->add_metadata();
2472 metadata->set_name(kStringName);
2473 metadata->set_string_value(kStringValue);
2474 metadata = bundle->add_metadata();
2475 metadata->set_name(kIntName);
2476 metadata->set_int_value(kIntValue);
2477 }
2478
2479 Tokenize();
2480 context_.sorter->ExtractEventsForced();
2481
2482 // Verify raw_table and args contents.
2483 const auto& raw_table = storage_->raw_table();
2484 EXPECT_EQ(raw_table.row_count(), 1u);
2485 EXPECT_EQ(raw_table.name()[0],
2486 storage_->InternString("chrome_event.metadata"));
2487 EXPECT_EQ(raw_table.arg_set_id()[0], 1u);
2488
2489 EXPECT_EQ(storage_->arg_table().row_count(), 2u);
2490 EXPECT_TRUE(HasArg(1u, storage_->InternString(kStringName),
2491 Variadic::String(storage_->InternString(kStringValue))));
2492 EXPECT_TRUE(HasArg(1u, storage_->InternString(kIntName),
2493 Variadic::Integer(kIntValue)));
2494 }
2495
TEST_F(ProtoTraceParserTest,ParseChromeLegacyFtraceIntoRawTable)2496 TEST_F(ProtoTraceParserTest, ParseChromeLegacyFtraceIntoRawTable) {
2497 static const char kDataPart0[] = "aaa";
2498 static const char kDataPart1[] = "bbb";
2499 static const char kFullData[] = "aaabbb";
2500
2501 {
2502 auto* packet = trace_->add_packet();
2503 packet->set_trusted_packet_sequence_id(1);
2504 auto* bundle = packet->set_chrome_events();
2505 bundle->add_legacy_ftrace_output(kDataPart0);
2506 bundle->add_legacy_ftrace_output(kDataPart1);
2507 }
2508
2509 Tokenize();
2510
2511 context_.sorter->ExtractEventsForced();
2512
2513 // Verify raw_table and args contents.
2514 const auto& raw_table = storage_->raw_table();
2515 EXPECT_EQ(raw_table.row_count(), 1u);
2516 EXPECT_EQ(raw_table.name()[0],
2517 storage_->InternString("chrome_event.legacy_system_trace"));
2518 EXPECT_EQ(raw_table.arg_set_id()[0], 1u);
2519
2520 EXPECT_EQ(storage_->arg_table().row_count(), 1u);
2521 EXPECT_TRUE(HasArg(1u, storage_->InternString("data"),
2522 Variadic::String(storage_->InternString(kFullData))));
2523 }
2524
TEST_F(ProtoTraceParserTest,ParseChromeLegacyJsonIntoRawTable)2525 TEST_F(ProtoTraceParserTest, ParseChromeLegacyJsonIntoRawTable) {
2526 static const char kUserTraceEvent[] = "{\"user\":1}";
2527
2528 {
2529 auto* packet = trace_->add_packet();
2530 packet->set_trusted_packet_sequence_id(1);
2531 auto* bundle = packet->set_chrome_events();
2532 auto* user_trace = bundle->add_legacy_json_trace();
2533 user_trace->set_type(protos::pbzero::ChromeLegacyJsonTrace::USER_TRACE);
2534 user_trace->set_data(kUserTraceEvent);
2535 }
2536
2537 Tokenize();
2538
2539 context_.sorter->ExtractEventsForced();
2540
2541 // Verify raw_table and args contents.
2542 const auto& raw_table = storage_->raw_table();
2543 EXPECT_EQ(raw_table.row_count(), 1u);
2544 EXPECT_EQ(raw_table.name()[0],
2545 storage_->InternString("chrome_event.legacy_user_trace"));
2546 EXPECT_EQ(raw_table.arg_set_id()[0], 1u);
2547
2548 EXPECT_EQ(storage_->arg_table().row_count(), 1u);
2549 EXPECT_TRUE(
2550 HasArg(1u, storage_->InternString("data"),
2551 Variadic::String(storage_->InternString(kUserTraceEvent))));
2552 }
2553
TEST_F(ProtoTraceParserTest,LoadChromeBenchmarkMetadata)2554 TEST_F(ProtoTraceParserTest, LoadChromeBenchmarkMetadata) {
2555 static const char kName[] = "name";
2556 static const char kTag1[] = "tag1";
2557 static const char kTag2[] = "tag2";
2558
2559 auto* metadata = trace_->add_packet()->set_chrome_benchmark_metadata();
2560 metadata->set_benchmark_name(kName);
2561 metadata->add_story_tags(kTag1);
2562 metadata->add_story_tags(kTag2);
2563
2564 Tokenize();
2565
2566 base::StringView benchmark = metadata::kNames[metadata::benchmark_name];
2567 base::StringView tags = metadata::kNames[metadata::benchmark_story_tags];
2568
2569 context_.sorter->ExtractEventsForced();
2570
2571 const auto& meta_keys = storage_->metadata_table().name();
2572 const auto& meta_values = storage_->metadata_table().str_value();
2573 EXPECT_EQ(storage_->metadata_table().row_count(), 3u);
2574
2575 std::vector<std::pair<base::StringView, base::StringView>> meta_entries;
2576 for (uint32_t i = 0; i < storage_->metadata_table().row_count(); i++) {
2577 meta_entries.emplace_back(
2578 std::make_pair(meta_keys.GetString(i), meta_values.GetString(i)));
2579 }
2580 EXPECT_THAT(meta_entries,
2581 UnorderedElementsAreArray({std::make_pair(benchmark, kName),
2582 std::make_pair(tags, kTag1),
2583 std::make_pair(tags, kTag2)}));
2584 }
2585
TEST_F(ProtoTraceParserTest,LoadChromeMetadata)2586 TEST_F(ProtoTraceParserTest, LoadChromeMetadata) {
2587 auto* track_event = trace_->add_packet()->set_chrome_events();
2588 {
2589 auto* metadata = track_event->add_metadata();
2590 metadata->set_name("str_name");
2591 metadata->set_string_value("foostr");
2592 }
2593
2594 {
2595 auto* metadata = track_event->add_metadata();
2596 metadata->set_name("int_name");
2597 metadata->set_int_value(42);
2598 }
2599
2600 {
2601 auto* metadata = track_event->add_metadata();
2602 metadata->set_name("bool_name");
2603 metadata->set_bool_value(true);
2604 }
2605
2606 {
2607 auto* metadata = track_event->add_metadata();
2608 metadata->set_name("json_name");
2609 metadata->set_json_value("{key: value}");
2610 }
2611
2612 Tokenize();
2613 context_.sorter->ExtractEventsForced();
2614
2615 const auto& metadata = storage_->metadata_table();
2616
2617 EXPECT_STREQ(metadata.name().GetString(0).c_str(), "cr-str_name");
2618 EXPECT_STREQ(metadata.str_value().GetString(0).c_str(), "foostr");
2619
2620 EXPECT_STREQ(metadata.name().GetString(1).c_str(), "cr-int_name");
2621 EXPECT_EQ(metadata.int_value()[1], 42);
2622
2623 EXPECT_STREQ(metadata.name().GetString(2).c_str(), "cr-bool_name");
2624 EXPECT_EQ(metadata.int_value()[2], 1);
2625
2626 EXPECT_STREQ(metadata.name().GetString(3).c_str(), "cr-json_name");
2627 EXPECT_STREQ(metadata.str_value().GetString(3).c_str(), "{key: value}");
2628 }
2629
TEST_F(ProtoTraceParserTest,AndroidPackagesList)2630 TEST_F(ProtoTraceParserTest, AndroidPackagesList) {
2631 auto* packet = trace_->add_packet();
2632 auto* pkg_list = packet->set_packages_list();
2633
2634 pkg_list->set_read_error(false);
2635 pkg_list->set_parse_error(true);
2636 {
2637 auto* pkg = pkg_list->add_packages();
2638 pkg->set_name("com.test.app");
2639 pkg->set_uid(1000);
2640 pkg->set_debuggable(false);
2641 pkg->set_profileable_from_shell(true);
2642 pkg->set_version_code(42);
2643 }
2644 {
2645 auto* pkg = pkg_list->add_packages();
2646 pkg->set_name("com.test.app2");
2647 pkg->set_uid(1001);
2648 pkg->set_debuggable(false);
2649 pkg->set_profileable_from_shell(false);
2650 pkg->set_version_code(43);
2651 }
2652
2653 Tokenize();
2654 context_.sorter->ExtractEventsForced();
2655
2656 // Packet-level errors reflected in stats storage.
2657 const auto& stats = context_.storage->stats();
2658 EXPECT_FALSE(stats[stats::packages_list_has_read_errors].value);
2659 EXPECT_TRUE(stats[stats::packages_list_has_parse_errors].value);
2660
2661 // Expect two metadata rows, each with an int_value of a separate arg set id.
2662 // The relevant arg sets have the info about the packages. To simplify test
2663 // structure, make an assumption that metadata storage is filled in in the
2664 // FIFO order of seen packages.
2665 const auto& package_list = context_.storage->package_list_table();
2666 ASSERT_EQ(package_list.row_count(), 2u);
2667
2668 EXPECT_STREQ(storage_->GetString(package_list.package_name()[0]).c_str(),
2669 "com.test.app");
2670 EXPECT_EQ(package_list.uid()[0], 1000u);
2671 EXPECT_EQ(package_list.debuggable()[0], false);
2672 EXPECT_EQ(package_list.profileable_from_shell()[0], true);
2673 EXPECT_EQ(package_list.version_code()[0], 42);
2674
2675 EXPECT_STREQ(storage_->GetString(package_list.package_name()[1]).c_str(),
2676 "com.test.app2");
2677 EXPECT_EQ(package_list.uid()[1], 1001u);
2678 EXPECT_EQ(package_list.debuggable()[1], false);
2679 EXPECT_EQ(package_list.profileable_from_shell()[1], false);
2680 EXPECT_EQ(package_list.version_code()[1], 43);
2681 }
2682
TEST_F(ProtoTraceParserTest,AndroidPackagesListDuplicate)2683 TEST_F(ProtoTraceParserTest, AndroidPackagesListDuplicate) {
2684 auto* packet = trace_->add_packet();
2685 auto* pkg_list = packet->set_packages_list();
2686
2687 pkg_list->set_read_error(false);
2688 pkg_list->set_parse_error(true);
2689 {
2690 auto* pkg = pkg_list->add_packages();
2691 pkg->set_name("com.test.app");
2692 pkg->set_uid(1000);
2693 pkg->set_debuggable(false);
2694 pkg->set_profileable_from_shell(true);
2695 pkg->set_version_code(42);
2696 }
2697 {
2698 auto* pkg = pkg_list->add_packages();
2699 pkg->set_name("com.test.app");
2700 pkg->set_uid(1000);
2701 pkg->set_debuggable(false);
2702 pkg->set_profileable_from_shell(true);
2703 pkg->set_version_code(42);
2704 }
2705
2706 Tokenize();
2707 context_.sorter->ExtractEventsForced();
2708
2709 // Packet-level errors reflected in stats storage.
2710 const auto& stats = context_.storage->stats();
2711 EXPECT_FALSE(stats[stats::packages_list_has_read_errors].value);
2712 EXPECT_TRUE(stats[stats::packages_list_has_parse_errors].value);
2713
2714 // Expect two metadata rows, each with an int_value of a separate arg set id.
2715 // The relevant arg sets have the info about the packages. To simplify test
2716 // structure, make an assumption that metadata storage is filled in in the
2717 // FIFO order of seen packages.
2718 const auto& package_list = context_.storage->package_list_table();
2719 ASSERT_EQ(package_list.row_count(), 1u);
2720
2721 EXPECT_STREQ(storage_->GetString(package_list.package_name()[0]).c_str(),
2722 "com.test.app");
2723 EXPECT_EQ(package_list.uid()[0], 1000u);
2724 EXPECT_EQ(package_list.debuggable()[0], false);
2725 EXPECT_EQ(package_list.profileable_from_shell()[0], true);
2726 EXPECT_EQ(package_list.version_code()[0], 42);
2727 }
2728
TEST_F(ProtoTraceParserTest,ParseCPUProfileSamplesIntoTable)2729 TEST_F(ProtoTraceParserTest, ParseCPUProfileSamplesIntoTable) {
2730 {
2731 auto* packet = trace_->add_packet();
2732 packet->set_trusted_packet_sequence_id(1);
2733 packet->set_incremental_state_cleared(true);
2734
2735 auto* thread_desc = packet->set_thread_descriptor();
2736 thread_desc->set_pid(15);
2737 thread_desc->set_tid(16);
2738 thread_desc->set_reference_timestamp_us(1);
2739 thread_desc->set_reference_thread_time_us(2);
2740
2741 auto* interned_data = packet->set_interned_data();
2742
2743 auto mapping = interned_data->add_mappings();
2744 mapping->set_iid(1);
2745 mapping->set_build_id(1);
2746
2747 auto build_id = interned_data->add_build_ids();
2748 build_id->set_iid(1);
2749 build_id->set_str("3BBCFBD372448A727265C3E7C4D954F91");
2750
2751 auto frame = interned_data->add_frames();
2752 frame->set_iid(1);
2753 frame->set_rel_pc(0x42);
2754 frame->set_mapping_id(1);
2755
2756 auto frame2 = interned_data->add_frames();
2757 frame2->set_iid(2);
2758 frame2->set_rel_pc(0x4242);
2759 frame2->set_mapping_id(1);
2760
2761 auto callstack = interned_data->add_callstacks();
2762 callstack->set_iid(1);
2763 callstack->add_frame_ids(1);
2764
2765 auto callstack2 = interned_data->add_callstacks();
2766 callstack2->set_iid(42);
2767 callstack2->add_frame_ids(2);
2768 }
2769
2770 {
2771 auto* packet = trace_->add_packet();
2772 packet->set_trusted_packet_sequence_id(1);
2773
2774 auto* samples = packet->set_streaming_profile_packet();
2775 samples->add_callstack_iid(42);
2776 samples->add_timestamp_delta_us(10);
2777
2778 samples->add_callstack_iid(1);
2779 samples->add_timestamp_delta_us(15);
2780 samples->set_process_priority(20);
2781 }
2782
2783 {
2784 auto* packet = trace_->add_packet();
2785 packet->set_trusted_packet_sequence_id(1);
2786 auto* samples = packet->set_streaming_profile_packet();
2787
2788 samples->add_callstack_iid(42);
2789 samples->add_timestamp_delta_us(42);
2790 samples->set_process_priority(30);
2791 }
2792
2793 EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
2794
2795 Tokenize();
2796 context_.sorter->ExtractEventsForced();
2797
2798 // Verify cpu_profile_samples.
2799 const auto& samples = storage_->cpu_profile_stack_sample_table();
2800 EXPECT_EQ(samples.row_count(), 3u);
2801
2802 EXPECT_EQ(samples.ts()[0], 11000);
2803 EXPECT_EQ(samples.callsite_id()[0], CallsiteId{0});
2804 EXPECT_EQ(samples.utid()[0], 1u);
2805 EXPECT_EQ(samples.process_priority()[0], 20);
2806
2807 EXPECT_EQ(samples.ts()[1], 26000);
2808 EXPECT_EQ(samples.callsite_id()[1], CallsiteId{1});
2809 EXPECT_EQ(samples.utid()[1], 1u);
2810 EXPECT_EQ(samples.process_priority()[1], 20);
2811
2812 EXPECT_EQ(samples.ts()[2], 68000);
2813 EXPECT_EQ(samples.callsite_id()[2], CallsiteId{0});
2814 EXPECT_EQ(samples.utid()[2], 1u);
2815 EXPECT_EQ(samples.process_priority()[2], 30);
2816
2817 // Breakpad build_ids should not be modified/mangled.
2818 ASSERT_STREQ(
2819 context_.storage
2820 ->GetString(storage_->stack_profile_mapping_table().build_id()[0])
2821 .c_str(),
2822 "3BBCFBD372448A727265C3E7C4D954F91");
2823 }
2824
TEST_F(ProtoTraceParserTest,CPUProfileSamplesTimestampsAreClockMonotonic)2825 TEST_F(ProtoTraceParserTest, CPUProfileSamplesTimestampsAreClockMonotonic) {
2826 {
2827 auto* packet = trace_->add_packet();
2828 packet->set_trusted_packet_sequence_id(0);
2829
2830 // 1000 us monotonic == 10000 us boottime.
2831 auto* clock_snapshot = packet->set_clock_snapshot();
2832 auto* clock_boot = clock_snapshot->add_clocks();
2833 clock_boot->set_clock_id(protos::pbzero::BUILTIN_CLOCK_BOOTTIME);
2834 clock_boot->set_timestamp(10000000);
2835 auto* clock_monotonic = clock_snapshot->add_clocks();
2836 clock_monotonic->set_clock_id(protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
2837 clock_monotonic->set_timestamp(1000000);
2838 }
2839
2840 {
2841 auto* packet = trace_->add_packet();
2842 packet->set_trusted_packet_sequence_id(1);
2843 packet->set_incremental_state_cleared(true);
2844
2845 auto* thread_desc = packet->set_thread_descriptor();
2846 thread_desc->set_pid(15);
2847 thread_desc->set_tid(16);
2848 thread_desc->set_reference_timestamp_us(1000);
2849 thread_desc->set_reference_thread_time_us(2000);
2850
2851 auto* interned_data = packet->set_interned_data();
2852
2853 auto mapping = interned_data->add_mappings();
2854 mapping->set_iid(1);
2855 mapping->set_build_id(1);
2856
2857 auto build_id = interned_data->add_build_ids();
2858 build_id->set_iid(1);
2859 build_id->set_str("3BBCFBD372448A727265C3E7C4D954F91");
2860
2861 auto frame = interned_data->add_frames();
2862 frame->set_iid(1);
2863 frame->set_rel_pc(0x42);
2864 frame->set_mapping_id(1);
2865
2866 auto callstack = interned_data->add_callstacks();
2867 callstack->set_iid(1);
2868 callstack->add_frame_ids(1);
2869 }
2870
2871 {
2872 auto* packet = trace_->add_packet();
2873 packet->set_trusted_packet_sequence_id(1);
2874
2875 auto* samples = packet->set_streaming_profile_packet();
2876 samples->add_callstack_iid(1);
2877 samples->add_timestamp_delta_us(15);
2878 }
2879
2880 EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
2881
2882 Tokenize();
2883 context_.sorter->ExtractEventsForced();
2884
2885 const auto& samples = storage_->cpu_profile_stack_sample_table();
2886 EXPECT_EQ(samples.row_count(), 1u);
2887
2888 // Should have been translated to boottime, i.e. 10015 us absolute.
2889 EXPECT_EQ(samples.ts()[0], 10015000);
2890 EXPECT_EQ(samples.callsite_id()[0], CallsiteId{0});
2891 EXPECT_EQ(samples.utid()[0], 1u);
2892 }
2893
TEST_F(ProtoTraceParserTest,ConfigUuid)2894 TEST_F(ProtoTraceParserTest, ConfigUuid) {
2895 auto* config = trace_->add_packet()->set_trace_config();
2896 config->set_trace_uuid_lsb(1);
2897 config->set_trace_uuid_msb(2);
2898
2899 ASSERT_TRUE(Tokenize().ok());
2900 context_.sorter->ExtractEventsForced();
2901
2902 SqlValue value = context_.metadata_tracker->GetMetadata(metadata::trace_uuid);
2903 EXPECT_STREQ(value.string_value, "00000000-0000-0002-0000-000000000001");
2904 ASSERT_TRUE(context_.uuid_found_in_trace);
2905 }
2906
TEST_F(ProtoTraceParserTest,PacketUuid)2907 TEST_F(ProtoTraceParserTest, PacketUuid) {
2908 auto* uuid = trace_->add_packet()->set_trace_uuid();
2909 uuid->set_lsb(1);
2910 uuid->set_msb(2);
2911
2912 ASSERT_TRUE(Tokenize().ok());
2913 context_.sorter->ExtractEventsForced();
2914
2915 SqlValue value = context_.metadata_tracker->GetMetadata(metadata::trace_uuid);
2916 EXPECT_STREQ(value.string_value, "00000000-0000-0002-0000-000000000001");
2917 ASSERT_TRUE(context_.uuid_found_in_trace);
2918 }
2919
2920 // If both the TraceConfig and TracePacket.trace_uuid are present, the latter
2921 // is considered the source of truth.
TEST_F(ProtoTraceParserTest,PacketAndConfigUuid)2922 TEST_F(ProtoTraceParserTest, PacketAndConfigUuid) {
2923 auto* uuid = trace_->add_packet()->set_trace_uuid();
2924 uuid->set_lsb(1);
2925 uuid->set_msb(2);
2926
2927 auto* config = trace_->add_packet()->set_trace_config();
2928 config->set_trace_uuid_lsb(42);
2929 config->set_trace_uuid_msb(42);
2930
2931 ASSERT_TRUE(Tokenize().ok());
2932 context_.sorter->ExtractEventsForced();
2933
2934 SqlValue value = context_.metadata_tracker->GetMetadata(metadata::trace_uuid);
2935 EXPECT_STREQ(value.string_value, "00000000-0000-0002-0000-000000000001");
2936 ASSERT_TRUE(context_.uuid_found_in_trace);
2937 }
2938
TEST_F(ProtoTraceParserTest,ConfigPbtxt)2939 TEST_F(ProtoTraceParserTest, ConfigPbtxt) {
2940 auto* config = trace_->add_packet()->set_trace_config();
2941 config->add_buffers()->set_size_kb(42);
2942
2943 ASSERT_TRUE(Tokenize().ok());
2944 context_.sorter->ExtractEventsForced();
2945
2946 SqlValue value =
2947 context_.metadata_tracker->GetMetadata(metadata::trace_config_pbtxt);
2948 EXPECT_THAT(value.string_value, HasSubstr("size_kb: 42"));
2949 }
2950
2951 } // namespace
2952 } // namespace trace_processor
2953 } // namespace perfetto
2954