Skip to content

GitLab

T
tangled
Commit 923d1c42 authored by Eric Seckler's avatar Eric Seckler Committed by Commit Bot
Browse files
Options

tracing: Switch to counter tracks for thread time / instruction count 

Encode thread time + instruction count using counter tracks in the
proto format. This should also pave the way to add more counters in the
future.

Bug: 928738
Change-Id: I6524aa99d630f7f156606cdde9f0f50a7735c31a
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2139822
Commit-Queue: Eric Seckler <eseckler@chromium.org>
Reviewed-by: default avatarSami Kyöstilä <skyostil@chromium.org>
Cr-Commit-Position: refs/heads/master@{#757818}
parent 11de47f6
Hide whitespace changes
Inline Side-by-side
Showing with 275 additions and 227 deletions
services/tracing/perfetto/privacy_filtered_fields-inl.h
View file @ 923d1c42
...@@ -135,6 +135,11 @@ constexpr MessageInfo kChromeCompositorSchedulerState = { ...@@ -135,6 +135,11 @@ constexpr MessageInfo kChromeCompositorSchedulerState = {
constexpr int kChromeUserEventIndices[] = {2, -1}; constexpr int kChromeUserEventIndices[] = {2, -1};
constexpr MessageInfo kChromeUserEvent = {kChromeUserEventIndices, nullptr}; constexpr MessageInfo kChromeUserEvent = {kChromeUserEventIndices, nullptr};
// Proto Message: ChromeKeyedService
constexpr int kChromeKeyedServiceIndices[] = {1, -1};
constexpr MessageInfo kChromeKeyedService = {kChromeKeyedServiceIndices,
nullptr};
// Proto Message: ChromeLegacyIpc // Proto Message: ChromeLegacyIpc
constexpr int kChromeLegacyIpcIndices[] = {1, 2, -1}; constexpr int kChromeLegacyIpcIndices[] = {1, 2, -1};
constexpr MessageInfo kChromeLegacyIpc = {kChromeLegacyIpcIndices, nullptr}; constexpr MessageInfo kChromeLegacyIpc = {kChromeLegacyIpcIndices, nullptr};
...@@ -146,25 +151,18 @@ constexpr MessageInfo kChromeHistogramSample = {kChromeHistogramSampleIndices, ...@@ -146,25 +151,18 @@ constexpr MessageInfo kChromeHistogramSample = {kChromeHistogramSampleIndices,
// Proto Message: ComponentInfo // Proto Message: ComponentInfo
constexpr int kComponentInfoIndices[] = {1, 2, -1}; constexpr int kComponentInfoIndices[] = {1, 2, -1};
constexpr MessageInfo kComponentInfo = { constexpr MessageInfo kComponentInfo = {kComponentInfoIndices, nullptr};
kComponentInfoIndices,
nullptr};
// Proto Message: ChromeLatencyInfo // Proto Message: ChromeLatencyInfo
constexpr int kChromeLatencyInfoIndices[] = {1, 2, 3, 4, 5, -1}; constexpr int kChromeLatencyInfoIndices[] = {1, 2, 3, 4, 5, -1};
constexpr MessageInfo const* kChromeLatencyInfoComplexMessages[] = { constexpr MessageInfo const* kChromeLatencyInfoComplexMessages[] = {
nullptr, nullptr, nullptr, nullptr, &kComponentInfo, nullptr};
nullptr,
nullptr,
&kComponentInfo,
nullptr};
constexpr MessageInfo kChromeLatencyInfo = {kChromeLatencyInfoIndices, constexpr MessageInfo kChromeLatencyInfo = {kChromeLatencyInfoIndices,
kChromeLatencyInfoComplexMessages}; kChromeLatencyInfoComplexMessages};
// Proto Message: TrackEvent // Proto Message: TrackEvent
// EDIT: Manually whitelisted: 29 (chrome_latency_info). constexpr int kTrackEventIndices[] = {1, 2, 3, 5, 6, 9, 10, 11, 12, 16,
constexpr int kTrackEventIndices[] = {1, 2, 3, 5, 6, 9, 10, 11, 17, 24, 25, 26, 27, 28, 29, 30, 31, -1};
16, 17, 24, 25, 27, 28, 29, -1};
constexpr MessageInfo const* kTrackEventComplexMessages[] = { constexpr MessageInfo const* kTrackEventComplexMessages[] = {
nullptr, nullptr,
nullptr, nullptr,
...@@ -176,11 +174,15 @@ constexpr MessageInfo const* kTrackEventComplexMessages[] = { ...@@ -176,11 +174,15 @@ constexpr MessageInfo const* kTrackEventComplexMessages[] = {
nullptr, nullptr,
nullptr, nullptr,
nullptr, nullptr,
nullptr,
&kChromeCompositorSchedulerState, &kChromeCompositorSchedulerState,
&kChromeUserEvent, &kChromeUserEvent,
&kChromeKeyedService,
&kChromeLegacyIpc, &kChromeLegacyIpc,
&kChromeHistogramSample, &kChromeHistogramSample,
&kChromeLatencyInfo}; &kChromeLatencyInfo,
nullptr,
nullptr};
constexpr MessageInfo kTrackEvent = {kTrackEventIndices, constexpr MessageInfo kTrackEvent = {kTrackEventIndices,
kTrackEventComplexMessages}; kTrackEventComplexMessages};
...@@ -303,7 +305,8 @@ constexpr MessageInfo kHeapGraph = {kHeapGraphIndices, ...@@ -303,7 +305,8 @@ constexpr MessageInfo kHeapGraph = {kHeapGraphIndices,
kHeapGraphComplexMessages}; kHeapGraphComplexMessages};
// Proto Message: TrackEventDefaults // Proto Message: TrackEventDefaults
constexpr int kTrackEventDefaultsIndices[] = {11, -1}; // Manually whitelisted: 31.
constexpr int kTrackEventDefaultsIndices[] = {11, 31, -1};
constexpr MessageInfo kTrackEventDefaults = {kTrackEventDefaultsIndices, constexpr MessageInfo kTrackEventDefaults = {kTrackEventDefaultsIndices,
nullptr}; nullptr};
...@@ -324,11 +327,20 @@ constexpr int kChromeThreadDescriptorIndices[] = {1, 2, -1}; ...@@ -324,11 +327,20 @@ constexpr int kChromeThreadDescriptorIndices[] = {1, 2, -1};
constexpr MessageInfo kChromeThreadDescriptor = {kChromeThreadDescriptorIndices, constexpr MessageInfo kChromeThreadDescriptor = {kChromeThreadDescriptorIndices,
nullptr}; nullptr};
// Proto Message: CounterDescriptor
constexpr int kCounterDescriptorIndices[] = {1, 3, 4, 5, -1};
constexpr MessageInfo kCounterDescriptor = {kCounterDescriptorIndices, nullptr};
// Proto Message: TrackDescriptor // Proto Message: TrackDescriptor
constexpr int kTrackDescriptorIndices[] = {1, 3, 4, 5, 6, 7, -1}; constexpr int kTrackDescriptorIndices[] = {1, 3, 4, 5, 6, 7, 8, -1};
constexpr MessageInfo const* kTrackDescriptorComplexMessages[] = { constexpr MessageInfo const* kTrackDescriptorComplexMessages[] = {
nullptr, &kProcessDescriptor, &kThreadDescriptor, nullptr,
nullptr, &kChromeProcessDescriptor, &kChromeThreadDescriptor}; &kProcessDescriptor,
&kThreadDescriptor,
nullptr,
&kChromeProcessDescriptor,
&kChromeThreadDescriptor,
&kCounterDescriptor};
constexpr MessageInfo kTrackDescriptor = {kTrackDescriptorIndices, constexpr MessageInfo kTrackDescriptor = {kTrackDescriptorIndices,
kTrackDescriptorComplexMessages}; kTrackDescriptorComplexMessages};
......
services/tracing/public/cpp/perfetto/trace_event_data_source_unittest.cc
View file @ 923d1c42
...@@ -45,6 +45,7 @@ ...@@ -45,6 +45,7 @@
#include "third_party/perfetto/protos/perfetto/trace/trace_packet.pbzero.h" #include "third_party/perfetto/protos/perfetto/trace/trace_packet.pbzero.h"
#include "third_party/perfetto/protos/perfetto/trace/track_event/chrome_process_descriptor.pb.h" #include "third_party/perfetto/protos/perfetto/trace/track_event/chrome_process_descriptor.pb.h"
#include "third_party/perfetto/protos/perfetto/trace/track_event/chrome_thread_descriptor.pb.h" #include "third_party/perfetto/protos/perfetto/trace/track_event/chrome_thread_descriptor.pb.h"
#include "third_party/perfetto/protos/perfetto/trace/track_event/counter_descriptor.pb.h"
#include "third_party/perfetto/protos/perfetto/trace/track_event/log_message.pbzero.h" #include "third_party/perfetto/protos/perfetto/trace/track_event/log_message.pbzero.h"
#include "third_party/perfetto/protos/perfetto/trace/track_event/process_descriptor.pb.h" #include "third_party/perfetto/protos/perfetto/trace/track_event/process_descriptor.pb.h"
#include "third_party/perfetto/protos/perfetto/trace/track_event/thread_descriptor.pb.h" #include "third_party/perfetto/protos/perfetto/trace/track_event/thread_descriptor.pb.h"
...@@ -63,6 +64,12 @@ constexpr const char kCategoryGroup[] = "foo"; ...@@ -63,6 +64,12 @@ constexpr const char kCategoryGroup[] = "foo";
constexpr uint32_t kClockIdAbsolute = 64; constexpr uint32_t kClockIdAbsolute = 64;
constexpr uint32_t kClockIdIncremental = 65; constexpr uint32_t kClockIdIncremental = 65;
base::ThreadTicks ThreadNow() {
return base::ThreadTicks::IsSupported()
? base::subtle::ThreadTicksNowIgnoringOverride()
: base::ThreadTicks();
}
class MockProducerClient : public ProducerClient { class MockProducerClient : public ProducerClient {
public: public:
explicit MockProducerClient( explicit MockProducerClient(
...@@ -341,9 +348,23 @@ class TraceEventDataSourceTest : public testing::Test { ...@@ -341,9 +348,23 @@ class TraceEventDataSourceTest : public testing::Test {
packet->trace_packet_defaults().track_event_defaults().track_uuid(), packet->trace_packet_defaults().track_event_defaults().track_uuid(),
0u); 0u);
if (base::ThreadTicks::IsSupported()) {
EXPECT_GT(packet->trace_packet_defaults()
.track_event_defaults()
.extra_counter_track_uuids_size(),
0);
}
default_track_uuid_ = default_track_uuid_ =
packet->trace_packet_defaults().track_event_defaults().track_uuid(); packet->trace_packet_defaults().track_event_defaults().track_uuid();
default_extra_counter_track_uuids_.clear();
for (const auto& uuid : packet->trace_packet_defaults()
.track_event_defaults()
.extra_counter_track_uuids()) {
default_extra_counter_track_uuids_.push_back(uuid);
}
// ClockSnapshot is only emitted when incremental state was reset, and // ClockSnapshot is only emitted when incremental state was reset, and
// thus also always serves as indicator for the state reset to the consumer. // thus also always serves as indicator for the state reset to the consumer.
EXPECT_EQ(packet->sequence_flags(), EXPECT_EQ(packet->sequence_flags(),
...@@ -353,7 +374,6 @@ class TraceEventDataSourceTest : public testing::Test { ...@@ -353,7 +374,6 @@ class TraceEventDataSourceTest : public testing::Test {
void ExpectThreadTrack(const perfetto::protos::TracePacket* packet, void ExpectThreadTrack(const perfetto::protos::TracePacket* packet,
uint64_t min_timestamp = 1u, uint64_t min_timestamp = 1u,
uint64_t min_thread_time = 1u,
bool filtering_enabled = false) { bool filtering_enabled = false) {
ASSERT_TRUE(packet->has_track_descriptor()); ASSERT_TRUE(packet->has_track_descriptor());
ASSERT_TRUE(packet->track_descriptor().has_thread()); ASSERT_TRUE(packet->track_descriptor().has_thread());
...@@ -372,13 +392,8 @@ class TraceEventDataSourceTest : public testing::Test { ...@@ -372,13 +392,8 @@ class TraceEventDataSourceTest : public testing::Test {
EXPECT_FALSE( EXPECT_FALSE(
packet->track_descriptor().thread().has_reference_timestamp_us()); packet->track_descriptor().thread().has_reference_timestamp_us());
EXPECT_FALSE(
EXPECT_GE(packet->track_descriptor().thread().reference_thread_time_us(), packet->track_descriptor().thread().has_reference_thread_time_us());
last_thread_time_);
if (base::ThreadTicks::IsSupported()) {
EXPECT_LE(packet->track_descriptor().thread().reference_thread_time_us(),
base::ThreadTicks::Now().since_origin().InMicroseconds());
}
if (filtering_enabled) { if (filtering_enabled) {
EXPECT_FALSE(packet->track_descriptor().thread().has_thread_name()); EXPECT_FALSE(packet->track_descriptor().thread().has_thread_name());
...@@ -389,15 +404,29 @@ class TraceEventDataSourceTest : public testing::Test { ...@@ -389,15 +404,29 @@ class TraceEventDataSourceTest : public testing::Test {
EXPECT_EQ(perfetto::protos::ChromeThreadDescriptor::THREAD_MAIN, EXPECT_EQ(perfetto::protos::ChromeThreadDescriptor::THREAD_MAIN,
packet->track_descriptor().chrome_thread().thread_type()); packet->track_descriptor().chrome_thread().thread_type());
last_thread_time_ =
packet->track_descriptor().thread().reference_thread_time_us();
EXPECT_EQ(packet->interned_data().event_categories_size(), 0); EXPECT_EQ(packet->interned_data().event_categories_size(), 0);
EXPECT_EQ(packet->interned_data().event_names_size(), 0); EXPECT_EQ(packet->interned_data().event_names_size(), 0);
EXPECT_EQ(packet->sequence_flags(), 0u); EXPECT_EQ(packet->sequence_flags(), 0u);
} }
void ExpectThreadTimeCounterTrack(
const perfetto::protos::TracePacket* packet) {
EXPECT_NE(packet->track_descriptor().uuid(), 0u);
EXPECT_NE(packet->track_descriptor().parent_uuid(), 0u);
EXPECT_EQ(packet->track_descriptor().uuid(),
default_extra_counter_track_uuids_[0]);
EXPECT_EQ(packet->track_descriptor().parent_uuid(), default_track_uuid_);
EXPECT_EQ(packet->track_descriptor().counter().type(),
perfetto::protos::CounterDescriptor::COUNTER_THREAD_TIME_NS);
EXPECT_EQ(packet->track_descriptor().counter().unit_multiplier(), 1000u);
EXPECT_TRUE(packet->track_descriptor().counter().is_incremental());
last_thread_time_ = 0;
}
void ExpectProcessTrack(const perfetto::protos::TracePacket* packet, void ExpectProcessTrack(const perfetto::protos::TracePacket* packet,
bool filtering_enabled = false) { bool filtering_enabled = false) {
ASSERT_TRUE(packet->has_track_descriptor()); ASSERT_TRUE(packet->has_track_descriptor());
...@@ -429,20 +458,23 @@ class TraceEventDataSourceTest : public testing::Test { ...@@ -429,20 +458,23 @@ class TraceEventDataSourceTest : public testing::Test {
SEQ_INCREMENTAL_STATE_CLEARED)); SEQ_INCREMENTAL_STATE_CLEARED));
} }
void ExpectStandardPreamble(size_t first_packet_index = 0, size_t ExpectStandardPreamble(size_t packet_index = 0,
bool privacy_filtering_enabled = false) { bool privacy_filtering_enabled = false) {
EXPECT_GE(producer_client()->GetFinalizedPacketCount(), 3u); auto* pt_packet = producer_client()->GetFinalizedPacket(packet_index++);
auto* pt_packet = producer_client()->GetFinalizedPacket(first_packet_index);
ExpectProcessTrack(pt_packet, privacy_filtering_enabled); ExpectProcessTrack(pt_packet, privacy_filtering_enabled);
auto* clock_packet = auto* clock_packet = producer_client()->GetFinalizedPacket(packet_index++);
producer_client()->GetFinalizedPacket(first_packet_index + 1);
ExpectClockSnapshotAndDefaults(clock_packet); ExpectClockSnapshotAndDefaults(clock_packet);
auto* tt_packet = auto* tt_packet = producer_client()->GetFinalizedPacket(packet_index++);
producer_client()->GetFinalizedPacket(first_packet_index + 2); ExpectThreadTrack(tt_packet, 1u, privacy_filtering_enabled);
ExpectThreadTrack(tt_packet, 1u, 1u, privacy_filtering_enabled);
if (base::ThreadTicks::IsSupported()) {
auto* ttt_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectThreadTimeCounterTrack(ttt_packet);
}
return packet_index;
} }
void ExpectTraceEvent(const perfetto::protos::TracePacket* packet, void ExpectTraceEvent(const perfetto::protos::TracePacket* packet,
...@@ -474,11 +506,14 @@ class TraceEventDataSourceTest : public testing::Test { ...@@ -474,11 +506,14 @@ class TraceEventDataSourceTest : public testing::Test {
TRACE_TIME_TICKS_NOW().since_origin().InMicroseconds())); TRACE_TIME_TICKS_NOW().since_origin().InMicroseconds()));
last_timestamp_ += packet->timestamp(); last_timestamp_ += packet->timestamp();
} }
if (packet->track_event().has_thread_time_delta_us()) {
EXPECT_LE( EXPECT_EQ(packet->track_event().extra_counter_track_uuids_size(), 0);
last_thread_time_ + packet->track_event().thread_time_delta_us(), if (packet->track_event().extra_counter_values_size()) {
TRACE_TIME_TICKS_NOW().since_origin().InMicroseconds()); int64_t thread_time_delta =
last_thread_time_ += packet->track_event().thread_time_delta_us(); packet->track_event().extra_counter_values()[0];
EXPECT_LE(last_thread_time_ + thread_time_delta,
TRACE_TIME_TICKS_NOW().since_origin().InMicroseconds());
last_thread_time_ += thread_time_delta;
} }
if (category_iid > 0) { if (category_iid > 0) {
...@@ -670,6 +705,7 @@ class TraceEventDataSourceTest : public testing::Test { ...@@ -670,6 +705,7 @@ class TraceEventDataSourceTest : public testing::Test {
int64_t last_thread_time_ = 0; int64_t last_thread_time_ = 0;
uint64_t default_track_uuid_ = 0u; uint64_t default_track_uuid_ = 0u;
uint64_t process_track_uuid_ = 0u; uint64_t process_track_uuid_ = 0u;
std::vector<uint64_t> default_extra_counter_track_uuids_;
std::string old_thread_name_; std::string old_thread_name_;
std::string old_process_name_; std::string old_process_name_;
...@@ -813,10 +849,9 @@ TEST_F(TraceEventDataSourceTest, BasicTraceEvent) { ...@@ -813,10 +849,9 @@ TEST_F(TraceEventDataSourceTest, BasicTraceEvent) {
TRACE_EVENT_BEGIN0(kCategoryGroup, "bar"); TRACE_EVENT_BEGIN0(kCategoryGroup, "bar");
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_BEGIN); TRACE_EVENT_PHASE_BEGIN);
...@@ -853,10 +888,9 @@ TEST_F(TraceEventDataSourceTest, TimestampedTraceEvent) { ...@@ -853,10 +888,9 @@ TEST_F(TraceEventDataSourceTest, TimestampedTraceEvent) {
kCategoryGroup, "bar", 42, 4242, kCategoryGroup, "bar", 42, 4242,
base::TimeTicks() + base::TimeDelta::FromMicroseconds(424242)); base::TimeTicks() + base::TimeDelta::FromMicroseconds(424242));
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent( ExpectTraceEvent(
e_packet, /*category_iid=*/1u, /*name_iid=*/1u, e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_ASYNC_BEGIN, TRACE_EVENT_PHASE_ASYNC_BEGIN,
...@@ -872,10 +906,9 @@ TEST_F(TraceEventDataSourceTest, InstantTraceEvent) { ...@@ -872,10 +906,9 @@ TEST_F(TraceEventDataSourceTest, InstantTraceEvent) {
TRACE_EVENT_INSTANT0(kCategoryGroup, "bar", TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_INSTANT0(kCategoryGroup, "bar", TRACE_EVENT_SCOPE_THREAD);
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
...@@ -889,10 +922,9 @@ TEST_F(TraceEventDataSourceTest, EventWithStringArgs) { ...@@ -889,10 +922,9 @@ TEST_F(TraceEventDataSourceTest, EventWithStringArgs) {
TRACE_EVENT_INSTANT2(kCategoryGroup, "bar", TRACE_EVENT_SCOPE_THREAD, TRACE_EVENT_INSTANT2(kCategoryGroup, "bar", TRACE_EVENT_SCOPE_THREAD,
"arg1_name", "arg1_val", "arg2_name", "arg2_val"); "arg1_name", "arg1_val", "arg2_name", "arg2_val");
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
...@@ -915,10 +947,9 @@ TEST_F(TraceEventDataSourceTest, EventWithCopiedStrings) { ...@@ -915,10 +947,9 @@ TEST_F(TraceEventDataSourceTest, EventWithCopiedStrings) {
TRACE_EVENT_SCOPE_THREAD | TRACE_EVENT_FLAG_COPY, TRACE_EVENT_SCOPE_THREAD | TRACE_EVENT_FLAG_COPY,
"arg1_name", "arg1_val", "arg2_name", "arg2_val"); "arg1_name", "arg1_val", "arg2_name", "arg2_val");
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_PHASE_INSTANT,
TRACE_EVENT_SCOPE_THREAD | TRACE_EVENT_FLAG_COPY); TRACE_EVENT_SCOPE_THREAD | TRACE_EVENT_FLAG_COPY);
...@@ -941,10 +972,9 @@ TEST_F(TraceEventDataSourceTest, EventWithUIntArgs) { ...@@ -941,10 +972,9 @@ TEST_F(TraceEventDataSourceTest, EventWithUIntArgs) {
TRACE_EVENT_INSTANT2(kCategoryGroup, "bar", TRACE_EVENT_SCOPE_THREAD, "foo", TRACE_EVENT_INSTANT2(kCategoryGroup, "bar", TRACE_EVENT_SCOPE_THREAD, "foo",
42u, "bar", 4242u); 42u, "bar", 4242u);
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
...@@ -960,10 +990,9 @@ TEST_F(TraceEventDataSourceTest, EventWithIntArgs) { ...@@ -960,10 +990,9 @@ TEST_F(TraceEventDataSourceTest, EventWithIntArgs) {
TRACE_EVENT_INSTANT2(kCategoryGroup, "bar", TRACE_EVENT_SCOPE_THREAD, "foo", TRACE_EVENT_INSTANT2(kCategoryGroup, "bar", TRACE_EVENT_SCOPE_THREAD, "foo",
42, "bar", 4242); 42, "bar", 4242);
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
...@@ -979,10 +1008,9 @@ TEST_F(TraceEventDataSourceTest, EventWithBoolArgs) { ...@@ -979,10 +1008,9 @@ TEST_F(TraceEventDataSourceTest, EventWithBoolArgs) {
TRACE_EVENT_INSTANT2(kCategoryGroup, "bar", TRACE_EVENT_SCOPE_THREAD, "foo", TRACE_EVENT_INSTANT2(kCategoryGroup, "bar", TRACE_EVENT_SCOPE_THREAD, "foo",
true, "bar", false); true, "bar", false);
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
...@@ -1000,10 +1028,9 @@ TEST_F(TraceEventDataSourceTest, EventWithDoubleArgs) { ...@@ -1000,10 +1028,9 @@ TEST_F(TraceEventDataSourceTest, EventWithDoubleArgs) {
TRACE_EVENT_INSTANT2(kCategoryGroup, "bar", TRACE_EVENT_SCOPE_THREAD, "foo", TRACE_EVENT_INSTANT2(kCategoryGroup, "bar", TRACE_EVENT_SCOPE_THREAD, "foo",
42.42, "bar", 4242.42); 42.42, "bar", 4242.42);
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
...@@ -1020,10 +1047,9 @@ TEST_F(TraceEventDataSourceTest, EventWithPointerArgs) { ...@@ -1020,10 +1047,9 @@ TEST_F(TraceEventDataSourceTest, EventWithPointerArgs) {
reinterpret_cast<void*>(0xBEEF), "bar", reinterpret_cast<void*>(0xBEEF), "bar",
reinterpret_cast<void*>(0xF00D)); reinterpret_cast<void*>(0xF00D));
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
...@@ -1066,10 +1092,9 @@ TEST_F(TraceEventDataSourceTest, EventWithConvertableArgs) { ...@@ -1066,10 +1092,9 @@ TEST_F(TraceEventDataSourceTest, EventWithConvertableArgs) {
EXPECT_EQ(2, num_calls); EXPECT_EQ(2, num_calls);
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
...@@ -1091,10 +1116,9 @@ TEST_F(TraceEventDataSourceTest, TaskExecutionEvent) { ...@@ -1091,10 +1116,9 @@ TEST_F(TraceEventDataSourceTest, TaskExecutionEvent) {
TRACE_EVENT_SCOPE_THREAD | TRACE_EVENT_FLAG_TYPED_PROTO_ARGS, "src_file", TRACE_EVENT_SCOPE_THREAD | TRACE_EVENT_FLAG_TYPED_PROTO_ARGS, "src_file",
"my_file", "src_func", "my_func"); "my_file", "src_func", "my_func");
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 5u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
...@@ -1108,7 +1132,7 @@ TEST_F(TraceEventDataSourceTest, TaskExecutionEvent) { ...@@ -1108,7 +1132,7 @@ TEST_F(TraceEventDataSourceTest, TaskExecutionEvent) {
EXPECT_EQ(locations[0].function_name(), "my_func"); EXPECT_EQ(locations[0].function_name(), "my_func");
// Second event should refer to the same interning entries. // Second event should refer to the same interning entries.
auto* e_packet2 = producer_client()->GetFinalizedPacket(4); auto* e_packet2 = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet2, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet2, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
...@@ -1124,10 +1148,9 @@ TEST_F(TraceEventDataSourceTest, TaskExecutionEventWithoutFunction) { ...@@ -1124,10 +1148,9 @@ TEST_F(TraceEventDataSourceTest, TaskExecutionEventWithoutFunction) {
TRACE_EVENT_SCOPE_THREAD | TRACE_EVENT_FLAG_TYPED_PROTO_ARGS, "src", TRACE_EVENT_SCOPE_THREAD | TRACE_EVENT_FLAG_TYPED_PROTO_ARGS, "src",
"my_file"); "my_file");
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
...@@ -1162,10 +1185,9 @@ TEST_F(TraceEventDataSourceTest, UpdateDurationOfCompleteEvent) { ...@@ -1162,10 +1185,9 @@ TEST_F(TraceEventDataSourceTest, UpdateDurationOfCompleteEvent) {
trace_event_trace_id.id_flags() | TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP, trace_event_trace_id.id_flags() | TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP,
trace_event_internal::kNoId); trace_event_internal::kNoId);
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* b_packet = producer_client()->GetFinalizedPacket(3); auto* b_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent( ExpectTraceEvent(
b_packet, /*category_iid=*/1u, /*name_iid=*/1u, TRACE_EVENT_PHASE_BEGIN, b_packet, /*category_iid=*/1u, /*name_iid=*/1u, TRACE_EVENT_PHASE_BEGIN,
TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP | TRACE_EVENT_FLAG_HAS_ID, /*id=*/0u, TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP | TRACE_EVENT_FLAG_HAS_ID, /*id=*/0u,
...@@ -1177,12 +1199,10 @@ TEST_F(TraceEventDataSourceTest, UpdateDurationOfCompleteEvent) { ...@@ -1177,12 +1199,10 @@ TEST_F(TraceEventDataSourceTest, UpdateDurationOfCompleteEvent) {
base::trace_event::TraceLog::GetInstance()->UpdateTraceEventDurationExplicit( base::trace_event::TraceLog::GetInstance()->UpdateTraceEventDurationExplicit(
category_group_enabled, kEventName, handle, /*thread_id=*/1, category_group_enabled, kEventName, handle, /*thread_id=*/1,
/*explicit_timestamps=*/true, /*explicit_timestamps=*/true,
base::TimeTicks() + base::TimeDelta::FromMicroseconds(30), base::TimeTicks() + base::TimeDelta::FromMicroseconds(30), ThreadNow(),
base::ThreadTicks() + base::TimeDelta::FromMicroseconds(50),
base::trace_event::ThreadInstructionCount()); base::trace_event::ThreadInstructionCount());
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 5u); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
auto* e_packet = producer_client()->GetFinalizedPacket(4);
ExpectTraceEvent( ExpectTraceEvent(
e_packet, /*category_iid=*/0u, /*name_iid=*/0u, TRACE_EVENT_PHASE_END, e_packet, /*category_iid=*/0u, /*name_iid=*/0u, TRACE_EVENT_PHASE_END,
TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP, /*id=*/0u, TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP, /*id=*/0u,
...@@ -1194,12 +1214,10 @@ TEST_F(TraceEventDataSourceTest, UpdateDurationOfCompleteEvent) { ...@@ -1194,12 +1214,10 @@ TEST_F(TraceEventDataSourceTest, UpdateDurationOfCompleteEvent) {
base::trace_event::TraceLog::GetInstance()->UpdateTraceEventDurationExplicit( base::trace_event::TraceLog::GetInstance()->UpdateTraceEventDurationExplicit(
category_group_enabled, "other_event_name", handle, /*thread_id=*/1, category_group_enabled, "other_event_name", handle, /*thread_id=*/1,
/*explicit_timestamps=*/true, /*explicit_timestamps=*/true,
base::TimeTicks() + base::TimeDelta::FromMicroseconds(40), base::TimeTicks() + base::TimeDelta::FromMicroseconds(40), ThreadNow(),
base::ThreadTicks() + base::TimeDelta::FromMicroseconds(60),
base::trace_event::ThreadInstructionCount()); base::trace_event::ThreadInstructionCount());
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 6u); auto* e2_packet = producer_client()->GetFinalizedPacket(packet_index++);
auto* e2_packet = producer_client()->GetFinalizedPacket(5);
ExpectTraceEvent( ExpectTraceEvent(
e2_packet, /*category_iid=*/0u, /*name_iid=*/0u, TRACE_EVENT_PHASE_END, e2_packet, /*category_iid=*/0u, /*name_iid=*/0u, TRACE_EVENT_PHASE_END,
TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP, /*id=*/0u, TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP, /*id=*/0u,
...@@ -1214,16 +1232,16 @@ TEST_F(TraceEventDataSourceTest, UpdateDurationOfCompleteEvent) { ...@@ -1214,16 +1232,16 @@ TEST_F(TraceEventDataSourceTest, UpdateDurationOfCompleteEvent) {
TEST_F(TraceEventDataSourceTest, InternedStrings) { TEST_F(TraceEventDataSourceTest, InternedStrings) {
CreateTraceEventDataSource(); CreateTraceEventDataSource();
size_t packet_index = 0u;
for (size_t i = 0; i < 2; i++) { for (size_t i = 0; i < 2; i++) {
TRACE_EVENT_INSTANT1("cat1", "e1", TRACE_EVENT_SCOPE_THREAD, "arg1", 4); TRACE_EVENT_INSTANT1("cat1", "e1", TRACE_EVENT_SCOPE_THREAD, "arg1", 4);
TRACE_EVENT_INSTANT1("cat1", "e1", TRACE_EVENT_SCOPE_THREAD, "arg1", 2); TRACE_EVENT_INSTANT1("cat1", "e1", TRACE_EVENT_SCOPE_THREAD, "arg1", 2);
TRACE_EVENT_INSTANT1("cat2", "e2", TRACE_EVENT_SCOPE_THREAD, "arg2", 1); TRACE_EVENT_INSTANT1("cat2", "e2", TRACE_EVENT_SCOPE_THREAD, "arg2", 1);
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 6u * (i + 1)); packet_index = ExpectStandardPreamble(packet_index);
ExpectStandardPreamble(6 * i); // 3 preamble packets.
// First packet needs to emit new interning entries // First packet needs to emit new interning entries
auto* e_packet1 = producer_client()->GetFinalizedPacket(3 + (6 * i)); auto* e_packet1 = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet1, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet1, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
...@@ -1237,7 +1255,7 @@ TEST_F(TraceEventDataSourceTest, InternedStrings) { ...@@ -1237,7 +1255,7 @@ TEST_F(TraceEventDataSourceTest, InternedStrings) {
ExpectDebugAnnotationNames(e_packet1, {{1u, "arg1"}}); ExpectDebugAnnotationNames(e_packet1, {{1u, "arg1"}});
// Second packet refers to the interning entries from packet 1. // Second packet refers to the interning entries from packet 1.
auto* e_packet2 = producer_client()->GetFinalizedPacket(4 + (6 * i)); auto* e_packet2 = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet2, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet2, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
...@@ -1251,7 +1269,7 @@ TEST_F(TraceEventDataSourceTest, InternedStrings) { ...@@ -1251,7 +1269,7 @@ TEST_F(TraceEventDataSourceTest, InternedStrings) {
ExpectDebugAnnotationNames(e_packet2, {}); ExpectDebugAnnotationNames(e_packet2, {});
// Third packet uses different names, so emits new entries. // Third packet uses different names, so emits new entries.
auto* e_packet3 = producer_client()->GetFinalizedPacket(5 + (6 * i)); auto* e_packet3 = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet3, /*category_iid=*/2u, /*name_iid=*/2u, ExpectTraceEvent(e_packet3, /*category_iid=*/2u, /*name_iid=*/2u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
...@@ -1274,12 +1292,11 @@ TEST_F(TraceEventDataSourceTest, FilteringSimpleTraceEvent) { ...@@ -1274,12 +1292,11 @@ TEST_F(TraceEventDataSourceTest, FilteringSimpleTraceEvent) {
CreateTraceEventDataSource(/* privacy_filtering_enabled =*/true); CreateTraceEventDataSource(/* privacy_filtering_enabled =*/true);
TRACE_EVENT_BEGIN0(kCategoryGroup, "bar"); TRACE_EVENT_BEGIN0(kCategoryGroup, "bar");
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u); size_t packet_index = ExpectStandardPreamble(
ExpectStandardPreamble( /*start_packet_index=*/0u,
/*start_packet_index=*/0, /*privacy_filtering_enabled=*/true);
/*privacy_filtering_enabled=*/true); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_BEGIN); TRACE_EVENT_PHASE_BEGIN);
...@@ -1293,12 +1310,11 @@ TEST_F(TraceEventDataSourceTest, FilteringEventWithArgs) { ...@@ -1293,12 +1310,11 @@ TEST_F(TraceEventDataSourceTest, FilteringEventWithArgs) {
TRACE_EVENT_INSTANT2(kCategoryGroup, "bar", TRACE_EVENT_SCOPE_THREAD, "foo", TRACE_EVENT_INSTANT2(kCategoryGroup, "bar", TRACE_EVENT_SCOPE_THREAD, "foo",
42, "bar", "string_val"); 42, "bar", "string_val");
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u); size_t packet_index = ExpectStandardPreamble(
ExpectStandardPreamble(
/*start_packet_index=*/0u, /*start_packet_index=*/0u,
/*privacy_filtering_enabled=*/true); // 3 preamble packets. /*privacy_filtering_enabled=*/true);
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
...@@ -1320,12 +1336,11 @@ TEST_F(TraceEventDataSourceTest, FilteringEventWithFlagCopy) { ...@@ -1320,12 +1336,11 @@ TEST_F(TraceEventDataSourceTest, FilteringEventWithFlagCopy) {
TRACE_EVENT_FLAG_JAVA_STRING_LITERALS, TRACE_EVENT_FLAG_JAVA_STRING_LITERALS,
"arg1_name", "arg1_val", "arg2_name", "arg2_val"); "arg1_name", "arg1_val", "arg2_name", "arg2_val");
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 5u); size_t packet_index = ExpectStandardPreamble(
ExpectStandardPreamble(
/*start_packet_index=*/0u, /*start_packet_index=*/0u,
/*privacy_filtering_enabled=*/true); // 3 preamble packets. /*privacy_filtering_enabled=*/true);
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
...@@ -1336,7 +1351,7 @@ TEST_F(TraceEventDataSourceTest, FilteringEventWithFlagCopy) { ...@@ -1336,7 +1351,7 @@ TEST_F(TraceEventDataSourceTest, FilteringEventWithFlagCopy) {
ExpectEventNames(e_packet, {{1u, "PRIVACY_FILTERED"}}); ExpectEventNames(e_packet, {{1u, "PRIVACY_FILTERED"}});
ExpectDebugAnnotationNames(e_packet, {}); ExpectDebugAnnotationNames(e_packet, {});
e_packet = producer_client()->GetFinalizedPacket(4); e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/2u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/2u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
...@@ -1421,11 +1436,10 @@ TEST_F(TraceEventDataSourceNoInterningTest, InterningScopedToPackets) { ...@@ -1421,11 +1436,10 @@ TEST_F(TraceEventDataSourceNoInterningTest, InterningScopedToPackets) {
TRACE_EVENT_INSTANT1("cat1", "e1", TRACE_EVENT_SCOPE_THREAD, "arg1", 2); TRACE_EVENT_INSTANT1("cat1", "e1", TRACE_EVENT_SCOPE_THREAD, "arg1", 2);
TRACE_EVENT_INSTANT1("cat2", "e2", TRACE_EVENT_SCOPE_THREAD, "arg2", 1); TRACE_EVENT_INSTANT1("cat2", "e2", TRACE_EVENT_SCOPE_THREAD, "arg2", 1);
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 6u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
// First packet needs to emit new interning entries // First packet needs to emit new interning entries
auto* e_packet1 = producer_client()->GetFinalizedPacket(3); auto* e_packet1 = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet1, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet1, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
...@@ -1439,7 +1453,7 @@ TEST_F(TraceEventDataSourceNoInterningTest, InterningScopedToPackets) { ...@@ -1439,7 +1453,7 @@ TEST_F(TraceEventDataSourceNoInterningTest, InterningScopedToPackets) {
ExpectDebugAnnotationNames(e_packet1, {{1u, "arg1"}}); ExpectDebugAnnotationNames(e_packet1, {{1u, "arg1"}});
// Second packet reemits the entries the same way. // Second packet reemits the entries the same way.
auto* e_packet2 = producer_client()->GetFinalizedPacket(4); auto* e_packet2 = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet2, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet2, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
...@@ -1453,7 +1467,7 @@ TEST_F(TraceEventDataSourceNoInterningTest, InterningScopedToPackets) { ...@@ -1453,7 +1467,7 @@ TEST_F(TraceEventDataSourceNoInterningTest, InterningScopedToPackets) {
ExpectDebugAnnotationNames(e_packet1, {{1u, "arg1"}}); ExpectDebugAnnotationNames(e_packet1, {{1u, "arg1"}});
// Third packet emits entries with the same IDs but different strings. // Third packet emits entries with the same IDs but different strings.
auto* e_packet3 = producer_client()->GetFinalizedPacket(5); auto* e_packet3 = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet3, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet3, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
...@@ -1563,10 +1577,9 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnBegin) { ...@@ -1563,10 +1577,9 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnBegin) {
EXPECT_TRUE(begin_called); EXPECT_TRUE(begin_called);
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_BEGIN); TRACE_EVENT_PHASE_BEGIN);
...@@ -1588,10 +1601,9 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnEnd) { ...@@ -1588,10 +1601,9 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnEnd) {
EXPECT_TRUE(end_called); EXPECT_TRUE(end_called);
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/0u, /*name_iid=*/0u, ExpectTraceEvent(e_packet, /*category_iid=*/0u, /*name_iid=*/0u,
TRACE_EVENT_PHASE_END); TRACE_EVENT_PHASE_END);
...@@ -1609,10 +1621,9 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnBeginAndEnd) { ...@@ -1609,10 +1621,9 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnBeginAndEnd) {
ctx.event()->set_log_message()->set_body_iid(84); ctx.event()->set_log_message()->set_body_iid(84);
}); });
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 5u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_BEGIN); TRACE_EVENT_PHASE_BEGIN);
...@@ -1621,7 +1632,7 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnBeginAndEnd) { ...@@ -1621,7 +1632,7 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnBeginAndEnd) {
ASSERT_TRUE(e_packet->track_event().has_log_message()); ASSERT_TRUE(e_packet->track_event().has_log_message());
EXPECT_EQ(e_packet->track_event().log_message().body_iid(), 42u); EXPECT_EQ(e_packet->track_event().log_message().body_iid(), 42u);
e_packet = producer_client()->GetFinalizedPacket(4); e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/0u, /*name_iid=*/0u, ExpectTraceEvent(e_packet, /*category_iid=*/0u, /*name_iid=*/0u,
TRACE_EVENT_PHASE_END); TRACE_EVENT_PHASE_END);
...@@ -1637,10 +1648,9 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnInstant) { ...@@ -1637,10 +1648,9 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnInstant) {
ctx.event()->set_log_message()->set_body_iid(42); ctx.event()->set_log_message()->set_body_iid(42);
}); });
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD); TRACE_EVENT_PHASE_INSTANT, TRACE_EVENT_SCOPE_THREAD);
...@@ -1661,10 +1671,9 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnScoped) { ...@@ -1661,10 +1671,9 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnScoped) {
ctx.event()->set_log_message()->set_body_iid(42); ctx.event()->set_log_message()->set_body_iid(42);
}); });
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 5u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_BEGIN); TRACE_EVENT_PHASE_BEGIN);
...@@ -1673,7 +1682,7 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnScoped) { ...@@ -1673,7 +1682,7 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnScoped) {
ASSERT_TRUE(e_packet->track_event().has_log_message()); ASSERT_TRUE(e_packet->track_event().has_log_message());
EXPECT_EQ(e_packet->track_event().log_message().body_iid(), 42u); EXPECT_EQ(e_packet->track_event().log_message().body_iid(), 42u);
e_packet = producer_client()->GetFinalizedPacket(4); e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/0u, /*name_iid=*/0u, ExpectTraceEvent(e_packet, /*category_iid=*/0u, /*name_iid=*/0u,
TRACE_EVENT_PHASE_END); TRACE_EVENT_PHASE_END);
...@@ -1691,10 +1700,9 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnScopedCapture) { ...@@ -1691,10 +1700,9 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnScopedCapture) {
}); });
} }
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 5u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_BEGIN); TRACE_EVENT_PHASE_BEGIN);
...@@ -1703,7 +1711,7 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnScopedCapture) { ...@@ -1703,7 +1711,7 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnScopedCapture) {
ASSERT_TRUE(e_packet->track_event().has_log_message()); ASSERT_TRUE(e_packet->track_event().has_log_message());
EXPECT_EQ(e_packet->track_event().log_message().body_iid(), 42u); EXPECT_EQ(e_packet->track_event().log_message().body_iid(), 42u);
e_packet = producer_client()->GetFinalizedPacket(4); e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/0u, /*name_iid=*/0u, ExpectTraceEvent(e_packet, /*category_iid=*/0u, /*name_iid=*/0u,
TRACE_EVENT_PHASE_END); TRACE_EVENT_PHASE_END);
...@@ -1723,11 +1731,10 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnScopedMultipleEvents) { ...@@ -1723,11 +1731,10 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnScopedMultipleEvents) {
}); });
} }
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 7u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
// The first TRACE_EVENT begin. // The first TRACE_EVENT begin.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_BEGIN); TRACE_EVENT_PHASE_BEGIN);
...@@ -1737,21 +1744,21 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnScopedMultipleEvents) { ...@@ -1737,21 +1744,21 @@ TEST_F(TraceEventDataSourceTest, TypedArgumentsTracingOnScopedMultipleEvents) {
EXPECT_EQ(e_packet->track_event().log_message().body_iid(), 42u); EXPECT_EQ(e_packet->track_event().log_message().body_iid(), 42u);
// The second TRACE_EVENT begin. // The second TRACE_EVENT begin.
e_packet = producer_client()->GetFinalizedPacket(4); e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u, ExpectTraceEvent(e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_BEGIN); TRACE_EVENT_PHASE_BEGIN);
ASSERT_TRUE(e_packet->track_event().has_log_message()); ASSERT_TRUE(e_packet->track_event().has_log_message());
EXPECT_EQ(e_packet->track_event().log_message().body_iid(), 43u); EXPECT_EQ(e_packet->track_event().log_message().body_iid(), 43u);
// The second TRACE_EVENT end. // The second TRACE_EVENT end.
e_packet = producer_client()->GetFinalizedPacket(5); e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/0u, /*name_iid=*/0u, ExpectTraceEvent(e_packet, /*category_iid=*/0u, /*name_iid=*/0u,
TRACE_EVENT_PHASE_END); TRACE_EVENT_PHASE_END);
EXPECT_FALSE(e_packet->track_event().has_log_message()); EXPECT_FALSE(e_packet->track_event().has_log_message());
// The first TRACE_EVENT end. // The first TRACE_EVENT end.
e_packet = producer_client()->GetFinalizedPacket(6); e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/0u, /*name_iid=*/0u, ExpectTraceEvent(e_packet, /*category_iid=*/0u, /*name_iid=*/0u,
TRACE_EVENT_PHASE_END); TRACE_EVENT_PHASE_END);
EXPECT_FALSE(e_packet->track_event().has_log_message()); EXPECT_FALSE(e_packet->track_event().has_log_message());
...@@ -1767,10 +1774,9 @@ TEST_F(TraceEventDataSourceTest, HistogramSample) { ...@@ -1767,10 +1774,9 @@ TEST_F(TraceEventDataSourceTest, HistogramSample) {
UMA_HISTOGRAM_BOOLEAN("Foo.Bar", true); UMA_HISTOGRAM_BOOLEAN("Foo.Bar", true);
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectEventCategories(e_packet, ExpectEventCategories(e_packet,
{{1u, TRACE_DISABLED_BY_DEFAULT("histogram_samples")}}); {{1u, TRACE_DISABLED_BY_DEFAULT("histogram_samples")}});
...@@ -1796,10 +1802,9 @@ TEST_F(TraceEventDataSourceTest, UserActionEvent) { ...@@ -1796,10 +1802,9 @@ TEST_F(TraceEventDataSourceTest, UserActionEvent) {
base::RecordAction(base::UserMetricsAction("Test_Action")); base::RecordAction(base::UserMetricsAction("Test_Action"));
EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u); size_t packet_index = ExpectStandardPreamble();
ExpectStandardPreamble(); // 3 preamble packets.
auto* e_packet = producer_client()->GetFinalizedPacket(3); auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectEventCategories( ExpectEventCategories(
e_packet, {{1u, TRACE_DISABLED_BY_DEFAULT("user_action_samples")}}); e_packet, {{1u, TRACE_DISABLED_BY_DEFAULT("user_action_samples")}});
......
services/tracing/public/cpp/perfetto/track_event_thread_local_event_sink.cc
View file @ 923d1c42
...@@ -37,6 +37,7 @@ ...@@ -37,6 +37,7 @@
using TraceLog = base::trace_event::TraceLog; using TraceLog = base::trace_event::TraceLog;
using perfetto::protos::pbzero::ChromeThreadDescriptor; using perfetto::protos::pbzero::ChromeThreadDescriptor;
using perfetto::protos::pbzero::ClockSnapshot; using perfetto::protos::pbzero::ClockSnapshot;
using perfetto::protos::pbzero::CounterDescriptor;
using perfetto::protos::pbzero::ThreadDescriptor; using perfetto::protos::pbzero::ThreadDescriptor;
using perfetto::protos::pbzero::TracePacket; using perfetto::protos::pbzero::TracePacket;
using perfetto::protos::pbzero::TracePacketDefaults; using perfetto::protos::pbzero::TracePacketDefaults;
...@@ -56,12 +57,6 @@ const char* const kPrivacyFiltered = "PRIVACY_FILTERED"; ...@@ -56,12 +57,6 @@ const char* const kPrivacyFiltered = "PRIVACY_FILTERED";
constexpr uint32_t kClockIdAbsolute = 64; constexpr uint32_t kClockIdAbsolute = 64;
constexpr uint32_t kClockIdIncremental = 65; constexpr uint32_t kClockIdIncremental = 65;
base::ThreadTicks ThreadNow() {
return base::ThreadTicks::IsSupported()
? base::subtle::ThreadTicksNowIgnoringOverride()
: base::ThreadTicks();
}
// Names of events that should be converted into a TaskExecution event. // Names of events that should be converted into a TaskExecution event.
const char* kTaskExecutionEventCategory = "toplevel"; const char* kTaskExecutionEventCategory = "toplevel";
const char* kTaskExecutionEventNames[3] = {"ThreadControllerImpl::RunTask", const char* kTaskExecutionEventNames[3] = {"ThreadControllerImpl::RunTask",
...@@ -390,32 +385,32 @@ TrackEvent* TrackEventThreadLocalEventSink::PrepareTrackEvent( ...@@ -390,32 +385,32 @@ TrackEvent* TrackEventThreadLocalEventSink::PrepareTrackEvent(
} }
} }
if (!trace_event->thread_timestamp().is_null()) { bool has_thread_time = !trace_event->thread_timestamp().is_null();
// Thread timestamps are never user-provided, but COMPLETE events may get bool has_instruction_count =
// reordered, so we can still observe timestamps that are further in the !trace_event->thread_instruction_count().is_null();
// past. Emit those as absolute timestamps, since we don't support
// negative deltas.
if (last_thread_time_ > trace_event->thread_timestamp()) {
track_event->set_thread_time_absolute_us(
trace_event->thread_timestamp().since_origin().InMicroseconds());
} else {
track_event->set_thread_time_delta_us(
(trace_event->thread_timestamp() - last_thread_time_)
.InMicroseconds());
last_thread_time_ = trace_event->thread_timestamp();
}
}
if (!trace_event->thread_instruction_count().is_null()) { // We always snapshot the thread timestamp when we snapshot instruction
// Thread instruction counts are never user-provided, but COMPLETE events // count. If we didn't do this, we'd have to make sure to override the
// may get reordered, so we can still observe counts that are lower. Emit // value of extra_counter_track_uuids.
// those as absolute counts, since we don't support negative deltas. DCHECK(has_thread_time || !has_instruction_count);
if (last_thread_instruction_count_.ToInternalValue() >
trace_event->thread_instruction_count().ToInternalValue()) { if (has_thread_time) {
track_event->set_thread_instruction_count_absolute( // Thread timestamps are never user-provided, and since we split COMPLETE
trace_event->thread_instruction_count().ToInternalValue()); // events into BEGIN+END event pairs, they should not appear out of order.
} else { DCHECK(trace_event->thread_timestamp() >= last_thread_time_);
track_event->set_thread_instruction_count_delta(
track_event->add_extra_counter_values(
(trace_event->thread_timestamp() - last_thread_time_).InMicroseconds());
last_thread_time_ = trace_event->thread_timestamp();
if (has_instruction_count) {
// Thread instruction counts are never user-provided, and since we split
// COMPLETE events into BEGIN+END event pairs, they should not appear out
// of order.
DCHECK(trace_event->thread_instruction_count().ToInternalValue() >=
last_thread_instruction_count_.ToInternalValue());
track_event->add_extra_counter_values(
(trace_event->thread_instruction_count() - (trace_event->thread_instruction_count() -
last_thread_instruction_count_) last_thread_instruction_count_)
.ToInternalValue()); .ToInternalValue());
...@@ -695,18 +690,17 @@ void TrackEventThreadLocalEventSink::Flush() { ...@@ -695,18 +690,17 @@ void TrackEventThreadLocalEventSink::Flush() {
void TrackEventThreadLocalEventSink::OnThreadNameChanged(const char* name) { void TrackEventThreadLocalEventSink::OnThreadNameChanged(const char* name) {
if (thread_id_ != static_cast<int>(base::PlatformThread::CurrentId())) if (thread_id_ != static_cast<int>(base::PlatformThread::CurrentId()))
return; return;
auto trace_packet = trace_writer_->NewTracePacket(); EmitThreadTrackDescriptor(nullptr, TRACE_TIME_TICKS_NOW(), name);
EmitTrackDescriptor(&trace_packet, nullptr, TRACE_TIME_TICKS_NOW(), name);
} }
void TrackEventThreadLocalEventSink::EmitTrackDescriptor( void TrackEventThreadLocalEventSink::EmitThreadTrackDescriptor(
protozero::MessageHandle<TracePacket>* trace_packet,
base::trace_event::TraceEvent* trace_event, base::trace_event::TraceEvent* trace_event,
base::TimeTicks timestamp, base::TimeTicks timestamp,
const char* maybe_new_name) { const char* maybe_new_name) {
SetPacketTimestamp(trace_packet, timestamp); auto packet = trace_writer_->NewTracePacket();
SetPacketTimestamp(&packet, timestamp);
TrackDescriptor* track_descriptor = (*trace_packet)->set_track_descriptor(); TrackDescriptor* track_descriptor = packet->set_track_descriptor();
// TODO(eseckler): Call ThreadTrack::Current() instead once the client lib // TODO(eseckler): Call ThreadTrack::Current() instead once the client lib
// supports Chrome's tids. // supports Chrome's tids.
auto thread_track = perfetto::ThreadTrack::ForThread(thread_id_); auto thread_track = perfetto::ThreadTrack::ForThread(thread_id_);
...@@ -716,7 +710,7 @@ void TrackEventThreadLocalEventSink::EmitTrackDescriptor( ...@@ -716,7 +710,7 @@ void TrackEventThreadLocalEventSink::EmitTrackDescriptor(
// from Chrome, and supports pivacy filtering, and we moved off reference_* // from Chrome, and supports pivacy filtering, and we moved off reference_*
// fields in ThreadDescriptor. // fields in ThreadDescriptor.
track_descriptor->set_uuid(thread_track.uuid); track_descriptor->set_uuid(thread_track.uuid);
PERFETTO_DCHECK(thread_track.parent_uuid); DCHECK(thread_track.parent_uuid);
track_descriptor->set_parent_uuid(thread_track.parent_uuid); track_descriptor->set_parent_uuid(thread_track.parent_uuid);
ThreadDescriptor* thread = track_descriptor->set_thread(); ThreadDescriptor* thread = track_descriptor->set_thread();
...@@ -736,42 +730,49 @@ void TrackEventThreadLocalEventSink::EmitTrackDescriptor( ...@@ -736,42 +730,49 @@ void TrackEventThreadLocalEventSink::EmitTrackDescriptor(
thread->set_thread_name(thread_name_); thread->set_thread_name(thread_name_);
} }
// TODO(eseckler): Switch to a more generic encoding format for counters and
// move them out of ThreadDescriptor.
if (!trace_event || trace_event->thread_timestamp().is_null()) {
last_thread_time_ = ThreadNow();
} else {
// Thread timestamp is never user-provided.
DCHECK_LE(trace_event->thread_timestamp(), ThreadNow());
last_thread_time_ = trace_event->thread_timestamp();
}
thread->set_reference_thread_time_us(
last_thread_time_.since_origin().InMicroseconds());
if (base::trace_event::ThreadInstructionCount::IsSupported()) {
if (!trace_event || trace_event->thread_instruction_count().is_null()) {
last_thread_instruction_count_ =
base::trace_event::ThreadInstructionCount::Now();
} else {
// Thread instruction count is never user-provided.
DCHECK_LE(
trace_event->thread_instruction_count().ToInternalValue(),
base::trace_event::ThreadInstructionCount::Now().ToInternalValue());
last_thread_instruction_count_ = trace_event->thread_instruction_count();
}
thread->set_reference_thread_instruction_count(
last_thread_instruction_count_.ToInternalValue());
}
ChromeThreadDescriptor* chrome_thread = track_descriptor->set_chrome_thread(); ChromeThreadDescriptor* chrome_thread = track_descriptor->set_chrome_thread();
chrome_thread->set_thread_type(thread_type_); chrome_thread->set_thread_type(thread_type_);
// TODO(eseckler): Fill in remaining fields in ChromeThreadDescriptor. // TODO(eseckler): Fill in remaining fields in ChromeThreadDescriptor.
} }
void TrackEventThreadLocalEventSink::EmitCounterTrackDescriptor(
base::TimeTicks timestamp,
uint64_t thread_track_uuid,
uint64_t counter_track_uuid_bit,
CounterDescriptor::BuiltinCounterType counter_type,
uint64_t unit_multiplier) {
auto packet = trace_writer_->NewTracePacket();
SetPacketTimestamp(&packet, timestamp);
TrackDescriptor* track_descriptor = packet->set_track_descriptor();
// TODO(eseckler): Switch to client library support for CounterTrack uuid
// calculation once available.
track_descriptor->set_uuid(thread_track_uuid ^ counter_track_uuid_bit);
track_descriptor->set_parent_uuid(thread_track_uuid);
CounterDescriptor* counter = track_descriptor->set_counter();
if (counter_type != CounterDescriptor::COUNTER_UNSPECIFIED) {
counter->set_type(CounterDescriptor::COUNTER_THREAD_TIME_NS);
}
if (unit_multiplier) {
counter->set_unit_multiplier(1000u);
}
counter->set_is_incremental(true);
}
void TrackEventThreadLocalEventSink::DoResetIncrementalState( void TrackEventThreadLocalEventSink::DoResetIncrementalState(
base::trace_event::TraceEvent* trace_event, base::trace_event::TraceEvent* trace_event,
bool explicit_timestamp) { bool explicit_timestamp) {
// Bits xor-ed into the track uuid of a thread track to make the track uuid of
// a thread time / instruction count track. These bits are chosen from the
// upper end of the uint64_t bytes, because the tid of the thread is hashed
// into the least significant 32 bits of the uuid.
constexpr uint64_t kThreadTimeTrackUuidBit = static_cast<uint64_t>(1u) << 32;
constexpr uint64_t kThreadInstructionCountTrackUuidBit =
static_cast<uint64_t>(1u) << 33;
interned_event_categories_.ResetEmittedState(); interned_event_categories_.ResetEmittedState();
interned_event_names_.ResetEmittedState(); interned_event_names_.ResetEmittedState();
interned_annotation_names_.ResetEmittedState(); interned_annotation_names_.ResetEmittedState();
...@@ -787,6 +788,11 @@ void TrackEventThreadLocalEventSink::DoResetIncrementalState( ...@@ -787,6 +788,11 @@ void TrackEventThreadLocalEventSink::DoResetIncrementalState(
} }
last_timestamp_ = timestamp; last_timestamp_ = timestamp;
// TODO(eseckler): Call ThreadTrack::Current() instead once the client lib
// supports Chrome's tids.
uint64_t thread_track_uuid =
perfetto::ThreadTrack::ForThread(thread_id_).uuid;
{ {
// Emit a new clock snapshot with this timestamp, and also set the // Emit a new clock snapshot with this timestamp, and also set the
// |incremental_state_cleared| flag and defaults. // |incremental_state_cleared| flag and defaults.
...@@ -796,10 +802,16 @@ void TrackEventThreadLocalEventSink::DoResetIncrementalState( ...@@ -796,10 +802,16 @@ void TrackEventThreadLocalEventSink::DoResetIncrementalState(
TracePacketDefaults* tp_defaults = packet->set_trace_packet_defaults(); TracePacketDefaults* tp_defaults = packet->set_trace_packet_defaults();
tp_defaults->set_timestamp_clock_id(kClockIdIncremental); tp_defaults->set_timestamp_clock_id(kClockIdIncremental);
TrackEventDefaults* te_defaults = tp_defaults->set_track_event_defaults(); TrackEventDefaults* te_defaults = tp_defaults->set_track_event_defaults();
// TODO(eseckler): Call ThreadTrack::Current() instead once the client lib
// supports Chrome's tids. // Default to thread track, with counter values for thread time and
te_defaults->set_track_uuid( // instruction count, if supported.
perfetto::ThreadTrack::ForThread(thread_id_).uuid); te_defaults->set_track_uuid(thread_track_uuid);
te_defaults->add_extra_counter_track_uuids(thread_track_uuid ^
kThreadTimeTrackUuidBit);
if (base::trace_event::ThreadInstructionCount::IsSupported()) {
te_defaults->add_extra_counter_track_uuids(
thread_track_uuid ^ kThreadInstructionCountTrackUuidBit);
}
ClockSnapshot* clocks = packet->set_clock_snapshot(); ClockSnapshot* clocks = packet->set_clock_snapshot();
// Always reference the boottime timestamps to help trace processor // Always reference the boottime timestamps to help trace processor
...@@ -829,9 +841,23 @@ void TrackEventThreadLocalEventSink::DoResetIncrementalState( ...@@ -829,9 +841,23 @@ void TrackEventThreadLocalEventSink::DoResetIncrementalState(
clock_incremental->set_is_incremental(true); clock_incremental->set_is_incremental(true);
} }
// Emit a new track descriptor in another packet. // Emit new track descriptors for the thread and its counters in separate
auto packet = trace_writer_->NewTracePacket(); // packets.
EmitTrackDescriptor(&packet, trace_event, timestamp); EmitThreadTrackDescriptor(trace_event, timestamp);
if (base::ThreadTicks::IsSupported()) {
EmitCounterTrackDescriptor(
timestamp, thread_track_uuid, kThreadTimeTrackUuidBit,
CounterDescriptor::COUNTER_THREAD_TIME_NS, 1000u);
}
if (base::trace_event::ThreadInstructionCount::IsSupported()) {
EmitCounterTrackDescriptor(
timestamp, thread_track_uuid, kThreadInstructionCountTrackUuidBit,
CounterDescriptor::COUNTER_THREAD_INSTRUCTION_COUNT);
}
// The first set of counter values should be absolute.
last_thread_time_ = base::ThreadTicks();
last_thread_instruction_count_ = base::trace_event::ThreadInstructionCount();
reset_incremental_state_ = false; reset_incremental_state_ = false;
} }
......
services/tracing/public/cpp/perfetto/track_event_thread_local_event_sink.h
View file @ 923d1c42
...@@ -22,6 +22,7 @@ ...@@ -22,6 +22,7 @@
#include "third_party/perfetto/include/perfetto/tracing/event_context.h" #include "third_party/perfetto/include/perfetto/tracing/event_context.h"
#include "third_party/perfetto/protos/perfetto/trace/interned_data/interned_data.pbzero.h" #include "third_party/perfetto/protos/perfetto/trace/interned_data/interned_data.pbzero.h"
#include "third_party/perfetto/protos/perfetto/trace/track_event/chrome_thread_descriptor.pbzero.h" #include "third_party/perfetto/protos/perfetto/trace/track_event/chrome_thread_descriptor.pbzero.h"
#include "third_party/perfetto/protos/perfetto/trace/track_event/counter_descriptor.pbzero.h"
#include "third_party/perfetto/protos/perfetto/trace/track_event/track_event.pbzero.h" #include "third_party/perfetto/protos/perfetto/trace/track_event/track_event.pbzero.h"
namespace tracing { namespace tracing {
...@@ -125,12 +126,16 @@ class COMPONENT_EXPORT(TRACING_CPP) TrackEventThreadLocalEventSink ...@@ -125,12 +126,16 @@ class COMPONENT_EXPORT(TRACING_CPP) TrackEventThreadLocalEventSink
private: private:
static constexpr size_t kMaxCompleteEventDepth = 30; static constexpr size_t kMaxCompleteEventDepth = 30;
void EmitTrackDescriptor( void EmitThreadTrackDescriptor(base::trace_event::TraceEvent* trace_event,
protozero::MessageHandle<perfetto::protos::pbzero::TracePacket>* base::TimeTicks timestamp,
trace_packet, const char* maybe_new_name = nullptr);
base::trace_event::TraceEvent* trace_event, void EmitCounterTrackDescriptor(
base::TimeTicks timestamp, base::TimeTicks timestamp,
const char* maybe_new_name = nullptr); uint64_t thread_track_uuid,
uint64_t counter_track_uuid_bit,
perfetto::protos::pbzero::CounterDescriptor::BuiltinCounterType
counter_type,
uint64_t unit_multiplier = 0u);
void DoResetIncrementalState(base::trace_event::TraceEvent* trace_event, void DoResetIncrementalState(base::trace_event::TraceEvent* trace_event,
bool explicit_timestamp); bool explicit_timestamp);
void SetPacketTimestamp( void SetPacketTimestamp(
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment