Commit d0e620d5 authored by Andrew Shulaev's avatar Andrew Shulaev Committed by Commit Bot

Typed parameters for async events support

This patch adds support for typed arguments on async events (using
Perfetto's Track argument for trace macros), which will enable

Bug: 149824486
Change-Id: I2fa599dfa037528bf2c04e3e5ec8cdfaf0eac56d
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2096756
Commit-Queue: Andrew Shulaev <ddrone@google.com>
Reviewed-by: default avatarStephen Nusko <nuskos@chromium.org>
Reviewed-by: default avatarEric Seckler <eseckler@chromium.org>
Cr-Commit-Position: refs/heads/master@{#761029}
parent b8e55a49
......@@ -36,6 +36,12 @@ constexpr char kTraceEventEndName[] = "";
// strings must be static constants. The track event is only recorded if
// |category| is enabled for a tracing session.
//
// Rest of parameters can contain: a perfetto::Track object for asynchronous
// events and a lambda used to fill typed event. Should be passed in that exact
// order when both are used.
//
// When lambda is passed as an argument, it is executed synchronously.
//
// TODO(nuskos): Give a simple example once we have a typed event that doesn't
// need interning.
// TRACE_EVENT_BEGIN("log", "LogMessage",
......@@ -43,21 +49,24 @@ constexpr char kTraceEventEndName[] = "";
// auto* event = ctx.event();
// // Fill in some field in track_event.
// });
//
// When lambda is passed as an argument, it is executed synchronously.
#define TRACE_EVENT_BEGIN(category, name, ...) \
TRACING_INTERNAL_ADD_TRACE_EVENT(TRACE_EVENT_PHASE_BEGIN, category, name, \
TRACE_EVENT_FLAG_NONE, ##__VA_ARGS__)
// End a thread-scoped slice under |category|.
#define TRACE_EVENT_END(category, ...) \
TRACING_INTERNAL_ADD_TRACE_EVENT(TRACE_EVENT_PHASE_END, category, \
kTraceEventEndName, TRACE_EVENT_FLAG_NONE, \
##__VA_ARGS__)
#define TRACE_EVENT_END(category, ...) \
TRACING_INTERNAL_ADD_TRACE_EVENT(TRACE_EVENT_PHASE_END, category, \
tracing::kTraceEventEndName, \
TRACE_EVENT_FLAG_NONE, ##__VA_ARGS__)
// Begin a thread-scoped slice which gets automatically closed when going out
// of scope.
//
// BEWARE: similarly to TRACE_EVENT_BEGIN, this macro does accept a track, but
// it does not work properly and should not be used.
// TODO(b/154583431): figure out how to fix or disallow that and update the
// comment.
//
// Similarly to TRACE_EVENT_BEGIN, when lambda is passed as an argument, it is
// executed synchronously.
#define TRACE_EVENT(category, name, ...) \
......
......@@ -6,10 +6,8 @@
#define SERVICES_TRACING_PUBLIC_CPP_PERFETTO_MACROS_INTERNAL_H_
#include "build/build_config.h"
namespace perfetto {
class EventContext;
}
#include "third_party/perfetto/include/perfetto/tracing/event_context.h"
#include "third_party/perfetto/include/perfetto/tracing/track.h"
#if !defined(OS_IOS) && !defined(OS_NACL)
......@@ -34,6 +32,7 @@ static inline base::trace_event::TraceEventHandle AddTraceEvent(
const unsigned char* category_group_enabled,
const char* name,
unsigned int flags,
const perfetto::Track& track,
TrackEventArgumentFunction argument_func) {
base::trace_event::TraceEventHandle handle = {0, 0, 0};
auto maybe_event =
......@@ -43,9 +42,11 @@ static inline base::trace_event::TraceEventHandle AddTraceEvent(
}
TraceEventDataSource::OnAddTraceEvent(&maybe_event.value(),
/* thread_will_flush = */ false,
nullptr, std::move(argument_func));
nullptr, track,
std::move(argument_func));
return handle;
}
} // namespace internal
} // namespace tracing
......@@ -106,9 +107,11 @@ static inline base::trace_event::TraceEventHandle AddTraceEvent(
const unsigned char*,
const char*,
unsigned int,
const perfetto::Track&,
TrackEventArgumentFunction) {
return {0, 0, 0};
}
} // namespace internal
} // namespace tracing
......@@ -120,4 +123,57 @@ static inline base::trace_event::TraceEventHandle AddTraceEvent(
##__VA_ARGS__);
#endif // else of !defined(OS_IOS) && !defined(OS_NACL)
namespace tracing {
namespace internal {
// Copy of function with the same name from Perfetto client library.
template <typename T>
static constexpr bool IsValidTraceLambdaImpl(
typename std::enable_if<static_cast<bool>(
sizeof(std::declval<T>()(std::declval<perfetto::EventContext>()),
0))>::type* = nullptr) {
return true;
}
template <typename T>
static constexpr bool IsValidTraceLambdaImpl(...) {
return false;
}
template <typename T>
static constexpr bool IsValidTraceLambda() {
return IsValidTraceLambdaImpl<T>(nullptr);
}
template <
typename TrackEventArgumentFunction = void (*)(perfetto::EventContext),
typename ArgumentFunctionCheck = typename std::enable_if<
IsValidTraceLambda<TrackEventArgumentFunction>()>::type>
static inline base::trace_event::TraceEventHandle AddTraceEvent(
char phase,
const unsigned char* category_group_enabled,
const char* name,
unsigned int flags,
TrackEventArgumentFunction argument_func) {
perfetto::Track track{};
return AddTraceEvent(phase, category_group_enabled, name, flags, track,
argument_func);
}
template <typename TrackType,
typename TrackTypeCheck = typename std::enable_if<
std::is_convertible<TrackType, perfetto::Track>::value>::type>
inline base::trace_event::TraceEventHandle AddTraceEvent(
char phase,
const unsigned char* category_group_enabled,
const char* name,
unsigned int flags,
const TrackType& track) {
return AddTraceEvent(phase, category_group_enabled, name, flags, track,
[](perfetto::EventContext ctx) {});
}
} // namespace internal
} // namespace tracing
#endif // SERVICES_TRACING_PUBLIC_CPP_PERFETTO_MACROS_INTERNAL_H_
......@@ -949,7 +949,7 @@ void TraceEventDataSource::OnAddTraceEvent(
TraceEvent* trace_event,
bool thread_will_flush,
base::trace_event::TraceEventHandle* handle) {
OnAddTraceEvent(trace_event, thread_will_flush, handle,
OnAddTraceEvent(trace_event, thread_will_flush, handle, perfetto::Track(),
[](perfetto::EventContext) {});
}
......
......@@ -188,12 +188,13 @@ class COMPONENT_EXPORT(TRACING_CPP) TraceEventDataSource
static void OnAddTraceEvent(base::trace_event::TraceEvent* trace_event,
bool thread_will_flush,
base::trace_event::TraceEventHandle* handle,
const perfetto::Track& track,
TrackEventArgumentFunction func) {
auto* thread_local_event_sink = GetOrPrepareEventSink(thread_will_flush);
if (thread_local_event_sink) {
AutoThreadLocalBoolean thread_is_in_trace_event(
GetThreadIsInTraceEventTLS());
thread_local_event_sink->AddTraceEvent(trace_event, handle, func);
thread_local_event_sink->AddTraceEvent(trace_event, handle, track, func);
}
}
......
......@@ -485,7 +485,8 @@ class TraceEventDataSourceTest : public testing::Test {
uint64_t id = 0,
uint64_t absolute_timestamp = 0,
int32_t tid_override = 0,
int32_t pid_override = 0) {
int32_t pid_override = 0,
const perfetto::Track& track = perfetto::Track()) {
// All TrackEvents need incremental state for delta timestamps / interning.
EXPECT_EQ(packet->sequence_flags(),
static_cast<uint32_t>(perfetto::protos::pbzero::TracePacket::
......@@ -560,22 +561,22 @@ class TraceEventDataSourceTest : public testing::Test {
break;
case TRACE_EVENT_SCOPE_THREAD:
if (!tid_override) {
if (!track) {
// Default to thread track.
EXPECT_FALSE(packet->track_event().has_track_uuid());
} else {
EXPECT_EQ(packet->track_event().track_uuid(),
perfetto::ThreadTrack::ForThread(tid_override).uuid);
EXPECT_TRUE(packet->track_event().has_track_uuid());
EXPECT_EQ(packet->track_event().track_uuid(), track.uuid);
}
break;
}
} else {
if (!tid_override) {
if (!track) {
// Default to thread track.
EXPECT_FALSE(packet->track_event().has_track_uuid());
} else {
EXPECT_EQ(packet->track_event().track_uuid(),
perfetto::ThreadTrack::ForThread(tid_override).uuid);
EXPECT_TRUE(packet->track_event().has_track_uuid());
EXPECT_EQ(packet->track_event().track_uuid(), track.uuid);
}
}
} else {
......@@ -895,7 +896,8 @@ TEST_F(TraceEventDataSourceTest, TimestampedTraceEvent) {
e_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_ASYNC_BEGIN,
TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP | TRACE_EVENT_FLAG_HAS_ID, /*id=*/42u,
/*absolute_timestamp=*/424242, /*tid_override=*/4242);
/*absolute_timestamp=*/424242, /*tid_override=*/4242, /*pid_override=*/0,
perfetto::ThreadTrack::ForThread(4242));
ExpectEventCategories(e_packet, {{1u, kCategoryGroup}});
ExpectEventNames(e_packet, {{1u, "bar"}});
......@@ -1191,7 +1193,8 @@ TEST_F(TraceEventDataSourceTest, UpdateDurationOfCompleteEvent) {
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);
/*absolute_timestamp=*/10, /*tid_override=*/1, /*pid_override=*/0,
perfetto::ThreadTrack::ForThread(1));
// 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
......@@ -1203,10 +1206,11 @@ TEST_F(TraceEventDataSourceTest, UpdateDurationOfCompleteEvent) {
base::trace_event::ThreadInstructionCount());
auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
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);
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, perfetto::ThreadTrack::ForThread(1));
// Updating the duration of an event that wasn't added before tracing begun
// will only emit an END event, again without category or name.
......@@ -1218,10 +1222,130 @@ TEST_F(TraceEventDataSourceTest, UpdateDurationOfCompleteEvent) {
base::trace_event::ThreadInstructionCount());
auto* e2_packet = producer_client()->GetFinalizedPacket(packet_index++);
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);
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, perfetto::ThreadTrack::ForThread(1));
}
TEST_F(TraceEventDataSourceTest, TrackSupportOnBeginAndEndWithLambda) {
CreateTraceEventDataSource();
auto track = perfetto::Track(1);
bool begin_called = false;
bool end_called = false;
TRACE_EVENT_BEGIN("browser", "bar", track,
[&](perfetto::EventContext ctx) { begin_called = true; });
EXPECT_TRUE(begin_called);
TRACE_EVENT_END("browser", track,
[&](perfetto::EventContext ctx) { end_called = true; });
EXPECT_TRUE(end_called);
size_t packet_index = ExpectStandardPreamble();
auto* b_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(b_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_BEGIN, /*flags=*/0, /*id=*/0,
/*absolute_timestamp=*/0, /*tid_override=*/0,
/*pid_override=*/0, track);
ExpectEventCategories(b_packet, {{1u, "browser"}});
ExpectEventNames(b_packet, {{1u, "bar"}});
auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/0, /*name_iid=*/0,
TRACE_EVENT_PHASE_END, /*flags=*/0, /*id=*/0,
/*absolute_timestamp=*/0, /*tid_override=*/0,
/*pid_override=*/0, track);
}
TEST_F(TraceEventDataSourceTest, TrackSupportOnBeginAndEnd) {
CreateTraceEventDataSource();
auto track = perfetto::Track(1);
TRACE_EVENT_BEGIN("browser", "bar", track);
TRACE_EVENT_END("browser", track);
size_t packet_index = ExpectStandardPreamble();
auto* b_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(b_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_BEGIN, /*flags=*/0, /*id=*/0,
/*absolute_timestamp=*/0, /*tid_override=*/0,
/*pid_override=*/0, track);
ExpectEventCategories(b_packet, {{1u, "browser"}});
ExpectEventNames(b_packet, {{1u, "bar"}});
auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/0, /*name_iid=*/0,
TRACE_EVENT_PHASE_END, /*flags=*/0, /*id=*/0,
/*absolute_timestamp=*/0, /*tid_override=*/0,
/*pid_override=*/0, track);
}
// TODO(ddrone): following tests should be re-enabled once we figure out how
// tracks on scoped events supposed to work
TEST_F(TraceEventDataSourceTest, DISABLED_TrackSupport) {
CreateTraceEventDataSource();
auto track = perfetto::Track(1);
{ TRACE_EVENT("browser", "bar", track); }
size_t packet_index = ExpectStandardPreamble();
auto* b_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(b_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_BEGIN, /*flags=*/0, /*id=*/0,
/*absolute_timestamp=*/0, /*tid_override=*/0,
/*pid_override=*/0, track);
ExpectEventCategories(b_packet, {{1u, "browser"}});
ExpectEventNames(b_packet, {{1u, "bar"}});
auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/0, /*name_iid=*/0,
TRACE_EVENT_PHASE_END, /*flags=*/0, /*id=*/0,
/*absolute_timestamp=*/0, /*tid_override=*/0,
/*pid_override=*/0, track);
}
TEST_F(TraceEventDataSourceTest, DISABLED_TrackSupportWithLambda) {
CreateTraceEventDataSource();
auto track = perfetto::Track(1);
bool lambda_called = false;
{
TRACE_EVENT("browser", "bar", track,
[&](perfetto::EventContext ctx) { lambda_called = true; });
}
EXPECT_TRUE(lambda_called);
size_t packet_index = ExpectStandardPreamble();
auto* b_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(b_packet, /*category_iid=*/1u, /*name_iid=*/1u,
TRACE_EVENT_PHASE_BEGIN, /*flags=*/0, /*id=*/0,
/*absolute_timestamp=*/0, /*tid_override=*/0,
/*pid_override=*/0, track);
ExpectEventCategories(b_packet, {{1u, "browser"}});
ExpectEventNames(b_packet, {{1u, "bar"}});
auto* e_packet = producer_client()->GetFinalizedPacket(packet_index++);
ExpectTraceEvent(e_packet, /*category_iid=*/0, /*name_iid=*/0,
TRACE_EVENT_PHASE_END, /*flags=*/0, /*id=*/0,
/*absolute_timestamp=*/0, /*tid_override=*/0,
/*pid_override=*/0, track);
}
// TODO(eseckler): Add a test with multiple events + same strings (cat, name,
......
......@@ -680,7 +680,9 @@ void TrackEventThreadLocalEventSink::UpdateDuration(
trace_event_internal::kNoId /* bind_id */, nullptr,
explicit_timestamps ? TRACE_EVENT_FLAG_EXPLICIT_TIMESTAMP
: TRACE_EVENT_FLAG_NONE);
AddTraceEvent(&new_trace_event, nullptr, [](perfetto::EventContext) {});
perfetto::Track track{};
AddTraceEvent(&new_trace_event, nullptr, track,
[](perfetto::EventContext) {});
}
void TrackEventThreadLocalEventSink::Flush() {
......
......@@ -92,6 +92,7 @@ class COMPONENT_EXPORT(TRACING_CPP) TrackEventThreadLocalEventSink
typename TrackEventArgumentFunction = void (*)(perfetto::EventContext)>
void AddTraceEvent(base::trace_event::TraceEvent* trace_event,
base::trace_event::TraceEventHandle* handle,
const perfetto::Track& track,
TrackEventArgumentFunction arg_func) {
ResetIncrementalStateIfNeeded(trace_event);
......@@ -100,6 +101,11 @@ class COMPONENT_EXPORT(TRACING_CPP) TrackEventThreadLocalEventSink
// Note: Since |track_event| is a protozero message under |trace_packet|, we
// can't modify |trace_packet| further until we're done with |track_event|.
auto* track_event = PrepareTrackEvent(trace_event, handle, &trace_packet);
if (track) {
track_event->set_track_uuid(track.uuid);
}
arg_func(perfetto::EventContext(track_event));
if (!pending_interning_updates_.empty()) {
......
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