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