Revert "perfetto: Split COMPLETE events into BEGIN/END pairs"
This reverts commit 4da1652655a4cc8038e2c7fe60fad09cb27e006c.
Reason for revert: crbug.com/1026658
Original change's description:
> perfetto: Split COMPLETE events into BEGIN/END pairs
>
> There are a few reasons why this is desirable:
> (1) Reduces need for complete event stack in ThreadLocalEventSinks,
> which was brittle before (e.g. crbug.com/983307).
> (2) Makes it possible to flush event sinks while tracing in the future
> without losing not-yet-completed COMPLETE events from the stack
> (streamed tracing use case). Events that didn't end before the
> flush will still be present in the trace as BEGIN only.
> (3) Prevents reordering of nested COMPLETE events - something which
> could confuse TraceProcessor in the past (events with identical
> begin timestamps would be imported incorrectly).
>
> To achieve this, this patch also plumbs the EXPLICIT_TIMESTAMP flag
> and thread id through to TraceLog::UpdateTraceEventDurationExplicit,
> because it seems that android can add COMPLETE events with explicit
> timestamps / threads [1].
>
> [1] https://cs.chromium.org/chromium/src/base/android/early_trace_event_binding.cc?q=INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMPS&ss=chromium&l=31
>
> Bug: 983307, 928738, 1006770
> Change-Id: I66e685c04c068646d550f182185d3c45febcbfa8
> Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1899852
> Commit-Queue: Eric Seckler <eseckler@chromium.org>
> Reviewed-by: oysteine <oysteine@chromium.org>
> Cr-Commit-Position: refs/heads/master@{#716871}
TBR=oysteine@chromium.org,eseckler@chromium.org
Change-Id: I8056e483b439796eed90feaaa09434f7f63d1124
No-Presubmit: true
No-Tree-Checks: true
No-Try: true
Bug: 983307, 928738, 1006770, 1026658
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1927034
Reviewed-by: Eric Seckler <eseckler@chromium.org>
Commit-Queue: Eric Seckler <eseckler@chromium.org>
Cr-Commit-Position: refs/heads/master@{#717158}
diff --git a/base/trace_event/trace_event.h b/base/trace_event/trace_event.h
index df910294..08f8ea80 100644
--- a/base/trace_event/trace_event.h
+++ b/base/trace_event/trace_event.h
@@ -174,11 +174,8 @@
// const unsigned char* category_group_enabled,
// const char* name,
// base::trace_event::TraceEventHandle id,
-// int thread_id,
-// bool explicit_timestamps,
-// const base::TimeTicks& now,
-// const base::ThreadTicks& thread_now,
-// base::trace_event::ThreadInstructionCount thread_instruction_now)
+// const TimeTicks& now,
+// const ThreadTicks* thread_now)
#define TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION_EXPLICIT \
trace_event_internal::UpdateTraceEventDurationExplicit
@@ -382,29 +379,28 @@
// Implementation detail: internal macro to create static category and add
// event if the category is enabled.
-#define INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMPS( \
- category_group, name, id, thread_id, begin_timestamp, end_timestamp, \
- thread_end_timestamp, flags, ...) \
- do { \
- INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category_group); \
- if (INTERNAL_TRACE_EVENT_CATEGORY_GROUP_ENABLED()) { \
- trace_event_internal::TraceID trace_event_trace_id((id)); \
- unsigned int trace_event_flags = \
- flags | trace_event_trace_id.id_flags(); \
- const unsigned char* uid_category_group_enabled = \
- INTERNAL_TRACE_EVENT_UID(category_group_enabled); \
- auto handle = \
- trace_event_internal::AddTraceEventWithThreadIdAndTimestamp( \
- TRACE_EVENT_PHASE_COMPLETE, uid_category_group_enabled, name, \
- trace_event_trace_id.scope(), trace_event_trace_id.raw_id(), \
- thread_id, begin_timestamp, \
- trace_event_flags | TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP, \
- trace_event_internal::kNoId, ##__VA_ARGS__); \
- TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION_EXPLICIT( \
- uid_category_group_enabled, name, handle, thread_id, \
- /*explicit_timestamps=*/true, end_timestamp, thread_end_timestamp, \
- base::trace_event::ThreadInstructionCount()); \
- } \
+#define INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMPS( \
+ category_group, name, id, thread_id, begin_timestamp, end_timestamp, \
+ thread_end_timestamp, flags, ...) \
+ do { \
+ INTERNAL_TRACE_EVENT_GET_CATEGORY_INFO(category_group); \
+ if (INTERNAL_TRACE_EVENT_CATEGORY_GROUP_ENABLED()) { \
+ trace_event_internal::TraceID trace_event_trace_id((id)); \
+ unsigned int trace_event_flags = \
+ flags | trace_event_trace_id.id_flags(); \
+ const unsigned char* uid_category_group_enabled = \
+ INTERNAL_TRACE_EVENT_UID(category_group_enabled); \
+ auto handle = \
+ trace_event_internal::AddTraceEventWithThreadIdAndTimestamp( \
+ TRACE_EVENT_PHASE_COMPLETE, uid_category_group_enabled, name, \
+ trace_event_trace_id.scope(), trace_event_trace_id.raw_id(), \
+ thread_id, begin_timestamp, \
+ trace_event_flags | TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP, \
+ trace_event_internal::kNoId, ##__VA_ARGS__); \
+ TRACE_EVENT_API_UPDATE_TRACE_EVENT_DURATION_EXPLICIT( \
+ uid_category_group_enabled, name, handle, end_timestamp, \
+ thread_end_timestamp, base::trace_event::ThreadInstructionCount()); \
+ } \
} while (0)
// The linked ID will not be mangled.
@@ -721,8 +717,6 @@
const unsigned char* category_group_enabled,
const char* name,
base::trace_event::TraceEventHandle handle,
- int thread_id,
- bool explicit_timestamps,
const base::TimeTicks& now,
const base::ThreadTicks& thread_now,
base::trace_event::ThreadInstructionCount thread_instruction_now);
diff --git a/base/trace_event/trace_log.cc b/base/trace_event/trace_log.cc
index f785ef3..1e0cd14 100644
--- a/base/trace_event/trace_log.cc
+++ b/base/trace_event/trace_log.cc
@@ -1405,19 +1405,15 @@
if (!category_group_enabled_local)
return;
- UpdateTraceEventDurationExplicit(
- category_group_enabled, name, handle,
- static_cast<int>(base::PlatformThread::CurrentId()),
- /*explicit_timestamps=*/false, OffsetNow(), ThreadNow(),
- ThreadInstructionNow());
+ UpdateTraceEventDurationExplicit(category_group_enabled, name, handle,
+ OffsetNow(), ThreadNow(),
+ ThreadInstructionNow());
}
void TraceLog::UpdateTraceEventDurationExplicit(
const unsigned char* category_group_enabled,
const char* name,
TraceEventHandle handle,
- int thread_id,
- bool explicit_timestamps,
const TimeTicks& now,
const ThreadTicks& thread_now,
ThreadInstructionCount thread_instruction_now) {
@@ -1442,9 +1438,7 @@
auto update_duration_override =
update_duration_override_.load(std::memory_order_relaxed);
if (update_duration_override) {
- update_duration_override(category_group_enabled, name, handle, thread_id,
- explicit_timestamps, now, thread_now,
- thread_instruction_now);
+ update_duration_override(handle, now, thread_now, thread_instruction_now);
return;
}
}
@@ -1822,15 +1816,13 @@
const unsigned char* category_group_enabled,
const char* name,
base::trace_event::TraceEventHandle handle,
- int thread_id,
- bool explicit_timestamps,
const base::TimeTicks& now,
const base::ThreadTicks& thread_now,
base::trace_event::ThreadInstructionCount thread_instruction_now) {
return base::trace_event::TraceLog::GetInstance()
->UpdateTraceEventDurationExplicit(category_group_enabled, name, handle,
- thread_id, explicit_timestamps, now,
- thread_now, thread_instruction_now);
+ now, thread_now,
+ thread_instruction_now);
}
ScopedTraceBinaryEfficient::ScopedTraceBinaryEfficient(
diff --git a/base/trace_event/trace_log.h b/base/trace_event/trace_log.h
index 6b877179..e0c850ca 100644
--- a/base/trace_event/trace_log.h
+++ b/base/trace_event/trace_log.h
@@ -201,11 +201,7 @@
TraceEventHandle* handle);
using OnFlushFunction = void (*)();
using UpdateDurationFunction =
- void (*)(const unsigned char* category_group_enabled,
- const char* name,
- TraceEventHandle handle,
- int thread_id,
- bool explicit_timestamps,
+ void (*)(TraceEventHandle handle,
const TimeTicks& now,
const ThreadTicks& thread_now,
ThreadInstructionCount thread_instruction_now);
@@ -296,8 +292,6 @@
const unsigned char* category_group_enabled,
const char* name,
TraceEventHandle handle,
- int thread_id,
- bool explicit_timestamps,
const TimeTicks& now,
const ThreadTicks& thread_now,
ThreadInstructionCount thread_instruction_now);
diff --git a/services/tracing/public/cpp/perfetto/thread_local_event_sink.h b/services/tracing/public/cpp/perfetto/thread_local_event_sink.h
index c4f32dd9..8435060 100644
--- a/services/tracing/public/cpp/perfetto/thread_local_event_sink.h
+++ b/services/tracing/public/cpp/perfetto/thread_local_event_sink.h
@@ -39,11 +39,7 @@
base::trace_event::TraceEventHandle* handle) = 0;
virtual void UpdateDuration(
- const unsigned char* category_group_enabled,
- const char* name,
base::trace_event::TraceEventHandle handle,
- int thread_id,
- bool explicit_timestamps,
const base::TimeTicks& now,
const base::ThreadTicks& thread_now,
base::trace_event::ThreadInstructionCount thread_instruction_now) = 0;
diff --git a/services/tracing/public/cpp/perfetto/trace_event_data_source.cc b/services/tracing/public/cpp/perfetto/trace_event_data_source.cc
index 34d20da9..24b29aa 100644
--- a/services/tracing/public/cpp/perfetto/trace_event_data_source.cc
+++ b/services/tracing/public/cpp/perfetto/trace_event_data_source.cc
@@ -884,11 +884,7 @@
// static
void TraceEventDataSource::OnUpdateDuration(
- const unsigned char* category_group_enabled,
- const char* name,
base::trace_event::TraceEventHandle handle,
- int thread_id,
- bool explicit_timestamps,
const base::TimeTicks& now,
const base::ThreadTicks& thread_now,
base::trace_event::ThreadInstructionCount thread_instruction_now) {
@@ -901,9 +897,8 @@
auto* thread_local_event_sink =
static_cast<ThreadLocalEventSink*>(ThreadLocalEventSinkSlot()->Get());
if (thread_local_event_sink) {
- thread_local_event_sink->UpdateDuration(
- category_group_enabled, name, handle, thread_id, explicit_timestamps,
- now, thread_now, thread_instruction_now);
+ thread_local_event_sink->UpdateDuration(handle, now, thread_now,
+ thread_instruction_now);
}
}
diff --git a/services/tracing/public/cpp/perfetto/trace_event_data_source.h b/services/tracing/public/cpp/perfetto/trace_event_data_source.h
index 6df3f78d..b5d22bf3 100644
--- a/services/tracing/public/cpp/perfetto/trace_event_data_source.h
+++ b/services/tracing/public/cpp/perfetto/trace_event_data_source.h
@@ -210,11 +210,7 @@
bool thread_will_flush,
base::trace_event::TraceEventHandle* handle);
static void OnUpdateDuration(
- const unsigned char* category_group_enabled,
- const char* name,
base::trace_event::TraceEventHandle handle,
- int thread_id,
- bool explicit_timestamps,
const base::TimeTicks& now,
const base::ThreadTicks& thread_now,
base::trace_event::ThreadInstructionCount thread_instruction_now);
diff --git a/services/tracing/public/cpp/perfetto/trace_event_data_source_unittest.cc b/services/tracing/public/cpp/perfetto/trace_event_data_source_unittest.cc
index e28efaaa..99d4f19 100644
--- a/services/tracing/public/cpp/perfetto/trace_event_data_source_unittest.cc
+++ b/services/tracing/public/cpp/perfetto/trace_event_data_source_unittest.cc
@@ -335,13 +335,8 @@
last_thread_time_ += packet->track_event().thread_time_delta_us();
}
- if (category_iid > 0) {
- EXPECT_EQ(packet->track_event().category_iids_size(), 1);
- EXPECT_EQ(packet->track_event().category_iids(0), category_iid);
- } else {
- EXPECT_EQ(packet->track_event().category_iids_size(), 0);
- }
-
+ EXPECT_EQ(packet->track_event().category_iids_size(), 1);
+ EXPECT_EQ(packet->track_event().category_iids(0), category_iid);
EXPECT_TRUE(packet->track_event().has_legacy_event());
const auto& legacy_event = packet->track_event().legacy_event();
@@ -935,56 +930,44 @@
trace_event_internal::TraceID trace_event_trace_id =
trace_event_internal::kNoId;
- // COMPLETE events are split into a BEGIN/END event pair. Adding the event
- // writes the BEGIN event immediately.
auto handle = trace_event_internal::AddTraceEventWithThreadIdAndTimestamp(
TRACE_EVENT_PHASE_COMPLETE, category_group_enabled, kEventName,
trace_event_trace_id.scope(), trace_event_trace_id.raw_id(),
- /*thread_id=*/1,
+ 1 /* thread_id */,
base::TimeTicks() + base::TimeDelta::FromMicroseconds(10),
trace_event_trace_id.id_flags() | TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP,
trace_event_internal::kNoId);
- EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 2u);
- auto* b_packet = producer_client()->GetFinalizedPacket(1);
- ExpectTraceEvent(
- b_packet, /*category_iid=*/1u, /*name_iid=*/1u, TRACE_EVENT_PHASE_BEGIN,
- TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP | TRACE_EVENT_FLAG_HAS_ID, /*id=*/0u,
- /*absolute_timestamp=*/10, /*tid_override=*/1, /*pid_override=*/0);
-
- // Updating the duration of the event as it goes out of scope results in the
- // corresponding END event being written. These END events don't contain any
- // event names or categories in the proto format.
base::trace_event::TraceLog::GetInstance()->UpdateTraceEventDurationExplicit(
- category_group_enabled, kEventName, handle, /*thread_id=*/1,
- /*explicit_timestamps=*/true,
+ category_group_enabled, kEventName, handle,
base::TimeTicks() + base::TimeDelta::FromMicroseconds(30),
base::ThreadTicks() + base::TimeDelta::FromMicroseconds(50),
base::trace_event::ThreadInstructionCount());
- EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 3u);
- auto* e_packet = producer_client()->GetFinalizedPacket(2);
+ // The call to UpdateTraceEventDurationExplicit should have successfully
+ // updated the duration of the event which was added in the
+ // AddTraceEventWithThreadIdAndTimestamp call.
+ EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 2u);
+ auto* e_packet = producer_client()->GetFinalizedPacket(1);
ExpectTraceEvent(
- e_packet, /*category_iid=*/0u, /*name_iid=*/0u, TRACE_EVENT_PHASE_END,
- TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP, /*id=*/0u,
- /*absolute_timestamp=*/30, /*tid_override=*/1, /*pid_override=*/0);
+ e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
+ TRACE_EVENT_PHASE_COMPLETE,
+ TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP | TRACE_EVENT_FLAG_HAS_ID, /*id=*/0u,
+ /*absolute_timestamp=*/10, /*tid_override=*/1, /*pid_override=*/0,
+ /*duration=*/20);
- // Updating the duration of an event that wasn't added before tracing begun
- // will only emit an END event, again without category or name.
+ // Updating the duration of an invalid event should cause no further events to
+ // be emitted.
handle.event_index = 0;
+
base::trace_event::TraceLog::GetInstance()->UpdateTraceEventDurationExplicit(
- category_group_enabled, "other_event_name", handle, /*thread_id=*/1,
- /*explicit_timestamps=*/true,
- base::TimeTicks() + base::TimeDelta::FromMicroseconds(40),
- base::ThreadTicks() + base::TimeDelta::FromMicroseconds(60),
+ category_group_enabled, kEventName, handle,
+ base::TimeTicks() + base::TimeDelta::FromMicroseconds(30),
+ base::ThreadTicks() + base::TimeDelta::FromMicroseconds(50),
base::trace_event::ThreadInstructionCount());
- EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 4u);
- auto* e2_packet = producer_client()->GetFinalizedPacket(3);
- ExpectTraceEvent(
- e2_packet, /*category_iid=*/0u, /*name_iid=*/0u, TRACE_EVENT_PHASE_END,
- TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP, /*id=*/0u,
- /*absolute_timestamp=*/40, /*tid_override=*/1, /*pid_override=*/0);
+ // No further packets should have been emitted.
+ EXPECT_EQ(producer_client()->GetFinalizedPacketCount(), 2u);
}
// TODO(eseckler): Add a test with multiple events + same strings (cat, name,
diff --git a/services/tracing/public/cpp/perfetto/track_event_thread_local_event_sink.cc b/services/tracing/public/cpp/perfetto/track_event_thread_local_event_sink.cc
index 2809fec8..2ca0914 100644
--- a/services/tracing/public/cpp/perfetto/track_event_thread_local_event_sink.cc
+++ b/services/tracing/public/cpp/perfetto/track_event_thread_local_event_sink.cc
@@ -38,6 +38,12 @@
namespace {
+// To mark TraceEvent handles that have been added by Perfetto,
+// we use the chunk index so high that TraceLog would've asserted
+// at this point anyway.
+constexpr uint32_t kMagicChunkIndex =
+ base::trace_event::TraceBufferChunk::kMaxChunkIndex;
+
// Replacement string for names of events with TRACE_EVENT_FLAG_COPY.
const char* const kPrivacyFiltered = "PRIVACY_FILTERED";
@@ -181,12 +187,28 @@
void TrackEventThreadLocalEventSink::AddTraceEvent(
base::trace_event::TraceEvent* trace_event,
base::trace_event::TraceEventHandle* handle) {
- char phase = trace_event->phase();
+ // TODO(eseckler): Support splitting COMPLETE events into BEGIN/END pairs.
+ // For now, we emit them as legacy events so that the generated JSON trace
+ // size remains small.
+ if (handle && trace_event->phase() == TRACE_EVENT_PHASE_COMPLETE) {
+ // 'X' phase events are added through a scoped object and
+ // will have its duration updated when said object drops off
+ // the stack; keep a copy of the event around instead of
+ // writing it into SHM, until we have the duration.
+ // We can't keep the TraceEvent around in the scoped object
+ // itself as that causes a lot more codegen in the callsites
+ // and bloats the binary size too much (due to the increased
+ // sizeof() of the scoped object itself).
+ DCHECK_LT(current_stack_depth_, kMaxCompleteEventDepth);
+ if (current_stack_depth_ >= kMaxCompleteEventDepth) {
+ return;
+ }
- // Split COMPLETE events into BEGIN/END pairs. We write the BEGIN here, and
- // the END in UpdateDuration().
- if (phase == TRACE_EVENT_PHASE_COMPLETE) {
- phase = TRACE_EVENT_PHASE_BEGIN;
+ complete_event_stack_[current_stack_depth_] = std::move(*trace_event);
+ handle->event_index = ++current_stack_depth_;
+ handle->chunk_index = kMagicChunkIndex;
+ handle->chunk_seq = sink_id_;
+ return;
}
uint32_t flags = trace_event->flags();
@@ -209,14 +231,10 @@
const char* category_name =
TraceLog::GetCategoryGroupName(trace_event->category_group_enabled());
- InterningIndexEntry interned_category{};
- // Don't write the category for END events that were split from a COMPLETE
- // event to save trace size.
- if (handle || phase != TRACE_EVENT_PHASE_END) {
- interned_category = interned_event_categories_.LookupOrAdd(category_name);
- }
+ InterningIndexEntry interned_category =
+ interned_event_categories_.LookupOrAdd(category_name);
- InterningIndexEntry interned_name{};
+ InterningIndexEntry interned_name;
const size_t kMaxSize = base::trace_event::TraceArguments::kMaxSize;
InterningIndexEntry interned_annotation_names[kMaxSize] = {
InterningIndexEntry{}};
@@ -228,74 +246,69 @@
const char* log_message_body = nullptr;
int line_number = 0;
- // Don't write the name or arguments for END events that were split from a
- // COMPLETE event to save trace size.
- if (handle || phase != TRACE_EVENT_PHASE_END) {
- if (copy_strings) {
- if (!is_java_event && privacy_filtering_enabled_) {
- interned_name = interned_event_names_.LookupOrAdd(kPrivacyFiltered);
- } else {
- interned_name =
- interned_event_names_.LookupOrAdd(std::string(trace_event->name()));
- for (size_t i = 0;
- i < trace_event->arg_size() && trace_event->arg_name(i); ++i) {
- interned_annotation_names[i] = interned_annotation_names_.LookupOrAdd(
- std::string(trace_event->arg_name(i)));
- }
- }
+ if (copy_strings) {
+ if (!is_java_event && privacy_filtering_enabled_) {
+ interned_name = interned_event_names_.LookupOrAdd(kPrivacyFiltered);
} else {
- interned_name = interned_event_names_.LookupOrAdd(trace_event->name());
+ interned_name =
+ interned_event_names_.LookupOrAdd(std::string(trace_event->name()));
+ for (size_t i = 0;
+ i < trace_event->arg_size() && trace_event->arg_name(i); ++i) {
+ interned_annotation_names[i] = interned_annotation_names_.LookupOrAdd(
+ std::string(trace_event->arg_name(i)));
+ }
+ }
+ } else {
+ interned_name = interned_event_names_.LookupOrAdd(trace_event->name());
- // TODO(eseckler): Remove special handling of typed events here once we
- // support them in TRACE_EVENT macros.
+ // TODO(eseckler): Remove special handling of typed events here once we
+ // support them in TRACE_EVENT macros.
- if (flags & TRACE_EVENT_FLAG_TYPED_PROTO_ARGS) {
- if (trace_event->arg_size() == 2u) {
+ if (flags & TRACE_EVENT_FLAG_TYPED_PROTO_ARGS) {
+ if (trace_event->arg_size() == 2u) {
+ DCHECK_EQ(strcmp(category_name, kTaskExecutionEventCategory), 0);
+ DCHECK(strcmp(trace_event->name(), kTaskExecutionEventNames[0]) == 0 ||
+ strcmp(trace_event->name(), kTaskExecutionEventNames[1]) == 0 ||
+ strcmp(trace_event->name(), kTaskExecutionEventNames[2]) == 0);
+ // Double argument task execution event (src_file, src_func).
+ DCHECK_EQ(trace_event->arg_type(0), TRACE_VALUE_TYPE_STRING);
+ DCHECK_EQ(trace_event->arg_type(1), TRACE_VALUE_TYPE_STRING);
+ src_file = trace_event->arg_value(0).as_string;
+ src_func = trace_event->arg_value(1).as_string;
+ } else {
+ // arg_size == 1 enforced by the maximum number of parameter == 2.
+ DCHECK_EQ(trace_event->arg_size(), 1u);
+
+ if (trace_event->arg_type(0) == TRACE_VALUE_TYPE_STRING) {
+ // Single argument task execution event (src_file).
DCHECK_EQ(strcmp(category_name, kTaskExecutionEventCategory), 0);
DCHECK(
strcmp(trace_event->name(), kTaskExecutionEventNames[0]) == 0 ||
strcmp(trace_event->name(), kTaskExecutionEventNames[1]) == 0 ||
strcmp(trace_event->name(), kTaskExecutionEventNames[2]) == 0);
- // Double argument task execution event (src_file, src_func).
- DCHECK_EQ(trace_event->arg_type(0), TRACE_VALUE_TYPE_STRING);
- DCHECK_EQ(trace_event->arg_type(1), TRACE_VALUE_TYPE_STRING);
src_file = trace_event->arg_value(0).as_string;
- src_func = trace_event->arg_value(1).as_string;
} else {
- // arg_size == 1 enforced by the maximum number of parameter == 2.
- DCHECK_EQ(trace_event->arg_size(), 1u);
+ DCHECK(trace_event->arg_type(0) == TRACE_VALUE_TYPE_CONVERTABLE);
+ DCHECK(strcmp(category_name, "log") == 0);
+ DCHECK(strcmp(trace_event->name(), "LogMessage") == 0);
+ const base::trace_event::LogMessage* value =
+ static_cast<base::trace_event::LogMessage*>(
+ trace_event->arg_value(0).as_convertable);
+ src_file = value->file();
+ line_number = value->line_number();
+ log_message_body = value->message().c_str();
- if (trace_event->arg_type(0) == TRACE_VALUE_TYPE_STRING) {
- // Single argument task execution event (src_file).
- DCHECK_EQ(strcmp(category_name, kTaskExecutionEventCategory), 0);
- DCHECK(
- strcmp(trace_event->name(), kTaskExecutionEventNames[0]) == 0 ||
- strcmp(trace_event->name(), kTaskExecutionEventNames[1]) == 0 ||
- strcmp(trace_event->name(), kTaskExecutionEventNames[2]) == 0);
- src_file = trace_event->arg_value(0).as_string;
- } else {
- DCHECK_EQ(trace_event->arg_type(0), TRACE_VALUE_TYPE_CONVERTABLE);
- DCHECK(strcmp(category_name, "log") == 0);
- DCHECK(strcmp(trace_event->name(), "LogMessage") == 0);
- const base::trace_event::LogMessage* value =
- static_cast<base::trace_event::LogMessage*>(
- trace_event->arg_value(0).as_convertable);
- src_file = value->file();
- line_number = value->line_number();
- log_message_body = value->message().c_str();
-
- interned_log_message_body =
- interned_log_message_bodies_.LookupOrAdd(value->message());
- } // else
- } // else
- interned_source_location = interned_source_locations_.LookupOrAdd(
- std::make_tuple(src_file, src_func, line_number));
- } else if (!privacy_filtering_enabled_) {
- for (size_t i = 0;
- i < trace_event->arg_size() && trace_event->arg_name(i); ++i) {
- interned_annotation_names[i] =
- interned_annotation_names_.LookupOrAdd(trace_event->arg_name(i));
- }
+ interned_log_message_body =
+ interned_log_message_bodies_.LookupOrAdd(value->message());
+ } // else
+ } // else
+ interned_source_location = interned_source_locations_.LookupOrAdd(
+ std::make_tuple(src_file, src_func, line_number));
+ } else if (!privacy_filtering_enabled_) {
+ for (size_t i = 0;
+ i < trace_event->arg_size() && trace_event->arg_name(i); ++i) {
+ interned_annotation_names[i] =
+ interned_annotation_names_.LookupOrAdd(trace_event->arg_name(i));
}
}
}
@@ -354,9 +367,7 @@
}
// TODO(eseckler): Split comma-separated category strings.
- if (interned_category.id) {
- track_event->add_category_iids(interned_category.id);
- }
+ track_event->add_category_iids(interned_category.id);
if (interned_log_message_body.id) {
auto* log_message = track_event->set_log_message();
@@ -371,11 +382,9 @@
auto* legacy_event = track_event->set_legacy_event();
- // TODO(eseckler): Set name on |track_event| instead.
- if (interned_name.id) {
- legacy_event->set_name_iid(interned_name.id);
- }
+ legacy_event->set_name_iid(interned_name.id);
+ char phase = trace_event->phase();
legacy_event->set_phase(phase);
if (phase == TRACE_EVENT_PHASE_COMPLETE) {
@@ -476,8 +485,7 @@
// Emit any new interned data entries into the packet.
perfetto::protos::pbzero::InternedData* interned_data = nullptr;
-
- if (interned_category.id && !interned_category.was_emitted) {
+ if (!interned_category.was_emitted) {
if (!interned_data) {
interned_data = trace_packet->set_interned_data();
}
@@ -486,7 +494,7 @@
category_entry->set_name(category_name);
}
- if (interned_name.id && !interned_name.was_emitted) {
+ if (!interned_name.was_emitted) {
if (!interned_data) {
interned_data = trace_packet->set_interned_data();
}
@@ -546,29 +554,41 @@
interned_source_locations_.Clear();
interned_log_message_bodies_.Clear();
}
-
-#if defined(OS_ANDROID)
- trace_event->SendToATrace();
-#endif
}
void TrackEventThreadLocalEventSink::UpdateDuration(
- const unsigned char* category_group_enabled,
- const char* name,
base::trace_event::TraceEventHandle handle,
- int thread_id,
- bool explicit_timestamps,
const base::TimeTicks& now,
const base::ThreadTicks& thread_now,
base::trace_event::ThreadInstructionCount thread_instruction_now) {
- base::trace_event::TraceEvent new_trace_event(
- thread_id, now, thread_now, thread_instruction_now, TRACE_EVENT_PHASE_END,
- category_group_enabled, name, trace_event_internal::kGlobalScope,
- trace_event_internal::kNoId /* id */,
- trace_event_internal::kNoId /* bind_id */, nullptr,
- explicit_timestamps ? TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP
- : TRACE_EVENT_FLAG_NONE);
- AddTraceEvent(&new_trace_event, nullptr);
+ if (!handle.event_index || handle.chunk_index != kMagicChunkIndex ||
+ handle.chunk_seq != sink_id_) {
+ return;
+ }
+
+ DCHECK_GE(current_stack_depth_, 1u);
+ // During trace shutdown, as the list of enabled categories are
+ // non-monotonically shut down, there's the possibility that events higher in
+ // the stack will have their category disabled prior to events lower in the
+ // stack, hence we get misaligned here. In this case, as we know we're
+ // shutting down, we leave the events unfinished.
+ if (handle.event_index != current_stack_depth_) {
+ DCHECK(handle.event_index > 0 &&
+ handle.event_index < current_stack_depth_ &&
+ !base::trace_event::TraceLog::GetInstance()->IsEnabled());
+ current_stack_depth_ = std::min(
+ current_stack_depth_, static_cast<uint32_t>(handle.event_index - 1));
+ return;
+ }
+
+ current_stack_depth_--;
+ complete_event_stack_[current_stack_depth_].UpdateDuration(
+ now, thread_now, thread_instruction_now);
+ AddTraceEvent(&complete_event_stack_[current_stack_depth_], nullptr);
+
+#if defined(OS_ANDROID)
+ complete_event_stack_[current_stack_depth_].SendToATrace();
+#endif
}
void TrackEventThreadLocalEventSink::Flush() {
diff --git a/services/tracing/public/cpp/perfetto/track_event_thread_local_event_sink.h b/services/tracing/public/cpp/perfetto/track_event_thread_local_event_sink.h
index 97cb808..b20860b 100644
--- a/services/tracing/public/cpp/perfetto/track_event_thread_local_event_sink.h
+++ b/services/tracing/public/cpp/perfetto/track_event_thread_local_event_sink.h
@@ -45,11 +45,7 @@
// ThreadLocalEventSink implementation:
void AddTraceEvent(base::trace_event::TraceEvent* trace_event,
base::trace_event::TraceEventHandle* handle) override;
- void UpdateDuration(const unsigned char* category_group_enabled,
- const char* name,
- base::trace_event::TraceEventHandle handle,
- int thread_id,
- bool explicit_timestamps,
+ void UpdateDuration(base::trace_event::TraceEventHandle handle,
const base::TimeTicks& now,
const base::ThreadTicks& thread_now,
base::trace_event::ThreadInstructionCount
@@ -98,6 +94,9 @@
perfetto::protos::pbzero::ThreadDescriptor::ChromeThreadType thread_type_ =
perfetto::protos::pbzero::ThreadDescriptor::CHROME_THREAD_UNSPECIFIED;
+ base::trace_event::TraceEvent complete_event_stack_[kMaxCompleteEventDepth];
+ uint32_t current_stack_depth_ = 0;
+
const bool privacy_filtering_enabled_;
};
