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