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