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