blob: 2444215d5a16f352007edb7cc569079cf513e834 [file] [log] [blame]
/*
* Copyright (C) 2018 The Android Open Source Project
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
#include "src/trace_processor/importers/proto/proto_trace_reader.h"
#include "perfetto/base/logging.h"
#include "perfetto/ext/base/string_view.h"
#include "perfetto/protozero/scattered_heap_buffer.h"
#include "perfetto/trace_processor/trace_blob.h"
#include "src/trace_processor/importers/common/args_tracker.h"
#include "src/trace_processor/importers/common/args_translation_table.h"
#include "src/trace_processor/importers/common/clock_tracker.h"
#include "src/trace_processor/importers/common/event_tracker.h"
#include "src/trace_processor/importers/common/flow_tracker.h"
#include "src/trace_processor/importers/common/metadata_tracker.h"
#include "src/trace_processor/importers/common/process_tracker.h"
#include "src/trace_processor/importers/common/slice_tracker.h"
#include "src/trace_processor/importers/common/track_tracker.h"
#include "src/trace_processor/importers/ftrace/sched_event_tracker.h"
#include "src/trace_processor/importers/proto/additional_modules.h"
#include "src/trace_processor/importers/proto/default_modules.h"
#include "src/trace_processor/importers/proto/proto_trace_parser.h"
#include "src/trace_processor/importers/proto/stack_profile_tracker.h"
#include "src/trace_processor/sorter/trace_sorter.h"
#include "src/trace_processor/storage/metadata.h"
#include "src/trace_processor/storage/trace_storage.h"
#include "src/trace_processor/util/descriptors.h"
#include "test/gtest_and_gmock.h"
#include "protos/perfetto/common/builtin_clock.pbzero.h"
#include "protos/perfetto/common/sys_stats_counters.pbzero.h"
#include "protos/perfetto/config/trace_config.pbzero.h"
#include "protos/perfetto/trace/android/packages_list.pbzero.h"
#include "protos/perfetto/trace/chrome/chrome_benchmark_metadata.pbzero.h"
#include "protos/perfetto/trace/chrome/chrome_trace_event.pbzero.h"
#include "protos/perfetto/trace/clock_snapshot.pbzero.h"
#include "protos/perfetto/trace/ftrace/ftrace.pbzero.h"
#include "protos/perfetto/trace/ftrace/ftrace_event.pbzero.h"
#include "protos/perfetto/trace/ftrace/ftrace_event_bundle.pbzero.h"
#include "protos/perfetto/trace/ftrace/generic.pbzero.h"
#include "protos/perfetto/trace/ftrace/power.pbzero.h"
#include "protos/perfetto/trace/ftrace/sched.pbzero.h"
#include "protos/perfetto/trace/ftrace/task.pbzero.h"
#include "protos/perfetto/trace/interned_data/interned_data.pbzero.h"
#include "protos/perfetto/trace/profiling/profile_packet.pbzero.h"
#include "protos/perfetto/trace/ps/process_tree.pbzero.h"
#include "protos/perfetto/trace/sys_stats/sys_stats.pbzero.h"
#include "protos/perfetto/trace/trace.pbzero.h"
#include "protos/perfetto/trace/trace_packet.pbzero.h"
#include "protos/perfetto/trace/trace_uuid.pbzero.h"
#include "protos/perfetto/trace/track_event/chrome_thread_descriptor.pbzero.h"
#include "protos/perfetto/trace/track_event/counter_descriptor.pbzero.h"
#include "protos/perfetto/trace/track_event/debug_annotation.pbzero.h"
#include "protos/perfetto/trace/track_event/log_message.pbzero.h"
#include "protos/perfetto/trace/track_event/process_descriptor.pbzero.h"
#include "protos/perfetto/trace/track_event/source_location.pbzero.h"
#include "protos/perfetto/trace/track_event/task_execution.pbzero.h"
#include "protos/perfetto/trace/track_event/thread_descriptor.pbzero.h"
#include "protos/perfetto/trace/track_event/track_descriptor.pbzero.h"
#include "protos/perfetto/trace/track_event/track_event.pbzero.h"
namespace perfetto {
namespace trace_processor {
namespace {
using ::testing::_;
using ::testing::Args;
using ::testing::AtLeast;
using ::testing::DoAll;
using ::testing::ElementsAreArray;
using ::testing::Eq;
using ::testing::HasSubstr;
using ::testing::IgnoreResult;
using ::testing::InSequence;
using ::testing::Invoke;
using ::testing::InvokeArgument;
using ::testing::NiceMock;
using ::testing::Pointwise;
using ::testing::Return;
using ::testing::ReturnRef;
using ::testing::UnorderedElementsAreArray;
namespace {
MATCHER_P(DoubleEq, exp, "Double matcher that satisfies -Wfloat-equal") {
// The IEEE standard says that any comparison operation involving
// a NAN must return false.
double d_exp = exp;
double d_arg = arg;
if (isnan(d_exp) || isnan(d_arg))
return false;
return fabs(d_arg - d_exp) < 1e-128;
}
} // namespace
class MockSchedEventTracker : public SchedEventTracker {
public:
explicit MockSchedEventTracker(TraceProcessorContext* context)
: SchedEventTracker(context) {}
MOCK_METHOD(void,
PushSchedSwitch,
(uint32_t cpu,
int64_t timestamp,
uint32_t prev_pid,
base::StringView prev_comm,
int32_t prev_prio,
int64_t prev_state,
uint32_t next_pid,
base::StringView next_comm,
int32_t next_prio),
(override));
};
class MockEventTracker : public EventTracker {
public:
explicit MockEventTracker(TraceProcessorContext* context)
: EventTracker(context) {}
~MockEventTracker() override = default;
MOCK_METHOD(void,
PushSchedSwitch,
(uint32_t cpu,
int64_t timestamp,
uint32_t prev_pid,
base::StringView prev_comm,
int32_t prev_prio,
int64_t prev_state,
uint32_t next_pid,
base::StringView next_comm,
int32_t next_prio));
MOCK_METHOD(std::optional<CounterId>,
PushCounter,
(int64_t timestamp, double value, TrackId track_id),
(override));
};
class MockProcessTracker : public ProcessTracker {
public:
explicit MockProcessTracker(TraceProcessorContext* context)
: ProcessTracker(context) {}
MOCK_METHOD(UniquePid,
SetProcessMetadata,
(uint32_t pid,
std::optional<uint32_t> ppid,
base::StringView process_name,
base::StringView cmdline),
(override));
MOCK_METHOD(UniqueTid,
UpdateThreadName,
(uint32_t tid,
StringId thread_name_id,
ThreadNamePriority priority),
(override));
MOCK_METHOD(void,
UpdateThreadNameByUtid,
(UniqueTid utid,
StringId thread_name_id,
ThreadNamePriority priority),
(override));
MOCK_METHOD(UniqueTid,
UpdateThread,
(uint32_t tid, uint32_t tgid),
(override));
MOCK_METHOD(UniquePid, GetOrCreateProcess, (uint32_t pid), (override));
MOCK_METHOD(void,
SetProcessNameIfUnset,
(UniquePid upid, StringId process_name_id),
(override));
};
class MockBoundInserter : public ArgsTracker::BoundInserter {
public:
MockBoundInserter()
: ArgsTracker::BoundInserter(&tracker_, nullptr, 0u), tracker_(nullptr) {
ON_CALL(*this, AddArg(_, _, _, _)).WillByDefault(ReturnRef(*this));
}
MOCK_METHOD(ArgsTracker::BoundInserter&,
AddArg,
(StringId flat_key,
StringId key,
Variadic v,
ArgsTracker::UpdatePolicy update_policy),
(override));
private:
ArgsTracker tracker_;
};
class MockSliceTracker : public SliceTracker {
public:
explicit MockSliceTracker(TraceProcessorContext* context)
: SliceTracker(context) {}
MOCK_METHOD(std::optional<SliceId>,
Begin,
(int64_t timestamp,
TrackId track_id,
StringId cat,
StringId name,
SetArgsCallback args_callback),
(override));
MOCK_METHOD(std::optional<SliceId>,
End,
(int64_t timestamp,
TrackId track_id,
StringId cat,
StringId name,
SetArgsCallback args_callback),
(override));
MOCK_METHOD(std::optional<SliceId>,
Scoped,
(int64_t timestamp,
TrackId track_id,
StringId cat,
StringId name,
int64_t duration,
SetArgsCallback args_callback),
(override));
MOCK_METHOD(std::optional<SliceId>,
StartSlice,
(int64_t timestamp,
TrackId track_id,
SetArgsCallback args_callback,
std::function<SliceId()> inserter),
(override));
};
class ProtoTraceParserTest : public ::testing::Test {
public:
ProtoTraceParserTest() {
storage_ = new TraceStorage();
context_.storage.reset(storage_);
context_.track_tracker.reset(new TrackTracker(&context_));
context_.global_args_tracker.reset(
new GlobalArgsTracker(context_.storage.get()));
context_.global_stack_profile_tracker.reset(
new GlobalStackProfileTracker());
context_.args_tracker.reset(new ArgsTracker(&context_));
context_.args_translation_table.reset(new ArgsTranslationTable(storage_));
context_.metadata_tracker.reset(
new MetadataTracker(context_.storage.get()));
event_ = new MockEventTracker(&context_);
context_.event_tracker.reset(event_);
sched_ = new MockSchedEventTracker(&context_);
context_.sched_tracker.reset(sched_);
process_ = new NiceMock<MockProcessTracker>(&context_);
context_.process_tracker.reset(process_);
slice_ = new NiceMock<MockSliceTracker>(&context_);
context_.slice_tracker.reset(slice_);
context_.slice_translation_table.reset(new SliceTranslationTable(storage_));
clock_ = new ClockTracker(&context_);
context_.clock_tracker.reset(clock_);
context_.flow_tracker.reset(new FlowTracker(&context_));
context_.sorter.reset(new TraceSorter(&context_, CreateParser(),
TraceSorter::SortingMode::kFullSort));
context_.descriptor_pool_.reset(new DescriptorPool());
RegisterDefaultModules(&context_);
RegisterAdditionalModules(&context_);
}
void ResetTraceBuffers() { trace_.Reset(); }
void SetUp() override { ResetTraceBuffers(); }
util::Status Tokenize() {
trace_->Finalize();
std::vector<uint8_t> trace_bytes = trace_.SerializeAsArray();
std::unique_ptr<uint8_t[]> raw_trace(new uint8_t[trace_bytes.size()]);
memcpy(raw_trace.get(), trace_bytes.data(), trace_bytes.size());
context_.chunk_reader.reset(new ProtoTraceReader(&context_));
auto status = context_.chunk_reader->Parse(TraceBlobView(
TraceBlob::TakeOwnership(std::move(raw_trace), trace_bytes.size())));
ResetTraceBuffers();
return status;
}
bool HasArg(ArgSetId set_id, StringId key_id, Variadic value) {
const auto& args = storage_->arg_table();
RowMap rm = args.FilterToRowMap({args.arg_set_id().eq(set_id)});
bool found = false;
for (auto it = rm.IterateRows(); it; it.Next()) {
if (args.key()[it.index()] == key_id) {
EXPECT_EQ(args.flat_key()[it.index()], key_id);
if (storage_->GetArgValue(it.index()) == value) {
found = true;
break;
}
}
}
return found;
}
protected:
std::unique_ptr<TraceParser> CreateParser() {
return std::unique_ptr<TraceParser>(new ProtoTraceParser(&context_));
}
protozero::HeapBuffered<protos::pbzero::Trace> trace_;
TraceProcessorContext context_;
MockEventTracker* event_;
MockSchedEventTracker* sched_;
MockProcessTracker* process_;
MockSliceTracker* slice_;
ClockTracker* clock_;
TraceStorage* storage_;
};
// TODO(eseckler): Refactor these into a new file for ftrace tests.
TEST_F(ProtoTraceParserTest, LoadSingleEvent) {
auto* bundle = trace_->add_packet()->set_ftrace_events();
bundle->set_cpu(10);
auto* event = bundle->add_event();
event->set_timestamp(1000);
event->set_pid(12);
static const char kProc1Name[] = "proc1";
static const char kProc2Name[] = "proc2";
auto* sched_switch = event->set_sched_switch();
sched_switch->set_prev_pid(10);
sched_switch->set_prev_comm(kProc2Name);
sched_switch->set_prev_prio(256);
sched_switch->set_prev_state(32);
sched_switch->set_next_comm(kProc1Name);
sched_switch->set_next_pid(100);
sched_switch->set_next_prio(1024);
EXPECT_CALL(*sched_,
PushSchedSwitch(10, 1000, 10, base::StringView(kProc2Name), 256,
32, 100, base::StringView(kProc1Name), 1024));
Tokenize();
context_.sorter->ExtractEventsForced();
}
TEST_F(ProtoTraceParserTest, LoadEventsIntoRaw) {
auto* bundle = trace_->add_packet()->set_ftrace_events();
bundle->set_cpu(10);
// This event is unknown and will only appear in
// raw events table.
auto* event = bundle->add_event();
event->set_timestamp(1000);
event->set_pid(12);
auto* task = event->set_task_newtask();
task->set_pid(123);
static const char task_newtask[] = "task_newtask";
task->set_comm(task_newtask);
task->set_clone_flags(12);
task->set_oom_score_adj(15);
// This event has specific parsing logic, but will
// also appear in raw events table.
event = bundle->add_event();
event->set_timestamp(1001);
event->set_pid(12);
auto* print = event->set_print();
print->set_ip(20);
static const char buf_value[] = "This is a print event";
print->set_buf(buf_value);
EXPECT_CALL(*process_, GetOrCreateProcess(123));
Tokenize();
context_.sorter->ExtractEventsForced();
const auto& raw = context_.storage->raw_table();
ASSERT_EQ(raw.row_count(), 2u);
const auto& args = context_.storage->arg_table();
ASSERT_EQ(args.row_count(), 6u);
// Order is by row and then by StringIds.
ASSERT_EQ(args.key()[0], context_.storage->InternString("comm"));
ASSERT_EQ(args.key()[1], context_.storage->InternString("pid"));
ASSERT_EQ(args.key()[2], context_.storage->InternString("oom_score_adj"));
ASSERT_EQ(args.key()[3], context_.storage->InternString("clone_flags"));
ASSERT_EQ(args.key()[4], context_.storage->InternString("ip"));
ASSERT_EQ(args.key()[5], context_.storage->InternString("buf"));
ASSERT_STREQ(args.string_value().GetString(0).c_str(), task_newtask);
ASSERT_EQ(args.int_value()[1], 123);
ASSERT_EQ(args.int_value()[2], 15);
ASSERT_EQ(args.int_value()[3], 12);
ASSERT_EQ(args.int_value()[4], 20);
ASSERT_STREQ(args.string_value().GetString(5).c_str(), buf_value);
// TODO(hjd): Add test ftrace event with all field types
// and test here.
}
TEST_F(ProtoTraceParserTest, LoadGenericFtrace) {
auto* packet = trace_->add_packet();
packet->set_timestamp(100);
auto* bundle = packet->set_ftrace_events();
bundle->set_cpu(4);
auto* ftrace = bundle->add_event();
ftrace->set_timestamp(100);
ftrace->set_pid(10);
auto* generic = ftrace->set_generic();
generic->set_event_name("Test");
auto* field = generic->add_field();
field->set_name("meta1");
field->set_str_value("value1");
field = generic->add_field();
field->set_name("meta2");
field->set_int_value(-2);
field = generic->add_field();
field->set_name("meta3");
field->set_uint_value(3);
Tokenize();
context_.sorter->ExtractEventsForced();
const auto& raw = storage_->raw_table();
ASSERT_EQ(raw.row_count(), 1u);
ASSERT_EQ(raw.ts()[raw.row_count() - 1], 100);
ASSERT_EQ(storage_->thread_table().tid()[raw.utid()[raw.row_count() - 1]],
10u);
ASSERT_EQ(raw.name().GetString(raw.row_count() - 1), "Test");
auto set_id = raw.arg_set_id()[raw.row_count() - 1];
const auto& args = storage_->arg_table();
RowMap rm = args.FilterToRowMap({args.arg_set_id().eq(set_id)});
auto row = rm.Get(0);
ASSERT_EQ(args.key().GetString(row), "meta1");
ASSERT_EQ(args.string_value().GetString(row++), "value1");
ASSERT_EQ(args.key().GetString(row), "meta2");
ASSERT_EQ(args.int_value()[row++], -2);
ASSERT_EQ(args.key().GetString(row), "meta3");
ASSERT_EQ(args.int_value()[row++], 3);
}
TEST_F(ProtoTraceParserTest, LoadMultipleEvents) {
auto* bundle = trace_->add_packet()->set_ftrace_events();
bundle->set_cpu(10);
auto* event = bundle->add_event();
event->set_timestamp(1000);
event->set_pid(12);
static const char kProcName1[] = "proc1";
static const char kProcName2[] = "proc2";
auto* sched_switch = event->set_sched_switch();
sched_switch->set_prev_pid(10);
sched_switch->set_prev_comm(kProcName2);
sched_switch->set_prev_prio(256);
sched_switch->set_prev_state(32);
sched_switch->set_next_comm(kProcName1);
sched_switch->set_next_pid(100);
sched_switch->set_next_prio(1024);
event = bundle->add_event();
event->set_timestamp(1001);
event->set_pid(12);
sched_switch = event->set_sched_switch();
sched_switch->set_prev_pid(100);
sched_switch->set_prev_comm(kProcName1);
sched_switch->set_prev_prio(256);
sched_switch->set_prev_state(32);
sched_switch->set_next_comm(kProcName2);
sched_switch->set_next_pid(10);
sched_switch->set_next_prio(512);
EXPECT_CALL(*sched_,
PushSchedSwitch(10, 1000, 10, base::StringView(kProcName2), 256,
32, 100, base::StringView(kProcName1), 1024));
EXPECT_CALL(*sched_,
PushSchedSwitch(10, 1001, 100, base::StringView(kProcName1), 256,
32, 10, base::StringView(kProcName2), 512));
Tokenize();
context_.sorter->ExtractEventsForced();
}
TEST_F(ProtoTraceParserTest, LoadMultiplePackets) {
auto* bundle = trace_->add_packet()->set_ftrace_events();
bundle->set_cpu(10);
auto* event = bundle->add_event();
event->set_timestamp(1000);
event->set_pid(12);
static const char kProcName1[] = "proc1";
static const char kProcName2[] = "proc2";
auto* sched_switch = event->set_sched_switch();
sched_switch->set_prev_pid(10);
sched_switch->set_prev_comm(kProcName2);
sched_switch->set_prev_prio(256);
sched_switch->set_prev_state(32);
sched_switch->set_next_comm(kProcName1);
sched_switch->set_next_pid(100);
sched_switch->set_next_prio(1024);
bundle = trace_->add_packet()->set_ftrace_events();
bundle->set_cpu(10);
event = bundle->add_event();
event->set_timestamp(1001);
event->set_pid(12);
sched_switch = event->set_sched_switch();
sched_switch->set_prev_pid(100);
sched_switch->set_prev_comm(kProcName1);
sched_switch->set_prev_prio(256);
sched_switch->set_prev_state(32);
sched_switch->set_next_comm(kProcName2);
sched_switch->set_next_pid(10);
sched_switch->set_next_prio(512);
EXPECT_CALL(*sched_,
PushSchedSwitch(10, 1000, 10, base::StringView(kProcName2), 256,
32, 100, base::StringView(kProcName1), 1024));
EXPECT_CALL(*sched_,
PushSchedSwitch(10, 1001, 100, base::StringView(kProcName1), 256,
32, 10, base::StringView(kProcName2), 512));
Tokenize();
context_.sorter->ExtractEventsForced();
}
TEST_F(ProtoTraceParserTest, RepeatedLoadSinglePacket) {
auto* bundle = trace_->add_packet()->set_ftrace_events();
bundle->set_cpu(10);
auto* event = bundle->add_event();
event->set_timestamp(1000);
event->set_pid(12);
static const char kProcName1[] = "proc1";
static const char kProcName2[] = "proc2";
auto* sched_switch = event->set_sched_switch();
sched_switch->set_prev_pid(10);
sched_switch->set_prev_comm(kProcName2);
sched_switch->set_prev_prio(256);
sched_switch->set_prev_state(32);
sched_switch->set_next_comm(kProcName1);
sched_switch->set_next_pid(100);
sched_switch->set_next_prio(1024);
EXPECT_CALL(*sched_,
PushSchedSwitch(10, 1000, 10, base::StringView(kProcName2), 256,
32, 100, base::StringView(kProcName1), 1024));
Tokenize();
context_.sorter->ExtractEventsForced();
bundle = trace_->add_packet()->set_ftrace_events();
bundle->set_cpu(10);
event = bundle->add_event();
event->set_timestamp(1001);
event->set_pid(12);
sched_switch = event->set_sched_switch();
sched_switch->set_prev_pid(100);
sched_switch->set_prev_comm(kProcName1);
sched_switch->set_prev_prio(256);
sched_switch->set_prev_state(32);
sched_switch->set_next_comm(kProcName2);
sched_switch->set_next_pid(10);
sched_switch->set_next_prio(512);
EXPECT_CALL(*sched_,
PushSchedSwitch(10, 1001, 100, base::StringView(kProcName1), 256,
32, 10, base::StringView(kProcName2), 512));
Tokenize();
context_.sorter->ExtractEventsForced();
}
TEST_F(ProtoTraceParserTest, LoadCpuFreq) {
auto* bundle = trace_->add_packet()->set_ftrace_events();
bundle->set_cpu(12);
auto* event = bundle->add_event();
event->set_timestamp(1000);
event->set_pid(12);
auto* cpu_freq = event->set_cpu_frequency();
cpu_freq->set_cpu_id(10);
cpu_freq->set_state(2000);
EXPECT_CALL(*event_, PushCounter(1000, DoubleEq(2000), TrackId{0}));
Tokenize();
context_.sorter->ExtractEventsForced();
EXPECT_EQ(context_.storage->cpu_counter_track_table().cpu()[0], 10u);
}
TEST_F(ProtoTraceParserTest, LoadCpuFreqKHz) {
auto* packet = trace_->add_packet();
uint64_t ts = 1000;
packet->set_timestamp(ts);
auto* bundle = packet->set_sys_stats();
bundle->add_cpufreq_khz(2650000u);
bundle->add_cpufreq_khz(3698200u);
EXPECT_CALL(*event_, PushCounter(static_cast<int64_t>(ts), DoubleEq(2650000u),
TrackId{0u}));
EXPECT_CALL(*event_, PushCounter(static_cast<int64_t>(ts), DoubleEq(3698200u),
TrackId{1u}));
Tokenize();
context_.sorter->ExtractEventsForced();
EXPECT_EQ(context_.storage->track_table().row_count(), 2u);
EXPECT_EQ(context_.storage->cpu_counter_track_table().row_count(), 2u);
auto row = context_.storage->cpu_counter_track_table().FindById(TrackId(0));
EXPECT_EQ(context_.storage->GetString(row->name()), "cpufreq");
EXPECT_EQ(row->cpu(), 0u);
row = context_.storage->cpu_counter_track_table().FindById(TrackId(1));
EXPECT_EQ(row->cpu(), 1u);
}
TEST_F(ProtoTraceParserTest, LoadMemInfo) {
auto* packet = trace_->add_packet();
uint64_t ts = 1000;
packet->set_timestamp(ts);
auto* bundle = packet->set_sys_stats();
auto* meminfo = bundle->add_meminfo();
meminfo->set_key(protos::pbzero::MEMINFO_MEM_TOTAL);
uint32_t value = 10;
meminfo->set_value(value);
EXPECT_CALL(*event_, PushCounter(static_cast<int64_t>(ts),
DoubleEq(value * 1024.0), TrackId{0u}));
Tokenize();
context_.sorter->ExtractEventsForced();
EXPECT_EQ(context_.storage->track_table().row_count(), 1u);
}
TEST_F(ProtoTraceParserTest, LoadVmStats) {
auto* packet = trace_->add_packet();
uint64_t ts = 1000;
packet->set_timestamp(ts);
auto* bundle = packet->set_sys_stats();
auto* meminfo = bundle->add_vmstat();
meminfo->set_key(protos::pbzero::VMSTAT_COMPACT_SUCCESS);
uint32_t value = 10;
meminfo->set_value(value);
EXPECT_CALL(*event_, PushCounter(static_cast<int64_t>(ts), DoubleEq(value),
TrackId{0u}));
Tokenize();
context_.sorter->ExtractEventsForced();
EXPECT_EQ(context_.storage->track_table().row_count(), 1u);
}
TEST_F(ProtoTraceParserTest, LoadProcessPacket) {
auto* tree = trace_->add_packet()->set_process_tree();
auto* process = tree->add_processes();
static const char kProcName1[] = "proc1";
process->add_cmdline(kProcName1);
process->set_pid(1);
process->set_ppid(3);
EXPECT_CALL(*process_,
SetProcessMetadata(1, Eq(3u), base::StringView(kProcName1),
base::StringView(kProcName1)));
Tokenize();
context_.sorter->ExtractEventsForced();
}
TEST_F(ProtoTraceParserTest, LoadProcessPacket_FirstCmdline) {
auto* tree = trace_->add_packet()->set_process_tree();
auto* process = tree->add_processes();
static const char kProcName1[] = "proc1";
static const char kProcName2[] = "proc2";
process->add_cmdline(kProcName1);
process->add_cmdline(kProcName2);
process->set_pid(1);
process->set_ppid(3);
EXPECT_CALL(*process_,
SetProcessMetadata(1, Eq(3u), base::StringView(kProcName1),
base::StringView("proc1 proc2")));
Tokenize();
context_.sorter->ExtractEventsForced();
}
TEST_F(ProtoTraceParserTest, LoadThreadPacket) {
auto* tree = trace_->add_packet()->set_process_tree();
auto* thread = tree->add_threads();
thread->set_tid(1);
thread->set_tgid(2);
EXPECT_CALL(*process_, UpdateThread(1, 2));
Tokenize();
context_.sorter->ExtractEventsForced();
}
TEST_F(ProtoTraceParserTest, ProcessNameFromProcessDescriptor) {
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_incremental_state_cleared(true);
auto* process_desc = packet->set_process_descriptor();
process_desc->set_pid(15);
process_desc->set_process_name("OldProcessName");
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_incremental_state_cleared(true);
auto* process_desc = packet->set_process_descriptor();
process_desc->set_pid(15);
process_desc->set_process_name("NewProcessName");
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(2);
packet->set_incremental_state_cleared(true);
auto* process_desc = packet->set_process_descriptor();
process_desc->set_pid(16);
process_desc->set_process_name("DifferentProcessName");
}
EXPECT_CALL(*process_, GetOrCreateProcess(15))
.WillRepeatedly(testing::Return(1u));
EXPECT_CALL(*process_, GetOrCreateProcess(16)).WillOnce(testing::Return(2u));
EXPECT_CALL(*process_, SetProcessNameIfUnset(
1u, storage_->InternString("OldProcessName")));
// Packet with same thread, but different name should update the name.
EXPECT_CALL(*process_, SetProcessNameIfUnset(
1u, storage_->InternString("NewProcessName")));
EXPECT_CALL(*process_,
SetProcessNameIfUnset(
2u, storage_->InternString("DifferentProcessName")));
Tokenize();
context_.sorter->ExtractEventsForced();
}
TEST_F(ProtoTraceParserTest, ThreadNameFromThreadDescriptor) {
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_incremental_state_cleared(true);
auto* thread_desc = packet->set_thread_descriptor();
thread_desc->set_pid(15);
thread_desc->set_tid(16);
thread_desc->set_reference_timestamp_us(1000);
thread_desc->set_reference_thread_time_us(2000);
thread_desc->set_thread_name("OldThreadName");
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_incremental_state_cleared(true);
auto* thread_desc = packet->set_thread_descriptor();
thread_desc->set_pid(15);
thread_desc->set_tid(16);
thread_desc->set_reference_timestamp_us(1000);
thread_desc->set_reference_thread_time_us(2000);
thread_desc->set_thread_name("NewThreadName");
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(2);
packet->set_incremental_state_cleared(true);
auto* thread_desc = packet->set_thread_descriptor();
thread_desc->set_pid(15);
thread_desc->set_tid(11);
thread_desc->set_reference_timestamp_us(1000);
thread_desc->set_reference_thread_time_us(2000);
thread_desc->set_thread_name("DifferentThreadName");
}
EXPECT_CALL(*process_, UpdateThread(16, 15))
.WillRepeatedly(testing::Return(1u));
EXPECT_CALL(*process_, UpdateThread(11, 15)).WillOnce(testing::Return(2u));
EXPECT_CALL(*process_, UpdateThreadNameByUtid(
1u, storage_->InternString("OldThreadName"),
ThreadNamePriority::kTrackDescriptor));
// Packet with same thread, but different name should update the name.
EXPECT_CALL(*process_, UpdateThreadNameByUtid(
1u, storage_->InternString("NewThreadName"),
ThreadNamePriority::kTrackDescriptor));
EXPECT_CALL(*process_, UpdateThreadNameByUtid(
2u, storage_->InternString("DifferentThreadName"),
ThreadNamePriority::kTrackDescriptor));
Tokenize();
context_.sorter->ExtractEventsForced();
}
TEST_F(ProtoTraceParserTest, TrackEventWithoutInternedData) {
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_incremental_state_cleared(true);
auto* thread_desc = packet->set_thread_descriptor();
thread_desc->set_pid(15);
thread_desc->set_tid(16);
thread_desc->set_reference_timestamp_us(1000);
thread_desc->set_reference_thread_time_us(2000);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10); // absolute: 1010.
event->set_thread_time_delta_us(5); // absolute: 2005.
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('B');
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10); // absolute: 1020.
event->set_thread_time_delta_us(5); // absolute: 2010.
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('E');
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_absolute_us(1005);
event->set_thread_time_absolute_us(2003);
event->add_category_iids(2);
event->add_category_iids(3);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(2);
legacy_event->set_phase('X');
legacy_event->set_duration_us(23); // absolute end: 1028.
legacy_event->set_thread_duration_us(12); // absolute end: 2015.
}
Tokenize();
EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
tables::ThreadTable::Row row(16);
row.upid = 1u;
storage_->mutable_thread_table()->Insert(row);
MockBoundInserter inserter;
StringId unknown_cat = storage_->InternString("unknown(1)");
constexpr TrackId track{0u};
constexpr TrackId thread_time_track{1u};
InSequence in_sequence; // Below slices should be sorted by timestamp.
// Only the begin thread time can be imported into the counter table.
EXPECT_CALL(*event_, PushCounter(1005000, testing::DoubleEq(2003000),
thread_time_track));
EXPECT_CALL(*slice_, StartSlice(1005000, track, _, _))
.WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()),
InvokeArgument<2>(&inserter), Return(SliceId(0u))));
EXPECT_CALL(*event_, PushCounter(1010000, testing::DoubleEq(2005000),
thread_time_track));
EXPECT_CALL(*slice_, StartSlice(1010000, track, _, _))
.WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()),
InvokeArgument<2>(&inserter), Return(SliceId(1u))));
EXPECT_CALL(*event_, PushCounter(1020000, testing::DoubleEq(2010000),
thread_time_track));
EXPECT_CALL(*slice_, End(1020000, track, unknown_cat, kNullStringId, _))
.WillOnce(DoAll(InvokeArgument<4>(&inserter), Return(SliceId(1u))));
context_.sorter->ExtractEventsForced();
EXPECT_EQ(storage_->slice_table().row_count(), 2u);
auto id_0 = storage_->slice_table().id().IndexOf(SliceId(0u));
EXPECT_TRUE(id_0);
EXPECT_EQ(storage_->slice_table().thread_ts()[*id_0], 2003000);
EXPECT_EQ(storage_->slice_table().thread_dur()[*id_0], 12000);
auto id_1 = storage_->slice_table().id().IndexOf(SliceId(1u));
EXPECT_TRUE(id_1);
EXPECT_EQ(storage_->slice_table().thread_ts()[*id_1], 2005000);
EXPECT_EQ(storage_->slice_table().thread_dur()[*id_1], 5000);
}
TEST_F(ProtoTraceParserTest, TrackEventWithoutInternedDataWithTypes) {
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_incremental_state_cleared(true);
auto* thread_desc = packet->set_thread_descriptor();
thread_desc->set_pid(15);
thread_desc->set_tid(16);
thread_desc->set_reference_timestamp_us(1000);
thread_desc->set_reference_thread_time_us(2000);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10); // absolute: 1010.
event->set_thread_time_delta_us(5); // absolute: 2005.
event->add_category_iids(1);
event->set_type(protos::pbzero::TrackEvent::TYPE_SLICE_BEGIN);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10); // absolute: 1020.
event->set_thread_time_delta_us(5); // absolute: 2010.
event->add_category_iids(1);
event->set_type(protos::pbzero::TrackEvent::TYPE_SLICE_END);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_absolute_us(1015);
event->set_thread_time_absolute_us(2007);
event->add_category_iids(2);
event->set_type(protos::pbzero::TrackEvent::TYPE_INSTANT);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(2);
}
Tokenize();
EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
tables::ThreadTable::Row row(16);
row.upid = 1u;
storage_->mutable_thread_table()->Insert(row);
MockBoundInserter inserter;
StringId unknown_cat1 = storage_->InternString("unknown(1)");
constexpr TrackId track{0u};
constexpr TrackId thread_time_track{1u};
InSequence in_sequence; // Below slices should be sorted by timestamp.
EXPECT_CALL(*event_, PushCounter(1010000, testing::DoubleEq(2005000),
thread_time_track));
EXPECT_CALL(*slice_, StartSlice(1010000, track, _, _))
.WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()),
InvokeArgument<2>(&inserter), Return(SliceId(0u))));
EXPECT_CALL(*event_, PushCounter(1015000, testing::DoubleEq(2007000),
thread_time_track));
EXPECT_CALL(*slice_, StartSlice(1015000, track, _, _))
.WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()),
InvokeArgument<2>(&inserter), Return(SliceId(1u))));
EXPECT_CALL(*event_, PushCounter(1020000, testing::DoubleEq(2010000),
thread_time_track));
EXPECT_CALL(*slice_, End(1020000, track, unknown_cat1, kNullStringId, _))
.WillOnce(DoAll(InvokeArgument<4>(&inserter), Return(SliceId(0u))));
context_.sorter->ExtractEventsForced();
EXPECT_EQ(storage_->slice_table().row_count(), 2u);
auto id_0 = storage_->slice_table().id().IndexOf(SliceId(0u));
EXPECT_TRUE(id_0);
EXPECT_EQ(storage_->slice_table().thread_ts()[*id_0], 2005000);
EXPECT_EQ(storage_->slice_table().thread_dur()[*id_0], 5000);
auto id_1 = storage_->slice_table().id().IndexOf(SliceId(1u));
EXPECT_TRUE(id_1);
EXPECT_EQ(storage_->slice_table().thread_ts()[*id_1], 2007000);
EXPECT_EQ(storage_->slice_table().thread_dur()[*id_1], 0);
}
TEST_F(ProtoTraceParserTest, TrackEventWithInternedData) {
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_incremental_state_cleared(true);
auto* thread_desc = packet->set_thread_descriptor();
thread_desc->set_pid(15);
thread_desc->set_tid(16);
thread_desc->set_reference_timestamp_us(1000);
thread_desc->set_reference_thread_time_us(2000);
thread_desc->set_reference_thread_instruction_count(3000);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10); // absolute: 1010.
event->set_thread_time_delta_us(5); // absolute: 2005.
event->set_thread_instruction_count_delta(20); // absolute: 3020.
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('B');
auto* interned_data = packet->set_interned_data();
auto cat1 = interned_data->add_event_categories();
cat1->set_iid(1);
cat1->set_name("cat1");
auto ev1 = interned_data->add_event_names();
ev1->set_iid(1);
ev1->set_name("ev1");
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_absolute_us(1040);
event->set_thread_time_absolute_us(2030);
event->set_thread_instruction_count_absolute(3100);
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('I');
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_absolute_us(1050);
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('i');
legacy_event->set_instant_event_scope(
protos::pbzero::TrackEvent::LegacyEvent::SCOPE_PROCESS);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10); // absolute: 1020.
event->set_thread_time_delta_us(5); // absolute: 2010.
event->set_thread_instruction_count_delta(20); // absolute: 3040.
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('E');
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_absolute_us(1005);
event->set_thread_time_absolute_us(2003);
event->set_thread_instruction_count_absolute(3010);
event->add_category_iids(2);
event->add_category_iids(3);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(4);
legacy_event->set_phase('X');
legacy_event->set_duration_us(23); // absolute end: 1028.
legacy_event->set_thread_duration_us(12); // absolute end: 2015.
legacy_event->set_thread_instruction_delta(50); // absolute end: 3060.
legacy_event->set_bind_id(9999);
legacy_event->set_flow_direction(
protos::pbzero::TrackEvent::LegacyEvent::FLOW_OUT);
auto* interned_data = packet->set_interned_data();
auto cat2 = interned_data->add_event_categories();
cat2->set_iid(2);
cat2->set_name("cat2");
auto cat3 = interned_data->add_event_categories();
cat3->set_iid(3);
cat3->set_name("cat3");
auto ev2 = interned_data->add_event_names();
ev2->set_iid(4);
ev2->set_name("ev2");
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* thread_desc = packet->set_thread_descriptor();
thread_desc->set_pid(15);
thread_desc->set_tid(16);
auto* event = packet->set_track_event();
event->set_timestamp_absolute_us(1005);
event->add_category_iids(2);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(4);
legacy_event->set_phase('t');
legacy_event->set_unscoped_id(220);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* thread_desc = packet->set_thread_descriptor();
thread_desc->set_pid(15);
thread_desc->set_tid(16);
auto* event = packet->set_track_event();
event->set_timestamp_absolute_us(1005);
event->add_category_iids(2);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(4);
legacy_event->set_phase('f');
legacy_event->set_unscoped_id(330);
legacy_event->set_bind_to_enclosing(false);
}
Tokenize();
EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
tables::ThreadTable::Row row(16);
row.upid = 2u;
storage_->mutable_thread_table()->Insert(row);
constexpr TrackId thread_1_track{0u};
constexpr TrackId thread_time_track{1u};
constexpr TrackId thread_instruction_count_track{2u};
constexpr TrackId process_2_track{3u};
StringId cat_1 = storage_->InternString("cat1");
StringId ev_1 = storage_->InternString("ev1");
InSequence in_sequence; // Below slices should be sorted by timestamp.
MockBoundInserter inserter;
// Only the begin timestamp counters can be imported into the counter table.
EXPECT_CALL(*event_, PushCounter(1005000, testing::DoubleEq(2003000),
thread_time_track));
EXPECT_CALL(*event_, PushCounter(1005000, testing::DoubleEq(3010),
thread_instruction_count_track));
EXPECT_CALL(*slice_, StartSlice(1005000, thread_1_track, _, _))
.WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()),
InvokeArgument<2>(&inserter), Return(SliceId(0u))));
EXPECT_CALL(*event_, PushCounter(1010000, testing::DoubleEq(2005000),
thread_time_track));
EXPECT_CALL(*event_, PushCounter(1010000, testing::DoubleEq(3020),
thread_instruction_count_track));
EXPECT_CALL(*slice_, StartSlice(1010000, thread_1_track, _, _))
.WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()),
InvokeArgument<2>(&inserter), Return(SliceId(1u))));
EXPECT_CALL(*event_, PushCounter(1020000, testing::DoubleEq(2010000),
thread_time_track));
EXPECT_CALL(*event_, PushCounter(1020000, testing::DoubleEq(3040),
thread_instruction_count_track));
EXPECT_CALL(*slice_, End(1020000, thread_1_track, cat_1, ev_1, _))
.WillOnce(DoAll(InvokeArgument<4>(&inserter), Return(SliceId(1u))));
EXPECT_CALL(*event_, PushCounter(1040000, testing::DoubleEq(2030000),
thread_time_track));
EXPECT_CALL(*event_, PushCounter(1040000, testing::DoubleEq(3100),
thread_instruction_count_track));
EXPECT_CALL(*slice_, StartSlice(1040000, thread_1_track, _, _))
.WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()),
InvokeArgument<2>(&inserter), Return(SliceId(2u))));
EXPECT_CALL(*slice_, Scoped(1050000, process_2_track, cat_1, ev_1, 0, _))
.WillOnce(DoAll(InvokeArgument<5>(&inserter), Return(SliceId(3u))));
// Second slice should have a legacy_event.passthrough_utid arg.
EXPECT_CALL(inserter, AddArg(_, _, Variadic::UnsignedInteger(1u), _));
context_.sorter->ExtractEventsForced();
EXPECT_EQ(storage_->slice_table().row_count(), 3u);
auto id_0 = storage_->slice_table().id().IndexOf(SliceId(0u));
EXPECT_TRUE(id_0);
EXPECT_EQ(storage_->slice_table().thread_ts()[*id_0], 2003000);
EXPECT_EQ(storage_->slice_table().thread_dur()[*id_0], 12000);
EXPECT_EQ(storage_->slice_table().thread_instruction_count()[*id_0], 3010);
EXPECT_EQ(storage_->slice_table().thread_instruction_delta()[*id_0], 50);
auto id_1 = storage_->slice_table().id().IndexOf(SliceId(1u));
EXPECT_TRUE(id_1);
EXPECT_EQ(storage_->slice_table().thread_ts()[*id_1], 2005000);
EXPECT_EQ(storage_->slice_table().thread_dur()[*id_1], 5000);
EXPECT_EQ(storage_->slice_table().thread_instruction_count()[*id_1], 3020);
EXPECT_EQ(storage_->slice_table().thread_instruction_delta()[*id_1], 20);
auto id_2 = storage_->slice_table().id().IndexOf(SliceId(2u));
EXPECT_TRUE(id_2);
EXPECT_EQ(storage_->slice_table().thread_ts()[*id_2], 2030000);
EXPECT_EQ(storage_->slice_table().thread_dur()[*id_2], 0);
EXPECT_EQ(storage_->slice_table().thread_instruction_count()[*id_2], 3100);
EXPECT_EQ(storage_->slice_table().thread_instruction_delta()[*id_2], 0);
}
TEST_F(ProtoTraceParserTest, TrackEventAsyncEvents) {
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_incremental_state_cleared(true);
auto* thread_desc = packet->set_thread_descriptor();
thread_desc->set_pid(15);
thread_desc->set_tid(16);
thread_desc->set_reference_timestamp_us(1000);
thread_desc->set_reference_thread_time_us(2000);
thread_desc->set_reference_thread_instruction_count(3000);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10); // absolute: 1010.
event->set_thread_time_delta_us(5); // absolute: 2005.
event->set_thread_instruction_count_delta(20); // absolute: 3020.
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('b');
legacy_event->set_global_id(10);
legacy_event->set_use_async_tts(true);
auto* interned_data = packet->set_interned_data();
auto cat1 = interned_data->add_event_categories();
cat1->set_iid(1);
cat1->set_name("cat1");
auto ev1 = interned_data->add_event_names();
ev1->set_iid(1);
ev1->set_name("ev1");
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10); // absolute: 1020.
event->set_thread_time_delta_us(5); // absolute: 2010.
event->set_thread_instruction_count_delta(20); // absolute: 3040.
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('e');
legacy_event->set_global_id(10);
legacy_event->set_use_async_tts(true);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_absolute_us(1015);
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(2);
legacy_event->set_phase('n');
legacy_event->set_global_id(10);
auto* interned_data = packet->set_interned_data();
auto ev2 = interned_data->add_event_names();
ev2->set_iid(2);
ev2->set_name("ev2");
}
{
// Different category but same global_id -> separate track.
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_absolute_us(1018);
event->add_category_iids(2);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(2);
legacy_event->set_phase('n');
legacy_event->set_global_id(15);
auto* interned_data = packet->set_interned_data();
auto cat2 = interned_data->add_event_categories();
cat2->set_iid(2);
cat2->set_name("cat2");
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_absolute_us(1030);
event->add_category_iids(2);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(2);
legacy_event->set_phase('n');
legacy_event->set_local_id(15);
legacy_event->set_id_scope("scope1");
}
Tokenize();
EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
tables::ThreadTable::Row row(16);
row.upid = 1u;
storage_->mutable_thread_table()->Insert(row);
StringId cat_1 = storage_->InternString("cat1");
StringId ev_1 = storage_->InternString("ev1");
StringId cat_2 = storage_->InternString("cat2");
StringId ev_2 = storage_->InternString("ev2");
TrackId thread_time_track{2u};
TrackId thread_instruction_count_track{3u};
InSequence in_sequence; // Below slices should be sorted by timestamp.
EXPECT_CALL(*event_, PushCounter(1010000, testing::DoubleEq(2005000),
thread_time_track));
EXPECT_CALL(*event_, PushCounter(1010000, testing::DoubleEq(3020),
thread_instruction_count_track));
EXPECT_CALL(*slice_, Begin(1010000, TrackId{1}, cat_1, ev_1, _))
.WillOnce(Return(SliceId(0u)));
EXPECT_CALL(*slice_, Scoped(1015000, TrackId{1}, cat_1, ev_2, 0, _));
EXPECT_CALL(*slice_, Scoped(1018000, TrackId{4}, cat_2, ev_2, 0, _));
EXPECT_CALL(*event_, PushCounter(1020000, testing::DoubleEq(2010000),
thread_time_track));
EXPECT_CALL(*event_, PushCounter(1020000, testing::DoubleEq(3040),
thread_instruction_count_track));
EXPECT_CALL(*slice_, End(1020000, TrackId{1}, cat_1, ev_1, _))
.WillOnce(Return(SliceId(SliceId(0u))));
EXPECT_CALL(*slice_, Scoped(1030000, TrackId{5}, cat_2, ev_2, 0, _));
context_.sorter->ExtractEventsForced();
// First track is for the thread; second first async, third and fourth for
// thread time and instruction count, others are the async event tracks.
EXPECT_EQ(storage_->track_table().row_count(), 6u);
EXPECT_EQ(storage_->track_table().name()[1], ev_1);
EXPECT_EQ(storage_->track_table().name()[4], ev_2);
EXPECT_EQ(storage_->track_table().name()[5], ev_2);
EXPECT_EQ(storage_->process_track_table().row_count(), 3u);
EXPECT_EQ(storage_->process_track_table().upid()[0], 1u);
EXPECT_EQ(storage_->process_track_table().upid()[1], 1u);
EXPECT_EQ(storage_->process_track_table().upid()[2], 1u);
EXPECT_EQ(storage_->virtual_track_slices().slice_count(), 1u);
EXPECT_EQ(storage_->virtual_track_slices().slice_ids()[0], SliceId(0u));
EXPECT_EQ(storage_->virtual_track_slices().thread_timestamp_ns()[0], 2005000);
EXPECT_EQ(storage_->virtual_track_slices().thread_duration_ns()[0], 5000);
EXPECT_EQ(storage_->virtual_track_slices().thread_instruction_counts()[0],
3020);
EXPECT_EQ(storage_->virtual_track_slices().thread_instruction_deltas()[0],
20);
}
// TODO(eseckler): Also test instant events on separate tracks.
TEST_F(ProtoTraceParserTest, TrackEventWithTrackDescriptors) {
// Sequence 1.
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_incremental_state_cleared(true);
packet->set_timestamp(1000000);
auto* track_desc = packet->set_track_descriptor();
track_desc->set_uuid(1234);
track_desc->set_name("Thread track 1");
auto* thread_desc = track_desc->set_thread();
thread_desc->set_pid(15);
thread_desc->set_tid(16);
auto* chrome_thread = track_desc->set_chrome_thread();
chrome_thread->set_thread_type(
protos::pbzero::ChromeThreadDescriptor::THREAD_SAMPLING_PROFILER);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_timestamp(1000000);
auto* track_desc = packet->set_track_descriptor();
track_desc->set_uuid(5678);
track_desc->set_name("Async track 1");
}
{
// Async event started on "Async track 1".
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_timestamp(1010000);
auto* event = packet->set_track_event();
event->set_track_uuid(5678);
event->set_thread_time_absolute_us(2005);
event->set_thread_instruction_count_absolute(3020);
event->add_category_iids(1);
event->set_name_iid(1);
event->set_type(protos::pbzero::TrackEvent::TYPE_SLICE_BEGIN);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_use_async_tts(true);
auto* interned_data = packet->set_interned_data();
auto cat1 = interned_data->add_event_categories();
cat1->set_iid(1);
cat1->set_name("cat1");
auto ev1 = interned_data->add_event_names();
ev1->set_iid(1);
ev1->set_name("ev1");
}
{
// Instant event on "Thread track 1".
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_timestamp(1015000);
auto* event = packet->set_track_event();
event->set_track_uuid(1234);
event->set_thread_time_absolute_us(2007);
event->add_category_iids(2);
event->set_name_iid(2);
event->set_type(protos::pbzero::TrackEvent::TYPE_INSTANT);
auto* interned_data = packet->set_interned_data();
auto cat1 = interned_data->add_event_categories();
cat1->set_iid(2);
cat1->set_name("cat2");
auto ev1 = interned_data->add_event_names();
ev1->set_iid(2);
ev1->set_name("ev2");
}
// Sequence 2.
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(2);
packet->set_incremental_state_cleared(true);
packet->set_timestamp(1000000);
auto* track_desc = packet->set_track_descriptor();
track_desc->set_uuid(4321);
track_desc->set_name("Thread track 2");
auto* thread_desc = track_desc->set_thread();
thread_desc->set_pid(15);
thread_desc->set_tid(17);
}
{
// Async event completed on "Async track 1".
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(2);
packet->set_timestamp(1020000);
auto* event = packet->set_track_event();
event->set_track_uuid(5678);
event->set_thread_time_absolute_us(2010);
event->set_thread_instruction_count_absolute(3040);
event->set_type(protos::pbzero::TrackEvent::TYPE_SLICE_END);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_use_async_tts(true);
}
{
// Instant event on "Thread track 2".
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(2);
packet->set_timestamp(1016000);
auto* event = packet->set_track_event();
event->set_track_uuid(4321);
event->set_thread_time_absolute_us(2008);
event->add_category_iids(1);
event->set_name_iid(1);
event->set_type(protos::pbzero::TrackEvent::TYPE_INSTANT);
auto* interned_data = packet->set_interned_data();
auto cat1 = interned_data->add_event_categories();
cat1->set_iid(1);
cat1->set_name("cat3");
auto ev1 = interned_data->add_event_names();
ev1->set_iid(1);
ev1->set_name("ev3");
}
EXPECT_CALL(*process_,
UpdateThreadNameByUtid(
1u, storage_->InternString("StackSamplingProfiler"),
ThreadNamePriority::kTrackDescriptorThreadType));
EXPECT_CALL(*process_,
UpdateThreadNameByUtid(2u, kNullStringId,
ThreadNamePriority::kTrackDescriptor));
EXPECT_CALL(*process_,
UpdateThreadNameByUtid(1u, kNullStringId,
ThreadNamePriority::kTrackDescriptor));
EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
EXPECT_CALL(*process_, UpdateThread(17, 15)).WillRepeatedly(Return(2u));
tables::ThreadTable::Row t1(16);
t1.upid = 1u;
storage_->mutable_thread_table()->Insert(t1);
tables::ThreadTable::Row t2(16);
t2.upid = 2u;
storage_->mutable_thread_table()->Insert(t2);
Tokenize();
StringId cat_1 = storage_->InternString("cat1");
StringId ev_1 = storage_->InternString("ev1");
InSequence in_sequence; // Below slices should be sorted by timestamp.
EXPECT_CALL(*slice_, Begin(1010000, TrackId{1}, cat_1, ev_1, _))
.WillOnce(Return(SliceId(2u)));
EXPECT_CALL(*event_,
PushCounter(1015000, testing::DoubleEq(2007000), TrackId{3}));
EXPECT_CALL(*slice_, StartSlice(1015000, TrackId{0}, _, _))
.WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()), Return(SliceId(0u))));
EXPECT_CALL(*event_,
PushCounter(1016000, testing::DoubleEq(2008000), TrackId{4}));
EXPECT_CALL(*slice_, StartSlice(1016000, TrackId{2}, _, _))
.WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()), Return(SliceId(1u))));
EXPECT_CALL(*slice_,
End(1020000, TrackId{1}, kNullStringId, kNullStringId, _))
.WillOnce(Return(SliceId(2u)));
context_.sorter->ExtractEventsForced();
// First track is "Thread track 1"; second is "Async track 1", third is global
// default track (parent of async track), fourth is "Thread track 2", fifth &
// sixth are thread time tracks for thread 1 and 2.
EXPECT_EQ(storage_->track_table().row_count(), 5u);
EXPECT_EQ(storage_->track_table().name().GetString(0), "Thread track 1");
EXPECT_EQ(storage_->track_table().name().GetString(1), "Async track 1");
EXPECT_EQ(storage_->track_table().name().GetString(2), "Thread track 2");
EXPECT_EQ(storage_->thread_track_table().row_count(), 2u);
EXPECT_EQ(storage_->thread_track_table().utid()[0], 1u);
EXPECT_EQ(storage_->thread_track_table().utid()[1], 2u);
EXPECT_EQ(storage_->virtual_track_slices().slice_count(), 1u);
EXPECT_EQ(storage_->virtual_track_slices().slice_ids()[0], SliceId(2u));
EXPECT_EQ(storage_->virtual_track_slices().thread_timestamp_ns()[0], 2005000);
EXPECT_EQ(storage_->virtual_track_slices().thread_duration_ns()[0], 5000);
EXPECT_EQ(storage_->virtual_track_slices().thread_instruction_counts()[0],
3020);
EXPECT_EQ(storage_->virtual_track_slices().thread_instruction_deltas()[0],
20);
EXPECT_EQ(storage_->slice_table().row_count(), 2u);
auto id_0 = storage_->slice_table().id().IndexOf(SliceId(0u));
EXPECT_TRUE(id_0);
EXPECT_EQ(storage_->slice_table().thread_ts()[*id_0], 2007000);
EXPECT_EQ(storage_->slice_table().thread_dur()[*id_0], 0);
// There was no thread instructions in the packets above.
EXPECT_FALSE(storage_->slice_table().thread_instruction_count()[*id_0]);
EXPECT_FALSE(storage_->slice_table().thread_instruction_delta()[*id_0]);
auto id_1 = storage_->slice_table().id().IndexOf(SliceId(1u));
EXPECT_TRUE(id_1);
EXPECT_EQ(storage_->slice_table().thread_ts()[*id_1], 2008000);
EXPECT_EQ(storage_->slice_table().thread_dur()[*id_1], 0);
EXPECT_FALSE(storage_->slice_table().thread_instruction_count()[*id_1]);
EXPECT_FALSE(storage_->slice_table().thread_instruction_delta()[*id_1]);
}
TEST_F(ProtoTraceParserTest, TrackEventWithResortedCounterDescriptor) {
// Descriptors with timestamps after the event below. They will be tokenized
// in the order they appear here, but then resorted before parsing to appear
// after the events below.
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_incremental_state_cleared(true);
packet->set_timestamp(3000);
auto* track_desc = packet->set_track_descriptor();
track_desc->set_uuid(1);
auto* thread_desc = track_desc->set_thread();
thread_desc->set_pid(5);
thread_desc->set_tid(1);
thread_desc->set_thread_name("t1");
// Default to track for "t1" and an extra counter for thread time.
auto* track_event_defaults =
packet->set_trace_packet_defaults()->set_track_event_defaults();
track_event_defaults->set_track_uuid(1);
// Thread-time counter track defined below.
track_event_defaults->add_extra_counter_track_uuids(10);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_timestamp(3000);
auto* track_desc = packet->set_track_descriptor();
track_desc->set_uuid(10);
track_desc->set_parent_uuid(1);
auto* counter = track_desc->set_counter();
counter->set_type(
protos::pbzero::CounterDescriptor::COUNTER_THREAD_TIME_NS);
counter->set_unit_multiplier(1000); // provided in us.
counter->set_is_incremental(true);
}
{
// Event with timestamps before the descriptors above. The thread time
// counter values should still be imported as counter values and as args for
// JSON export. Should appear on default track "t1" with
// extra_counter_values for "c1".
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_sequence_flags(
protos::pbzero::TracePacket::SEQ_NEEDS_INCREMENTAL_STATE);
packet->set_timestamp(1000);
auto* event = packet->set_track_event();
event->add_categories("cat1");
event->set_name("ev1");
event->set_type(protos::pbzero::TrackEvent::TYPE_SLICE_BEGIN);
event->add_extra_counter_values(1000); // absolute: 1000000.
}
{
// End for "ev1".
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_timestamp(1100);
auto* event = packet->set_track_event();
event->set_type(protos::pbzero::TrackEvent::TYPE_SLICE_END);
event->add_extra_counter_values(10); // absolute: 1010000.
}
EXPECT_CALL(*process_, UpdateThread(1, 5)).WillRepeatedly(Return(1u));
tables::ThreadTable::Row t1(16);
t1.upid = 1u;
storage_->mutable_thread_table()->Insert(t1);
Tokenize();
InSequence in_sequence; // Below slices should be sorted by timestamp.
EXPECT_CALL(*event_,
PushCounter(1000, testing::DoubleEq(1000000), TrackId{1}));
EXPECT_CALL(*slice_, StartSlice(1000, TrackId{0}, _, _))
.WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()), Return(SliceId(0u))));
EXPECT_CALL(*event_,
PushCounter(1100, testing::DoubleEq(1010000), TrackId{1}));
EXPECT_CALL(*slice_, End(1100, TrackId{0}, kNullStringId, kNullStringId, _))
.WillOnce(Return(SliceId(0u)));
EXPECT_CALL(*process_,
UpdateThreadNameByUtid(1u, storage_->InternString("t1"),
ThreadNamePriority::kTrackDescriptor));
context_.sorter->ExtractEventsForced();
// First track is thread time track, second is "t1".
EXPECT_EQ(storage_->track_table().row_count(), 2u);
EXPECT_EQ(storage_->thread_track_table().row_count(), 1u);
EXPECT_EQ(storage_->thread_track_table().utid()[0], 1u);
// Counter values should also be imported into thread slices.
EXPECT_EQ(storage_->slice_table().row_count(), 1u);
auto id_0 = storage_->slice_table().id().IndexOf(SliceId(0u));
EXPECT_TRUE(id_0);
EXPECT_EQ(storage_->slice_table().thread_ts()[*id_0], 1000000);
EXPECT_EQ(storage_->slice_table().thread_dur()[*id_0], 10000);
}
TEST_F(ProtoTraceParserTest, TrackEventWithoutIncrementalStateReset) {
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* thread_desc = packet->set_thread_descriptor();
thread_desc->set_pid(15);
thread_desc->set_tid(16);
thread_desc->set_reference_timestamp_us(1000);
thread_desc->set_reference_thread_time_us(2000);
}
{
// Event should be discarded because delta timestamps require valid
// incremental state + thread descriptor.
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10); // absolute: 1010.
event->set_thread_time_delta_us(5); // absolute: 2005.
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('B');
}
{
// Event should be discarded because it specifies
// SEQ_NEEDS_INCREMENTAL_STATE.
auto* packet = trace_->add_packet();
packet->set_timestamp(2000000);
packet->set_trusted_packet_sequence_id(1);
packet->set_sequence_flags(
protos::pbzero::TracePacket::SEQ_NEEDS_INCREMENTAL_STATE);
auto* event = packet->set_track_event();
event->add_categories("cat");
event->set_name("ev1");
event->set_type(protos::pbzero::TrackEvent::TYPE_INSTANT);
}
{
// Event should be accepted because it does not specify
// SEQ_NEEDS_INCREMENTAL_STATE and uses absolute timestamps.
auto* packet = trace_->add_packet();
packet->set_timestamp(2100000);
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->add_categories("cat1");
event->set_name("ev2");
event->set_type(protos::pbzero::TrackEvent::TYPE_INSTANT);
}
Tokenize();
StringId cat1 = storage_->InternString("cat1");
StringId ev2 = storage_->InternString("ev2");
EXPECT_CALL(*slice_, Scoped(2100000, TrackId{0}, cat1, ev2, 0, _))
.WillOnce(Return(SliceId(0u)));
context_.sorter->ExtractEventsForced();
}
TEST_F(ProtoTraceParserTest, TrackEventWithoutThreadDescriptor) {
{
// Event should be discarded because it specifies delta timestamps and no
// thread descriptor was seen yet.
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_incremental_state_cleared(true);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10);
event->set_thread_time_delta_us(5);
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('B');
}
{
// Events that specify SEQ_NEEDS_INCREMENTAL_STATE should be accepted even
// if there's no valid thread descriptor.
auto* packet = trace_->add_packet();
packet->set_timestamp(2000000);
packet->set_trusted_packet_sequence_id(1);
packet->set_sequence_flags(
protos::pbzero::TracePacket::SEQ_NEEDS_INCREMENTAL_STATE);
auto* event = packet->set_track_event();
event->add_categories("cat1");
event->set_name("ev1");
event->set_type(protos::pbzero::TrackEvent::TYPE_INSTANT);
}
Tokenize();
StringId cat1 = storage_->InternString("cat1");
StringId ev1 = storage_->InternString("ev1");
EXPECT_CALL(*slice_, Scoped(2000000, TrackId{0}, cat1, ev1, 0, _))
.WillOnce(Return(SliceId(0u)));
context_.sorter->ExtractEventsForced();
}
TEST_F(ProtoTraceParserTest, TrackEventWithDataLoss) {
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_incremental_state_cleared(true);
auto* thread_desc = packet->set_thread_descriptor();
thread_desc->set_pid(15);
thread_desc->set_tid(16);
thread_desc->set_reference_timestamp_us(1000);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10); // absolute: 1010.
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('B');
}
{
// Event should be dropped because data loss occurred before.
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_previous_packet_dropped(true); // Data loss occurred.
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10);
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('E');
}
{
// Event should be dropped because incremental state is invalid.
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10);
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('E');
}
{
// Event should be dropped because no new thread descriptor was seen yet.
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_incremental_state_cleared(true);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10);
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('E');
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* thread_desc = packet->set_thread_descriptor();
thread_desc->set_pid(15);
thread_desc->set_tid(16);
thread_desc->set_reference_timestamp_us(2000);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10); // absolute: 2010.
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('E');
}
Tokenize();
EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
tables::ThreadTable::Row row(16);
row.upid = 1u;
storage_->mutable_thread_table()->Insert(row);
StringId unknown_cat = storage_->InternString("unknown(1)");
constexpr TrackId track{0u};
InSequence in_sequence; // Below slices should be sorted by timestamp.
EXPECT_CALL(*slice_, StartSlice(1010000, track, _, _));
EXPECT_CALL(*slice_, End(2010000, track, unknown_cat, kNullStringId, _));
context_.sorter->ExtractEventsForced();
}
TEST_F(ProtoTraceParserTest, TrackEventMultipleSequences) {
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_incremental_state_cleared(true);
auto* thread_desc = packet->set_thread_descriptor();
thread_desc->set_pid(15);
thread_desc->set_tid(16);
thread_desc->set_reference_timestamp_us(1000);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10); // absolute: 1010.
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('B');
auto* interned_data = packet->set_interned_data();
auto cat1 = interned_data->add_event_categories();
cat1->set_iid(1);
cat1->set_name("cat1");
auto ev1 = interned_data->add_event_names();
ev1->set_iid(1);
ev1->set_name("ev1");
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(2);
packet->set_incremental_state_cleared(true);
auto* thread_desc = packet->set_thread_descriptor();
thread_desc->set_pid(15);
thread_desc->set_tid(17);
thread_desc->set_reference_timestamp_us(995);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(2);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10); // absolute: 1005.
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('B');
auto* interned_data = packet->set_interned_data();
auto cat1 = interned_data->add_event_categories();
cat1->set_iid(1);
cat1->set_name("cat1");
auto ev2 = interned_data->add_event_names();
ev2->set_iid(1);
ev2->set_name("ev2");
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10); // absolute: 1020.
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('E');
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(2);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10); // absolute: 1015.
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('E');
}
Tokenize();
EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
EXPECT_CALL(*process_, UpdateThread(17, 15)).WillRepeatedly(Return(2u));
tables::ThreadTable::Row t1(16);
t1.upid = 1u;
storage_->mutable_thread_table()->Insert(t1);
tables::ThreadTable::Row t2(17);
t2.upid = 1u;
storage_->mutable_thread_table()->Insert(t2);
StringId cat_1 = storage_->InternString("cat1");
StringId ev_2 = storage_->InternString("ev2");
StringId ev_1 = storage_->InternString("ev1");
constexpr TrackId thread_2_track{0u};
constexpr TrackId thread_1_track{1u};
InSequence in_sequence; // Below slices should be sorted by timestamp.
EXPECT_CALL(*slice_, StartSlice(1005000, thread_2_track, _, _));
EXPECT_CALL(*slice_, StartSlice(1010000, thread_1_track, _, _));
EXPECT_CALL(*slice_, End(1015000, thread_2_track, cat_1, ev_2, _));
EXPECT_CALL(*slice_, End(1020000, thread_1_track, cat_1, ev_1, _));
context_.sorter->ExtractEventsForced();
}
TEST_F(ProtoTraceParserTest, TrackEventWithDebugAnnotations) {
MockBoundInserter inserter;
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_incremental_state_cleared(true);
auto* thread_desc = packet->set_thread_descriptor();
thread_desc->set_pid(15);
thread_desc->set_tid(16);
thread_desc->set_reference_timestamp_us(1000);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10); // absolute: 1010.
event->add_category_iids(1);
auto* annotation1 = event->add_debug_annotations();
annotation1->set_name_iid(1);
annotation1->set_uint_value(10u);
auto* annotation2 = event->add_debug_annotations();
annotation2->set_name_iid(2);
auto* nested = annotation2->set_nested_value();
nested->set_nested_type(protos::pbzero::DebugAnnotation::NestedValue::DICT);
nested->add_dict_keys("child1");
nested->add_dict_keys("child2");
auto* child1 = nested->add_dict_values();
child1->set_nested_type(
protos::pbzero::DebugAnnotation::NestedValue::UNSPECIFIED);
child1->set_bool_value(true);
auto* child2 = nested->add_dict_values();
child2->set_nested_type(
protos::pbzero::DebugAnnotation::NestedValue::ARRAY);
auto* child21 = child2->add_array_values();
child21->set_nested_type(
protos::pbzero::DebugAnnotation::NestedValue::UNSPECIFIED);
child21->set_string_value("child21");
auto* child22 = child2->add_array_values();
child22->set_nested_type(
protos::pbzero::DebugAnnotation::NestedValue::UNSPECIFIED);
child22->set_double_value(2.2);
auto* child23 = child2->add_array_values();
child23->set_nested_type(
protos::pbzero::DebugAnnotation::NestedValue::UNSPECIFIED);
child23->set_int_value(23);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('B');
auto* interned_data = packet->set_interned_data();
auto cat1 = interned_data->add_event_categories();
cat1->set_iid(1);
cat1->set_name("cat1");
auto ev1 = interned_data->add_event_names();
ev1->set_iid(1);
ev1->set_name("ev1");
auto an1 = interned_data->add_debug_annotation_names();
an1->set_iid(1);
an1->set_name("an1");
auto an2 = interned_data->add_debug_annotation_names();
an2->set_iid(2);
an2->set_name("an2");
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10); // absolute: 1020.
event->add_category_iids(1);
auto* annotation3 = event->add_debug_annotations();
annotation3->set_name_iid(3);
annotation3->set_int_value(-3);
auto* annotation4 = event->add_debug_annotations();
annotation4->set_name_iid(4);
annotation4->set_bool_value(true);
auto* annotation5 = event->add_debug_annotations();
annotation5->set_name_iid(5);
annotation5->set_double_value(-5.5);
auto* annotation6 = event->add_debug_annotations();
annotation6->set_name_iid(6);
annotation6->set_pointer_value(20u);
auto* annotation7 = event->add_debug_annotations();
annotation7->set_name_iid(7);
annotation7->set_string_value("val7");
auto* annotation8 = event->add_debug_annotations();
annotation8->set_name_iid(8);
annotation8->set_legacy_json_value(
"{\"val8\": {\"a\": 42, \"b\": \"val8b\"}, \"arr8\": [1, 2, 3]}");
auto* annotation9 = event->add_debug_annotations();
annotation9->set_name_iid(9);
annotation9->set_int_value(15);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('E');
auto* interned_data = packet->set_interned_data();
auto an3 = interned_data->add_debug_annotation_names();
an3->set_iid(3);
an3->set_name("an3");
auto an4 = interned_data->add_debug_annotation_names();
an4->set_iid(4);
an4->set_name("an4");
auto an5 = interned_data->add_debug_annotation_names();
an5->set_iid(5);
an5->set_name("an5");
auto an6 = interned_data->add_debug_annotation_names();
an6->set_iid(6);
an6->set_name("an6");
auto an7 = interned_data->add_debug_annotation_names();
an7->set_iid(7);
an7->set_name("an7");
auto an8 = interned_data->add_debug_annotation_names();
an8->set_iid(8);
an8->set_name("an8");
auto an9 = interned_data->add_debug_annotation_names();
an9->set_iid(9);
an9->set_name("an8.foo");
}
Tokenize();
EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
tables::ThreadTable::Row row(16);
row.upid = 1u;
storage_->mutable_thread_table()->Insert(row);
StringId cat_1 = storage_->InternString("cat1");
StringId ev_1 = storage_->InternString("ev1");
StringId debug_an_1 = storage_->InternString("debug.an1");
StringId debug_an_2_child_1 = storage_->InternString("debug.an2.child1");
StringId debug_an_2_child_2 = storage_->InternString("debug.an2.child2");
StringId debug_an_2_child_2_0 = storage_->InternString("debug.an2.child2[0]");
StringId child21 = storage_->InternString("child21");
StringId debug_an_2_child_2_1 = storage_->InternString("debug.an2.child2[1]");
StringId debug_an_2_child_2_2 = storage_->InternString("debug.an2.child2[2]");
StringId debug_an_3 = storage_->InternString("debug.an3");
StringId debug_an_4 = storage_->InternString("debug.an4");
StringId debug_an_5 = storage_->InternString("debug.an5");
StringId debug_an_6 = storage_->InternString("debug.an6");
StringId debug_an_7 = storage_->InternString("debug.an7");
StringId val_7 = storage_->InternString("val7");
StringId debug_an_8_val8_a = storage_->InternString("debug.an8.val8.a");
StringId debug_an_8_val8_b = storage_->InternString("debug.an8.val8.b");
StringId val_8b = storage_->InternString("val8b");
StringId debug_an_8_arr8 = storage_->InternString("debug.an8.arr8");
StringId debug_an_8_arr8_0 = storage_->InternString("debug.an8.arr8[0]");
StringId debug_an_8_arr8_1 = storage_->InternString("debug.an8.arr8[1]");
StringId debug_an_8_arr8_2 = storage_->InternString("debug.an8.arr8[2]");
StringId debug_an_8_foo = storage_->InternString("debug.an8_foo");
constexpr TrackId track{0u};
EXPECT_CALL(*slice_, StartSlice(1010000, track, _, _))
.WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()),
InvokeArgument<2>(&inserter), Return(SliceId(0u))));
EXPECT_CALL(inserter, AddArg(debug_an_1, debug_an_1,
Variadic::UnsignedInteger(10u), _));
EXPECT_CALL(inserter, AddArg(debug_an_2_child_1, debug_an_2_child_1,
Variadic::Boolean(true), _));
EXPECT_CALL(inserter, AddArg(debug_an_2_child_2, debug_an_2_child_2_0,
Variadic::String(child21), _));
EXPECT_CALL(inserter, AddArg(debug_an_2_child_2, debug_an_2_child_2_1,
Variadic::Real(2.2), _));
EXPECT_CALL(inserter, AddArg(debug_an_2_child_2, debug_an_2_child_2_2,
Variadic::Integer(23), _));
EXPECT_CALL(*slice_, End(1020000, track, cat_1, ev_1, _))
.WillOnce(DoAll(InvokeArgument<4>(&inserter), Return(SliceId(0u))));
EXPECT_CALL(inserter,
AddArg(debug_an_3, debug_an_3, Variadic::Integer(-3), _));
EXPECT_CALL(inserter,
AddArg(debug_an_4, debug_an_4, Variadic::Boolean(true), _));
EXPECT_CALL(inserter,
AddArg(debug_an_5, debug_an_5, Variadic::Real(-5.5), _));
EXPECT_CALL(inserter,
AddArg(debug_an_6, debug_an_6, Variadic::Pointer(20u), _));
EXPECT_CALL(inserter,
AddArg(debug_an_7, debug_an_7, Variadic::String(val_7), _));
EXPECT_CALL(inserter, AddArg(debug_an_8_val8_a, debug_an_8_val8_a,
Variadic::Integer(42), _));
EXPECT_CALL(inserter, AddArg(debug_an_8_val8_b, debug_an_8_val8_b,
Variadic::String(val_8b), _));
EXPECT_CALL(inserter, AddArg(debug_an_8_arr8, debug_an_8_arr8_0,
Variadic::Integer(1), _));
EXPECT_CALL(inserter, AddArg(debug_an_8_arr8, debug_an_8_arr8_1,
Variadic::Integer(2), _));
EXPECT_CALL(inserter, AddArg(debug_an_8_arr8, debug_an_8_arr8_2,
Variadic::Integer(3), _));
EXPECT_CALL(inserter,
AddArg(debug_an_8_foo, debug_an_8_foo, Variadic::Integer(15), _));
context_.sorter->ExtractEventsForced();
}
TEST_F(ProtoTraceParserTest, TrackEventWithTaskExecution) {
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_incremental_state_cleared(true);
auto* thread_desc = packet->set_thread_descriptor();
thread_desc->set_pid(15);
thread_desc->set_tid(16);
thread_desc->set_reference_timestamp_us(1000);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10); // absolute: 1010.
event->add_category_iids(1);
auto* task_execution = event->set_task_execution();
task_execution->set_posted_from_iid(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('B');
auto* interned_data = packet->set_interned_data();
auto cat1 = interned_data->add_event_categories();
cat1->set_iid(1);
cat1->set_name("cat1");
auto ev1 = interned_data->add_event_names();
ev1->set_iid(1);
ev1->set_name("ev1");
auto loc1 = interned_data->add_source_locations();
loc1->set_iid(1);
loc1->set_file_name("file1");
loc1->set_function_name("func1");
loc1->set_line_number(42);
}
Tokenize();
EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
tables::ThreadTable::Row row(16);
row.upid = 1u;
storage_->mutable_thread_table()->Insert(row);
constexpr TrackId track{0u};
StringId file_1 = storage_->InternString("file1");
StringId func_1 = storage_->InternString("func1");
InSequence in_sequence; // Below slices should be sorted by timestamp.
MockBoundInserter inserter;
EXPECT_CALL(*slice_, StartSlice(1010000, track, _, _))
.WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()),
InvokeArgument<2>(&inserter), Return(SliceId(0u))));
EXPECT_CALL(inserter, AddArg(_, _, Variadic::String(file_1), _));
EXPECT_CALL(inserter, AddArg(_, _, Variadic::String(func_1), _));
EXPECT_CALL(inserter, AddArg(_, _, Variadic::UnsignedInteger(42), _));
context_.sorter->ExtractEventsForced();
}
TEST_F(ProtoTraceParserTest, TrackEventWithLogMessage) {
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_incremental_state_cleared(true);
auto* thread_desc = packet->set_thread_descriptor();
thread_desc->set_pid(15);
thread_desc->set_tid(16);
thread_desc->set_reference_timestamp_us(1000);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10); // absolute: 1010.
event->add_category_iids(1);
auto* log_message = event->set_log_message();
log_message->set_body_iid(1);
log_message->set_source_location_iid(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
legacy_event->set_phase('I');
auto* interned_data = packet->set_interned_data();
auto cat1 = interned_data->add_event_categories();
cat1->set_iid(1);
cat1->set_name("cat1");
auto ev1 = interned_data->add_event_names();
ev1->set_iid(1);
ev1->set_name("ev1");
auto body = interned_data->add_log_message_body();
body->set_iid(1);
body->set_body("body1");
auto loc1 = interned_data->add_source_locations();
loc1->set_iid(1);
loc1->set_file_name("file1");
loc1->set_function_name("func1");
loc1->set_line_number(1);
}
Tokenize();
EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
tables::ThreadTable::Row row(16);
row.upid = 1u;
storage_->mutable_thread_table()->Insert(row);
StringId body_1 = storage_->InternString("body1");
StringId file_1 = storage_->InternString("file1");
StringId func_1 = storage_->InternString("func1");
StringId source_location_id = storage_->InternString("file1:1");
constexpr TrackId track{0};
InSequence in_sequence; // Below slices should be sorted by timestamp.
MockBoundInserter inserter;
EXPECT_CALL(*slice_, StartSlice(1010000, track, _, _))
.WillOnce(DoAll(IgnoreResult(InvokeArgument<3>()),
InvokeArgument<2>(&inserter), Return(SliceId(0u))));
// Call with logMessageBody (body1 in this case).
EXPECT_CALL(inserter, AddArg(_, _, Variadic::String(body_1), _));
EXPECT_CALL(inserter, AddArg(_, _, Variadic::String(file_1), _));
EXPECT_CALL(inserter, AddArg(_, _, Variadic::String(func_1), _));
EXPECT_CALL(inserter, AddArg(_, _, Variadic::Integer(1), _));
context_.sorter->ExtractEventsForced();
EXPECT_GT(context_.storage->android_log_table().row_count(), 0u);
EXPECT_EQ(context_.storage->android_log_table().ts()[0], 1010000);
EXPECT_EQ(context_.storage->android_log_table().msg()[0], body_1);
EXPECT_EQ(context_.storage->android_log_table().tag()[0], source_location_id);
}
TEST_F(ProtoTraceParserTest, TrackEventParseLegacyEventIntoRawTable) {
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_incremental_state_cleared(true);
auto* thread_desc = packet->set_thread_descriptor();
thread_desc->set_pid(15);
thread_desc->set_tid(16);
thread_desc->set_reference_timestamp_us(1000);
thread_desc->set_reference_thread_time_us(2000);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10); // absolute: 1010.
event->set_thread_time_delta_us(5); // absolute: 2005.
event->add_category_iids(1);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
// Represents a phase that isn't parsed into regular trace processor tables.
legacy_event->set_phase('?');
legacy_event->set_duration_us(23);
legacy_event->set_thread_duration_us(15);
legacy_event->set_global_id(99u);
legacy_event->set_id_scope("scope1");
legacy_event->set_use_async_tts(true);
auto* annotation1 = event->add_debug_annotations();
annotation1->set_name_iid(1);
annotation1->set_uint_value(10u);
auto* interned_data = packet->set_interned_data();
auto cat1 = interned_data->add_event_categories();
cat1->set_iid(1);
cat1->set_name("cat1");
auto ev1 = interned_data->add_event_names();
ev1->set_iid(1);
ev1->set_name("ev1");
auto an1 = interned_data->add_debug_annotation_names();
an1->set_iid(1);
an1->set_name("an1");
}
Tokenize();
EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
// Only the begin thread time can be imported into the counter table.
EXPECT_CALL(*event_,
PushCounter(1010000, testing::DoubleEq(2005000), TrackId{1}));
tables::ThreadTable::Row row(16);
row.upid = 1u;
storage_->mutable_thread_table()->Insert(row);
StringId cat_1 = storage_->InternString("cat1");
StringId ev_1 = storage_->InternString("ev1");
StringId scope_1 = storage_->InternString("scope1");
StringId question = storage_->InternString("?");
StringId debug_an_1 = storage_->InternString("debug.an1");
context_.sorter->ExtractEventsForced();
::testing::Mock::VerifyAndClearExpectations(storage_);
// Verify raw_table and args contents.
const auto& raw_table = storage_->raw_table();
EXPECT_EQ(raw_table.row_count(), 1u);
EXPECT_EQ(raw_table.ts()[0], 1010000);
EXPECT_EQ(raw_table.name()[0],
storage_->InternString("track_event.legacy_event"));
EXPECT_EQ(raw_table.cpu()[0], 0u);
EXPECT_EQ(raw_table.utid()[0], 1u);
EXPECT_EQ(raw_table.arg_set_id()[0], 1u);
EXPECT_GE(storage_->arg_table().row_count(), 10u);
EXPECT_TRUE(HasArg(1u, storage_->InternString("legacy_event.category"),
Variadic::String(cat_1)));
EXPECT_TRUE(HasArg(1u, storage_->InternString("legacy_event.name"),
Variadic::String(ev_1)));
EXPECT_TRUE(HasArg(1u, storage_->InternString("legacy_event.phase"),
Variadic::String(question)));
EXPECT_TRUE(HasArg(1u, storage_->InternString("legacy_event.duration_ns"),
Variadic::Integer(23000)));
EXPECT_TRUE(HasArg(1u,
storage_->InternString("legacy_event.thread_timestamp_ns"),
Variadic::Integer(2005000)));
EXPECT_TRUE(HasArg(1u,
storage_->InternString("legacy_event.thread_duration_ns"),
Variadic::Integer(15000)));
EXPECT_TRUE(HasArg(1u, storage_->InternString("legacy_event.use_async_tts"),
Variadic::Boolean(true)));
EXPECT_TRUE(HasArg(1u, storage_->InternString("legacy_event.global_id"),
Variadic::UnsignedInteger(99u)));
EXPECT_TRUE(HasArg(1u, storage_->InternString("legacy_event.id_scope"),
Variadic::String(scope_1)));
EXPECT_TRUE(HasArg(1u, debug_an_1, Variadic::UnsignedInteger(10u)));
}
TEST_F(ProtoTraceParserTest, TrackEventLegacyTimestampsWithClockSnapshot) {
clock_->AddSnapshot({{protos::pbzero::BUILTIN_CLOCK_BOOTTIME, 0},
{protos::pbzero::BUILTIN_CLOCK_MONOTONIC, 1000000}});
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_incremental_state_cleared(true);
auto* thread_desc = packet->set_thread_descriptor();
thread_desc->set_pid(15);
thread_desc->set_tid(16);
thread_desc->set_reference_timestamp_us(1000); // MONOTONIC.
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* event = packet->set_track_event();
event->set_timestamp_delta_us(10); // absolute: 1010 (mon), 10 (boot).
event->add_category_iids(1);
event->set_type(protos::pbzero::TrackEvent::TYPE_SLICE_BEGIN);
auto* legacy_event = event->set_legacy_event();
legacy_event->set_name_iid(1);
}
Tokenize();
EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
tables::ThreadTable::Row row(16);
row.upid = 1u;
storage_->mutable_thread_table()->Insert(row);
constexpr TrackId track{0u};
InSequence in_sequence; // Below slices should be sorted by timestamp.
// Timestamp should be adjusted to trace time (BOOTTIME).
EXPECT_CALL(*slice_, StartSlice(10000, track, _, _));
context_.sorter->ExtractEventsForced();
}
TEST_F(ProtoTraceParserTest, ParseEventWithClockIdButWithoutClockSnapshot) {
{
auto* packet = trace_->add_packet();
packet->set_timestamp(1000);
packet->set_timestamp_clock_id(3);
packet->set_trusted_packet_sequence_id(1);
auto* bundle = packet->set_chrome_events();
auto* metadata = bundle->add_metadata();
metadata->set_name("test");
metadata->set_int_value(23);
}
util::Status status = Tokenize();
EXPECT_TRUE(status.ok());
context_.sorter->ExtractEventsForced();
// Metadata should have created a raw event.
const auto& raw_table = storage_->raw_table();
EXPECT_EQ(raw_table.row_count(), 1u);
}
TEST_F(ProtoTraceParserTest, ParseChromeMetadataEventIntoRawTable) {
static const char kStringName[] = "string_name";
static const char kStringValue[] = "string_value";
static const char kIntName[] = "int_name";
static const int kIntValue = 123;
{
auto* packet = trace_->add_packet();
packet->set_timestamp(1000);
packet->set_timestamp_clock_id(3);
packet->set_trusted_packet_sequence_id(1);
auto* bundle = packet->set_chrome_events();
auto* metadata = bundle->add_metadata();
metadata->set_name(kStringName);
metadata->set_string_value(kStringValue);
metadata = bundle->add_metadata();
metadata->set_name(kIntName);
metadata->set_int_value(kIntValue);
}
Tokenize();
context_.sorter->ExtractEventsForced();
// Verify raw_table and args contents.
const auto& raw_table = storage_->raw_table();
EXPECT_EQ(raw_table.row_count(), 1u);
EXPECT_EQ(raw_table.name()[0],
storage_->InternString("chrome_event.metadata"));
EXPECT_EQ(raw_table.arg_set_id()[0], 1u);
EXPECT_EQ(storage_->arg_table().row_count(), 2u);
EXPECT_TRUE(HasArg(1u, storage_->InternString(kStringName),
Variadic::String(storage_->InternString(kStringValue))));
EXPECT_TRUE(HasArg(1u, storage_->InternString(kIntName),
Variadic::Integer(kIntValue)));
}
TEST_F(ProtoTraceParserTest, ParseChromeLegacyFtraceIntoRawTable) {
static const char kDataPart0[] = "aaa";
static const char kDataPart1[] = "bbb";
static const char kFullData[] = "aaabbb";
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* bundle = packet->set_chrome_events();
bundle->add_legacy_ftrace_output(kDataPart0);
bundle->add_legacy_ftrace_output(kDataPart1);
}
Tokenize();
context_.sorter->ExtractEventsForced();
// Verify raw_table and args contents.
const auto& raw_table = storage_->raw_table();
EXPECT_EQ(raw_table.row_count(), 1u);
EXPECT_EQ(raw_table.name()[0],
storage_->InternString("chrome_event.legacy_system_trace"));
EXPECT_EQ(raw_table.arg_set_id()[0], 1u);
EXPECT_EQ(storage_->arg_table().row_count(), 1u);
EXPECT_TRUE(HasArg(1u, storage_->InternString("data"),
Variadic::String(storage_->InternString(kFullData))));
}
TEST_F(ProtoTraceParserTest, ParseChromeLegacyJsonIntoRawTable) {
static const char kUserTraceEvent[] = "{\"user\":1}";
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* bundle = packet->set_chrome_events();
auto* user_trace = bundle->add_legacy_json_trace();
user_trace->set_type(protos::pbzero::ChromeLegacyJsonTrace::USER_TRACE);
user_trace->set_data(kUserTraceEvent);
}
Tokenize();
context_.sorter->ExtractEventsForced();
// Verify raw_table and args contents.
const auto& raw_table = storage_->raw_table();
EXPECT_EQ(raw_table.row_count(), 1u);
EXPECT_EQ(raw_table.name()[0],
storage_->InternString("chrome_event.legacy_user_trace"));
EXPECT_EQ(raw_table.arg_set_id()[0], 1u);
EXPECT_EQ(storage_->arg_table().row_count(), 1u);
EXPECT_TRUE(
HasArg(1u, storage_->InternString("data"),
Variadic::String(storage_->InternString(kUserTraceEvent))));
}
TEST_F(ProtoTraceParserTest, LoadChromeBenchmarkMetadata) {
static const char kName[] = "name";
static const char kTag1[] = "tag1";
static const char kTag2[] = "tag2";
auto* metadata = trace_->add_packet()->set_chrome_benchmark_metadata();
metadata->set_benchmark_name(kName);
metadata->add_story_tags(kTag1);
metadata->add_story_tags(kTag2);
Tokenize();
base::StringView benchmark = metadata::kNames[metadata::benchmark_name];
base::StringView tags = metadata::kNames[metadata::benchmark_story_tags];
context_.sorter->ExtractEventsForced();
const auto& meta_keys = storage_->metadata_table().name();
const auto& meta_values = storage_->metadata_table().str_value();
EXPECT_EQ(storage_->metadata_table().row_count(), 3u);
std::vector<std::pair<base::StringView, base::StringView>> meta_entries;
for (uint32_t i = 0; i < storage_->metadata_table().row_count(); i++) {
meta_entries.emplace_back(
std::make_pair(meta_keys.GetString(i), meta_values.GetString(i)));
}
EXPECT_THAT(meta_entries,
UnorderedElementsAreArray({std::make_pair(benchmark, kName),
std::make_pair(tags, kTag1),
std::make_pair(tags, kTag2)}));
}
TEST_F(ProtoTraceParserTest, LoadChromeMetadata) {
auto* track_event = trace_->add_packet()->set_chrome_events();
{
auto* metadata = track_event->add_metadata();
metadata->set_name("str_name");
metadata->set_string_value("foostr");
}
{
auto* metadata = track_event->add_metadata();
metadata->set_name("int_name");
metadata->set_int_value(42);
}
{
auto* metadata = track_event->add_metadata();
metadata->set_name("bool_name");
metadata->set_bool_value(true);
}
{
auto* metadata = track_event->add_metadata();
metadata->set_name("json_name");
metadata->set_json_value("{key: value}");
}
Tokenize();
context_.sorter->ExtractEventsForced();
const auto& metadata = storage_->metadata_table();
EXPECT_STREQ(metadata.name().GetString(0).c_str(), "cr-str_name");
EXPECT_STREQ(metadata.str_value().GetString(0).c_str(), "foostr");
EXPECT_STREQ(metadata.name().GetString(1).c_str(), "cr-int_name");
EXPECT_EQ(metadata.int_value()[1], 42);
EXPECT_STREQ(metadata.name().GetString(2).c_str(), "cr-bool_name");
EXPECT_EQ(metadata.int_value()[2], 1);
EXPECT_STREQ(metadata.name().GetString(3).c_str(), "cr-json_name");
EXPECT_STREQ(metadata.str_value().GetString(3).c_str(), "{key: value}");
}
TEST_F(ProtoTraceParserTest, AndroidPackagesList) {
auto* packet = trace_->add_packet();
auto* pkg_list = packet->set_packages_list();
pkg_list->set_read_error(false);
pkg_list->set_parse_error(true);
{
auto* pkg = pkg_list->add_packages();
pkg->set_name("com.test.app");
pkg->set_uid(1000);
pkg->set_debuggable(false);
pkg->set_profileable_from_shell(true);
pkg->set_version_code(42);
}
{
auto* pkg = pkg_list->add_packages();
pkg->set_name("com.test.app2");
pkg->set_uid(1001);
pkg->set_debuggable(false);
pkg->set_profileable_from_shell(false);
pkg->set_version_code(43);
}
Tokenize();
context_.sorter->ExtractEventsForced();
// Packet-level errors reflected in stats storage.
const auto& stats = context_.storage->stats();
EXPECT_FALSE(stats[stats::packages_list_has_read_errors].value);
EXPECT_TRUE(stats[stats::packages_list_has_parse_errors].value);
// Expect two metadata rows, each with an int_value of a separate arg set id.
// The relevant arg sets have the info about the packages. To simplify test
// structure, make an assumption that metadata storage is filled in in the
// FIFO order of seen packages.
const auto& package_list = context_.storage->package_list_table();
ASSERT_EQ(package_list.row_count(), 2u);
EXPECT_STREQ(storage_->GetString(package_list.package_name()[0]).c_str(),
"com.test.app");
EXPECT_EQ(package_list.uid()[0], 1000u);
EXPECT_EQ(package_list.debuggable()[0], false);
EXPECT_EQ(package_list.profileable_from_shell()[0], true);
EXPECT_EQ(package_list.version_code()[0], 42);
EXPECT_STREQ(storage_->GetString(package_list.package_name()[1]).c_str(),
"com.test.app2");
EXPECT_EQ(package_list.uid()[1], 1001u);
EXPECT_EQ(package_list.debuggable()[1], false);
EXPECT_EQ(package_list.profileable_from_shell()[1], false);
EXPECT_EQ(package_list.version_code()[1], 43);
}
TEST_F(ProtoTraceParserTest, AndroidPackagesListDuplicate) {
auto* packet = trace_->add_packet();
auto* pkg_list = packet->set_packages_list();
pkg_list->set_read_error(false);
pkg_list->set_parse_error(true);
{
auto* pkg = pkg_list->add_packages();
pkg->set_name("com.test.app");
pkg->set_uid(1000);
pkg->set_debuggable(false);
pkg->set_profileable_from_shell(true);
pkg->set_version_code(42);
}
{
auto* pkg = pkg_list->add_packages();
pkg->set_name("com.test.app");
pkg->set_uid(1000);
pkg->set_debuggable(false);
pkg->set_profileable_from_shell(true);
pkg->set_version_code(42);
}
Tokenize();
context_.sorter->ExtractEventsForced();
// Packet-level errors reflected in stats storage.
const auto& stats = context_.storage->stats();
EXPECT_FALSE(stats[stats::packages_list_has_read_errors].value);
EXPECT_TRUE(stats[stats::packages_list_has_parse_errors].value);
// Expect two metadata rows, each with an int_value of a separate arg set id.
// The relevant arg sets have the info about the packages. To simplify test
// structure, make an assumption that metadata storage is filled in in the
// FIFO order of seen packages.
const auto& package_list = context_.storage->package_list_table();
ASSERT_EQ(package_list.row_count(), 1u);
EXPECT_STREQ(storage_->GetString(package_list.package_name()[0]).c_str(),
"com.test.app");
EXPECT_EQ(package_list.uid()[0], 1000u);
EXPECT_EQ(package_list.debuggable()[0], false);
EXPECT_EQ(package_list.profileable_from_shell()[0], true);
EXPECT_EQ(package_list.version_code()[0], 42);
}
TEST_F(ProtoTraceParserTest, ParseCPUProfileSamplesIntoTable) {
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_incremental_state_cleared(true);
auto* thread_desc = packet->set_thread_descriptor();
thread_desc->set_pid(15);
thread_desc->set_tid(16);
thread_desc->set_reference_timestamp_us(1);
thread_desc->set_reference_thread_time_us(2);
auto* interned_data = packet->set_interned_data();
auto mapping = interned_data->add_mappings();
mapping->set_iid(1);
mapping->set_build_id(1);
auto build_id = interned_data->add_build_ids();
build_id->set_iid(1);
build_id->set_str("3BBCFBD372448A727265C3E7C4D954F91");
auto frame = interned_data->add_frames();
frame->set_iid(1);
frame->set_rel_pc(0x42);
frame->set_mapping_id(1);
auto frame2 = interned_data->add_frames();
frame2->set_iid(2);
frame2->set_rel_pc(0x4242);
frame2->set_mapping_id(1);
auto callstack = interned_data->add_callstacks();
callstack->set_iid(1);
callstack->add_frame_ids(1);
auto callstack2 = interned_data->add_callstacks();
callstack2->set_iid(42);
callstack2->add_frame_ids(2);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* samples = packet->set_streaming_profile_packet();
samples->add_callstack_iid(42);
samples->add_timestamp_delta_us(10);
samples->add_callstack_iid(1);
samples->add_timestamp_delta_us(15);
samples->set_process_priority(20);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* samples = packet->set_streaming_profile_packet();
samples->add_callstack_iid(42);
samples->add_timestamp_delta_us(42);
samples->set_process_priority(30);
}
EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
Tokenize();
context_.sorter->ExtractEventsForced();
// Verify cpu_profile_samples.
const auto& samples = storage_->cpu_profile_stack_sample_table();
EXPECT_EQ(samples.row_count(), 3u);
EXPECT_EQ(samples.ts()[0], 11000);
EXPECT_EQ(samples.callsite_id()[0], CallsiteId{0});
EXPECT_EQ(samples.utid()[0], 1u);
EXPECT_EQ(samples.process_priority()[0], 20);
EXPECT_EQ(samples.ts()[1], 26000);
EXPECT_EQ(samples.callsite_id()[1], CallsiteId{1});
EXPECT_EQ(samples.utid()[1], 1u);
EXPECT_EQ(samples.process_priority()[1], 20);
EXPECT_EQ(samples.ts()[2], 68000);
EXPECT_EQ(samples.callsite_id()[2], CallsiteId{0});
EXPECT_EQ(samples.utid()[2], 1u);
EXPECT_EQ(samples.process_priority()[2], 30);
// Breakpad build_ids should not be modified/mangled.
ASSERT_STREQ(
context_.storage
->GetString(storage_->stack_profile_mapping_table().build_id()[0])
.c_str(),
"3BBCFBD372448A727265C3E7C4D954F91");
}
TEST_F(ProtoTraceParserTest, CPUProfileSamplesTimestampsAreClockMonotonic) {
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(0);
// 1000 us monotonic == 10000 us boottime.
auto* clock_snapshot = packet->set_clock_snapshot();
auto* clock_boot = clock_snapshot->add_clocks();
clock_boot->set_clock_id(protos::pbzero::BUILTIN_CLOCK_BOOTTIME);
clock_boot->set_timestamp(10000000);
auto* clock_monotonic = clock_snapshot->add_clocks();
clock_monotonic->set_clock_id(protos::pbzero::BUILTIN_CLOCK_MONOTONIC);
clock_monotonic->set_timestamp(1000000);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
packet->set_incremental_state_cleared(true);
auto* thread_desc = packet->set_thread_descriptor();
thread_desc->set_pid(15);
thread_desc->set_tid(16);
thread_desc->set_reference_timestamp_us(1000);
thread_desc->set_reference_thread_time_us(2000);
auto* interned_data = packet->set_interned_data();
auto mapping = interned_data->add_mappings();
mapping->set_iid(1);
mapping->set_build_id(1);
auto build_id = interned_data->add_build_ids();
build_id->set_iid(1);
build_id->set_str("3BBCFBD372448A727265C3E7C4D954F91");
auto frame = interned_data->add_frames();
frame->set_iid(1);
frame->set_rel_pc(0x42);
frame->set_mapping_id(1);
auto callstack = interned_data->add_callstacks();
callstack->set_iid(1);
callstack->add_frame_ids(1);
}
{
auto* packet = trace_->add_packet();
packet->set_trusted_packet_sequence_id(1);
auto* samples = packet->set_streaming_profile_packet();
samples->add_callstack_iid(1);
samples->add_timestamp_delta_us(15);
}
EXPECT_CALL(*process_, UpdateThread(16, 15)).WillRepeatedly(Return(1u));
Tokenize();
context_.sorter->ExtractEventsForced();
const auto& samples = storage_->cpu_profile_stack_sample_table();
EXPECT_EQ(samples.row_count(), 1u);
// Should have been translated to boottime, i.e. 10015 us absolute.
EXPECT_EQ(samples.ts()[0], 10015000);
EXPECT_EQ(samples.callsite_id()[0], CallsiteId{0});
EXPECT_EQ(samples.utid()[0], 1u);
}
TEST_F(ProtoTraceParserTest, ConfigUuid) {
auto* config = trace_->add_packet()->set_trace_config();
config->set_trace_uuid_lsb(1);
config->set_trace_uuid_msb(2);
ASSERT_TRUE(Tokenize().ok());
context_.sorter->ExtractEventsForced();
SqlValue value = context_.metadata_tracker->GetMetadata(metadata::trace_uuid);
EXPECT_STREQ(value.string_value, "00000000-0000-0002-0000-000000000001");
ASSERT_TRUE(context_.uuid_found_in_trace);
}
TEST_F(ProtoTraceParserTest, PacketUuid) {
auto* uuid = trace_->add_packet()->set_trace_uuid();
uuid->set_lsb(1);
uuid->set_msb(2);
ASSERT_TRUE(Tokenize().ok());
context_.sorter->ExtractEventsForced();
SqlValue value = context_.metadata_tracker->GetMetadata(metadata::trace_uuid);
EXPECT_STREQ(value.string_value, "00000000-0000-0002-0000-000000000001");
ASSERT_TRUE(context_.uuid_found_in_trace);
}
// If both the TraceConfig and TracePacket.trace_uuid are present, the latter
// is considered the source of truth.
TEST_F(ProtoTraceParserTest, PacketAndConfigUuid) {
auto* uuid = trace_->add_packet()->set_trace_uuid();
uuid->set_lsb(1);
uuid->set_msb(2);
auto* config = trace_->add_packet()->set_trace_config();
config->set_trace_uuid_lsb(42);
config->set_trace_uuid_msb(42);
ASSERT_TRUE(Tokenize().ok());
context_.sorter->ExtractEventsForced();
SqlValue value = context_.metadata_tracker->GetMetadata(metadata::trace_uuid);
EXPECT_STREQ(value.string_value, "00000000-0000-0002-0000-000000000001");
ASSERT_TRUE(context_.uuid_found_in_trace);
}
TEST_F(ProtoTraceParserTest, ConfigPbtxt) {
auto* config = trace_->add_packet()->set_trace_config();
config->add_buffers()->set_size_kb(42);
ASSERT_TRUE(Tokenize().ok());
context_.sorter->ExtractEventsForced();
SqlValue value =
context_.metadata_tracker->GetMetadata(metadata::trace_config_pbtxt);
EXPECT_THAT(value.string_value, HasSubstr("size_kb: 42"));
}
} // namespace
} // namespace trace_processor
} // namespace perfetto