Commit 4e40d1a7 authored by Alexander Timin's avatar Alexander Timin Committed by Chromium LUCI CQ

[tracing] Replace TRACE_EVENT_FLOW* with TRACE_EVENT_WITH_FLOW*.

Remove old-style deprecated macros and reduce confusion.

R=eseckler@chromium.org,sunnyps@chromium.org,rockot@chromium.org
BUG=1164298

Change-Id: Ibb827cb42b62fb0f00ae46bd082c8b4a6f17caa1
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2617782
Commit-Queue: Alexander Timin <altimin@chromium.org>
Reviewed-by: default avatarSunny Sachanandani <sunnyps@chromium.org>
Reviewed-by: default avatarKen Rockot <rockot@google.com>
Reviewed-by: default avatarEric Seckler <eseckler@chromium.org>
Cr-Commit-Position: refs/heads/master@{#842352}
parent d92110d8
...@@ -861,109 +861,6 @@ ...@@ -861,109 +861,6 @@
category_group, name, id, \ category_group, name, id, \
TRACE_EVENT_FLAG_COPY, arg1_name, arg1_val) TRACE_EVENT_FLAG_COPY, arg1_name, arg1_val)
// Records a single FLOW_BEGIN event called "name" immediately, with 0, 1 or 2
// associated arguments. If the category is not enabled, then this
// does nothing.
// - category and name strings must have application lifetime (statics or
// literals). They may not include " chars.
// - |id| is used to match the FLOW_BEGIN event with the FLOW_END event. FLOW
// events are considered to match if their category_group, name and id values
// all match. |id| must either be a pointer or an integer value up to 64 bits.
// If it's a pointer, the bits will be xored with a hash of the process ID so
// that the same pointer on two different processes will not collide.
// FLOW events are different from ASYNC events in how they are drawn by the
// tracing UI. A FLOW defines asynchronous data flow, such as posting a task
// (FLOW_BEGIN) and later executing that task (FLOW_END). Expect FLOWs to be
// drawn as lines or arrows from FLOW_BEGIN scopes to FLOW_END scopes. Similar
// to ASYNC, a FLOW can consist of multiple phases. The first phase is defined
// by the FLOW_BEGIN calls. Additional phases can be defined using the FLOW_STEP
// macros. When the operation completes, call FLOW_END. An async operation can
// span threads and processes, but all events in that operation must use the
// same |name| and |id|. Each event can have its own args.
#define TRACE_EVENT_FLOW_BEGIN0(category_group, name, id) \
INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_BEGIN, \
category_group, name, id, \
TRACE_EVENT_FLAG_NONE)
#define TRACE_EVENT_FLOW_BEGIN1(category_group, name, id, arg1_name, arg1_val) \
INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_BEGIN, \
category_group, name, id, \
TRACE_EVENT_FLAG_NONE, arg1_name, arg1_val)
#define TRACE_EVENT_FLOW_BEGIN2(category_group, name, id, arg1_name, arg1_val, \
arg2_name, arg2_val) \
INTERNAL_TRACE_EVENT_ADD_WITH_ID( \
TRACE_EVENT_PHASE_FLOW_BEGIN, category_group, name, id, \
TRACE_EVENT_FLAG_NONE, arg1_name, arg1_val, arg2_name, arg2_val)
#define TRACE_EVENT_COPY_FLOW_BEGIN0(category_group, name, id) \
INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_BEGIN, \
category_group, name, id, \
TRACE_EVENT_FLAG_COPY)
#define TRACE_EVENT_COPY_FLOW_BEGIN1(category_group, name, id, arg1_name, \
arg1_val) \
INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_BEGIN, \
category_group, name, id, \
TRACE_EVENT_FLAG_COPY, arg1_name, arg1_val)
#define TRACE_EVENT_COPY_FLOW_BEGIN2(category_group, name, id, arg1_name, \
arg1_val, arg2_name, arg2_val) \
INTERNAL_TRACE_EVENT_ADD_WITH_ID( \
TRACE_EVENT_PHASE_FLOW_BEGIN, category_group, name, id, \
TRACE_EVENT_FLAG_COPY, arg1_name, arg1_val, arg2_name, arg2_val)
// Records a single FLOW_STEP event for |step| immediately. If the category
// is not enabled, then this does nothing. The |name| and |id| must match the
// FLOW_BEGIN event above. The |step| param identifies this step within the
// async event. This should be called at the beginning of the next phase of an
// asynchronous operation.
#define TRACE_EVENT_FLOW_STEP0(category_group, name, id, step) \
INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_STEP, \
category_group, name, id, \
TRACE_EVENT_FLAG_NONE, "step", step)
#define TRACE_EVENT_FLOW_STEP1(category_group, name, id, step, arg1_name, \
arg1_val) \
INTERNAL_TRACE_EVENT_ADD_WITH_ID( \
TRACE_EVENT_PHASE_FLOW_STEP, category_group, name, id, \
TRACE_EVENT_FLAG_NONE, "step", step, arg1_name, arg1_val)
#define TRACE_EVENT_COPY_FLOW_STEP0(category_group, name, id, step) \
INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_STEP, \
category_group, name, id, \
TRACE_EVENT_FLAG_COPY, "step", step)
#define TRACE_EVENT_COPY_FLOW_STEP1(category_group, name, id, step, arg1_name, \
arg1_val) \
INTERNAL_TRACE_EVENT_ADD_WITH_ID( \
TRACE_EVENT_PHASE_FLOW_STEP, category_group, name, id, \
TRACE_EVENT_FLAG_COPY, "step", step, arg1_name, arg1_val)
// Records a single FLOW_END event for "name" immediately. If the category
// is not enabled, then this does nothing.
#define TRACE_EVENT_FLOW_END0(category_group, name, id) \
INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_END, category_group, \
name, id, TRACE_EVENT_FLAG_NONE)
#define TRACE_EVENT_FLOW_END_BIND_TO_ENCLOSING0(category_group, name, id) \
INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_END, category_group, \
name, id, \
TRACE_EVENT_FLAG_BIND_TO_ENCLOSING)
#define TRACE_EVENT_FLOW_END1(category_group, name, id, arg1_name, arg1_val) \
INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_END, category_group, \
name, id, TRACE_EVENT_FLAG_NONE, arg1_name, \
arg1_val)
#define TRACE_EVENT_FLOW_END2(category_group, name, id, arg1_name, arg1_val, \
arg2_name, arg2_val) \
INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_END, category_group, \
name, id, TRACE_EVENT_FLAG_NONE, arg1_name, \
arg1_val, arg2_name, arg2_val)
#define TRACE_EVENT_COPY_FLOW_END0(category_group, name, id) \
INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_END, category_group, \
name, id, TRACE_EVENT_FLAG_COPY)
#define TRACE_EVENT_COPY_FLOW_END1(category_group, name, id, arg1_name, \
arg1_val) \
INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_END, category_group, \
name, id, TRACE_EVENT_FLAG_COPY, arg1_name, \
arg1_val)
#define TRACE_EVENT_COPY_FLOW_END2(category_group, name, id, arg1_name, \
arg1_val, arg2_name, arg2_val) \
INTERNAL_TRACE_EVENT_ADD_WITH_ID(TRACE_EVENT_PHASE_FLOW_END, category_group, \
name, id, TRACE_EVENT_FLAG_COPY, arg1_name, \
arg1_val, arg2_name, arg2_val)
// Special trace event macro to trace task execution with the location where it // Special trace event macro to trace task execution with the location where it
// was posted from. // was posted from.
#define TRACE_TASK_EXECUTION(run_function, task) \ #define TRACE_TASK_EXECUTION(run_function, task) \
......
...@@ -64,8 +64,6 @@ const int kAsyncId = 5; ...@@ -64,8 +64,6 @@ const int kAsyncId = 5;
const char kAsyncIdStr[] = "0x5"; const char kAsyncIdStr[] = "0x5";
const int kAsyncId2 = 6; const int kAsyncId2 = 6;
const char kAsyncId2Str[] = "0x6"; const char kAsyncId2Str[] = "0x6";
const int kFlowId = 7;
const char kFlowIdStr[] = "0x7";
constexpr const char kRecordAllCategoryFilter[] = "*"; constexpr const char kRecordAllCategoryFilter[] = "*";
constexpr const char kAllCategory[] = "all"; constexpr const char kAllCategory[] = "all";
...@@ -445,12 +443,6 @@ void TraceWithAllMacroVariants(WaitableEvent* task_complete_event) { ...@@ -445,12 +443,6 @@ void TraceWithAllMacroVariants(WaitableEvent* task_complete_event) {
"name1", "value1", "name1", "value1",
"name2", "value2"); "name2", "value2");
TRACE_EVENT_FLOW_BEGIN0("all", "TRACE_EVENT_FLOW_BEGIN0 call", kFlowId);
TRACE_EVENT_FLOW_STEP0("all", "TRACE_EVENT_FLOW_STEP0 call",
kFlowId, "step1");
TRACE_EVENT_FLOW_END_BIND_TO_ENCLOSING0("all",
"TRACE_EVENT_FLOW_END_BIND_TO_ENCLOSING0 call", kFlowId);
TRACE_COUNTER1("all", "TRACE_COUNTER1 call", 31415); TRACE_COUNTER1("all", "TRACE_COUNTER1 call", 31415);
TRACE_COUNTER2("all", "TRACE_COUNTER2 call", TRACE_COUNTER2("all", "TRACE_COUNTER2 call",
"a", 30000, "a", 30000,
...@@ -643,17 +635,6 @@ void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed) { ...@@ -643,17 +635,6 @@ void ValidateAllTraceMacrosCreatedData(const ListValue& trace_parsed) {
EXPECT_SUB_FIND_("name2"); EXPECT_SUB_FIND_("name2");
EXPECT_SUB_FIND_("value2"); EXPECT_SUB_FIND_("value2");
EXPECT_FIND_("TRACE_EVENT_FLOW_BEGIN0 call");
EXPECT_SUB_FIND_("id");
EXPECT_SUB_FIND_(kFlowIdStr);
EXPECT_FIND_("TRACE_EVENT_FLOW_STEP0 call");
EXPECT_SUB_FIND_("id");
EXPECT_SUB_FIND_(kFlowIdStr);
EXPECT_SUB_FIND_("step1");
EXPECT_FIND_("TRACE_EVENT_FLOW_END_BIND_TO_ENCLOSING0 call");
EXPECT_SUB_FIND_("id");
EXPECT_SUB_FIND_(kFlowIdStr);
EXPECT_FIND_("TRACE_COUNTER1 call"); EXPECT_FIND_("TRACE_COUNTER1 call");
{ {
std::string ph; std::string ph;
......
...@@ -18,9 +18,11 @@ BeginFrameTracker::~BeginFrameTracker() = default; ...@@ -18,9 +18,11 @@ BeginFrameTracker::~BeginFrameTracker() = default;
void BeginFrameTracker::Start(const viz::BeginFrameArgs& new_args) { void BeginFrameTracker::Start(const viz::BeginFrameArgs& new_args) {
// Trace the frame time being passed between BeginFrameTrackers. // Trace the frame time being passed between BeginFrameTrackers.
TRACE_EVENT_FLOW_STEP0( TRACE_EVENT_WITH_FLOW1(TRACE_DISABLED_BY_DEFAULT("cc.debug.scheduler.frames"),
TRACE_DISABLED_BY_DEFAULT("cc.debug.scheduler.frames"), "BeginFrameArgs", "BeginFrameArgs",
new_args.frame_time.since_origin().InMicroseconds(), location_string_); TRACE_EVENT_FLAG_FLOW_IN | TRACE_EVENT_FLAG_FLOW_OUT,
new_args.frame_time.since_origin().InMicroseconds(),
"location", location_string_);
// Trace this specific begin frame tracker Start/Finish times. // Trace this specific begin frame tracker Start/Finish times.
TRACE_EVENT_COPY_ASYNC_BEGIN2( TRACE_EVENT_COPY_ASYNC_BEGIN2(
......
...@@ -356,9 +356,9 @@ bool Scheduler::OnBeginFrameDerivedImpl(const viz::BeginFrameArgs& args) { ...@@ -356,9 +356,9 @@ bool Scheduler::OnBeginFrameDerivedImpl(const viz::BeginFrameArgs& args) {
} }
// Trace this begin frame time through the Chrome stack // Trace this begin frame time through the Chrome stack
TRACE_EVENT_FLOW_BEGIN0( TRACE_EVENT_WITH_FLOW0(TRACE_DISABLED_BY_DEFAULT("cc.debug.scheduler.frames"),
TRACE_DISABLED_BY_DEFAULT("cc.debug.scheduler.frames"), "viz::BeginFrameArgs", TRACE_EVENT_FLAG_FLOW_OUT,
"viz::BeginFrameArgs", args.frame_time.since_origin().InMicroseconds()); args.frame_time.since_origin().InMicroseconds());
if (settings_.using_synchronous_renderer_compositor) { if (settings_.using_synchronous_renderer_compositor) {
BeginImplFrameSynchronous(args); BeginImplFrameSynchronous(args);
......
...@@ -136,8 +136,8 @@ bool WebGPUCommandSerializer::Flush() { ...@@ -136,8 +136,8 @@ bool WebGPUCommandSerializer::Flush() {
TRACE_EVENT1(TRACE_DISABLED_BY_DEFAULT("gpu.dawn"), TRACE_EVENT1(TRACE_DISABLED_BY_DEFAULT("gpu.dawn"),
"WebGPUCommandSerializer::Flush", "bytes", c2s_put_offset_); "WebGPUCommandSerializer::Flush", "bytes", c2s_put_offset_);
TRACE_EVENT_FLOW_BEGIN0( TRACE_EVENT_WITH_FLOW0(TRACE_DISABLED_BY_DEFAULT("gpu.dawn"),
TRACE_DISABLED_BY_DEFAULT("gpu.dawn"), "DawnCommands", "DawnCommands", TRACE_EVENT_FLAG_FLOW_OUT,
(static_cast<uint64_t>(c2s_buffer_.shm_id()) << 32) + (static_cast<uint64_t>(c2s_buffer_.shm_id()) << 32) +
c2s_buffer_.offset()); c2s_buffer_.offset());
...@@ -415,8 +415,9 @@ void WebGPUImplementation::OnGpuControlReturnData( ...@@ -415,8 +415,9 @@ void WebGPUImplementation::OnGpuControlReturnData(
#if BUILDFLAG(USE_DAWN) #if BUILDFLAG(USE_DAWN)
static uint32_t return_trace_id = 0; static uint32_t return_trace_id = 0;
TRACE_EVENT_FLOW_END0(TRACE_DISABLED_BY_DEFAULT("gpu.dawn"), TRACE_EVENT_WITH_FLOW0(TRACE_DISABLED_BY_DEFAULT("gpu.dawn"),
"DawnReturnCommands", return_trace_id++); "DawnReturnCommands", TRACE_EVENT_FLAG_FLOW_IN,
return_trace_id++);
TRACE_EVENT1(TRACE_DISABLED_BY_DEFAULT("gpu.dawn"), TRACE_EVENT1(TRACE_DISABLED_BY_DEFAULT("gpu.dawn"),
"WebGPUImplementation::OnGpuControlReturnData", "bytes", "WebGPUImplementation::OnGpuControlReturnData", "bytes",
......
...@@ -115,8 +115,9 @@ bool WireServerCommandSerializer::Flush() { ...@@ -115,8 +115,9 @@ bool WireServerCommandSerializer::Flush() {
"WireServerCommandSerializer::Flush", "bytes", put_offset_); "WireServerCommandSerializer::Flush", "bytes", put_offset_);
static uint32_t return_trace_id = 0; static uint32_t return_trace_id = 0;
TRACE_EVENT_FLOW_BEGIN0(TRACE_DISABLED_BY_DEFAULT("gpu.dawn"), TRACE_EVENT_WITH_FLOW0(TRACE_DISABLED_BY_DEFAULT("gpu.dawn"),
"DawnReturnCommands", return_trace_id++); "DawnReturnCommands", TRACE_EVENT_FLAG_FLOW_OUT,
return_trace_id++);
client_->HandleReturnData(base::make_span(buffer_.data(), put_offset_)); client_->HandleReturnData(base::make_span(buffer_.data(), put_offset_));
put_offset_ = kDawnReturnCmdsOffset; put_offset_ = kDawnReturnCmdsOffset;
...@@ -1026,8 +1027,9 @@ error::Error WebGPUDecoderImpl::HandleDawnCommands( ...@@ -1026,8 +1027,9 @@ error::Error WebGPUDecoderImpl::HandleDawnCommands(
return error::kOutOfBounds; return error::kOutOfBounds;
} }
TRACE_EVENT_FLOW_END0( TRACE_EVENT_WITH_FLOW0(
TRACE_DISABLED_BY_DEFAULT("gpu.dawn"), "DawnCommands", TRACE_DISABLED_BY_DEFAULT("gpu.dawn"), "DawnCommands",
TRACE_EVENT_FLAG_FLOW_IN,
(static_cast<uint64_t>(commands_shm_id) << 32) + commands_shm_offset); (static_cast<uint64_t>(commands_shm_id) << 32) + commands_shm_offset);
TRACE_EVENT1(TRACE_DISABLED_BY_DEFAULT("gpu.dawn"), TRACE_EVENT1(TRACE_DISABLED_BY_DEFAULT("gpu.dawn"),
......
...@@ -457,9 +457,9 @@ bool SyncChannel::SyncContext::TryToUnblockListener(const Message* msg) { ...@@ -457,9 +457,9 @@ bool SyncChannel::SyncContext::TryToUnblockListener(const Message* msg) {
} }
base::WaitableEvent* done_event = deserializers_.back().done_event; base::WaitableEvent* done_event = deserializers_.back().done_event;
TRACE_EVENT_FLOW_BEGIN0("toplevel.flow", TRACE_EVENT_WITH_FLOW0("toplevel.flow",
"SyncChannel::SyncContext::TryToUnblockListener", "SyncChannel::SyncContext::TryToUnblockListener",
done_event); done_event, TRACE_EVENT_FLAG_FLOW_OUT);
done_event->Signal(); done_event->Signal();
...@@ -522,9 +522,9 @@ void SyncChannel::SyncContext::CancelPendingSends() { ...@@ -522,9 +522,9 @@ void SyncChannel::SyncContext::CancelPendingSends() {
PendingSyncMessageQueue::iterator iter; PendingSyncMessageQueue::iterator iter;
DVLOG(1) << "Canceling pending sends"; DVLOG(1) << "Canceling pending sends";
for (iter = deserializers_.begin(); iter != deserializers_.end(); iter++) { for (iter = deserializers_.begin(); iter != deserializers_.end(); iter++) {
TRACE_EVENT_FLOW_BEGIN0("toplevel.flow", TRACE_EVENT_WITH_FLOW0("toplevel.flow",
"SyncChannel::SyncContext::CancelPendingSends", "SyncChannel::SyncContext::CancelPendingSends",
iter->done_event); iter->done_event, TRACE_EVENT_FLAG_FLOW_OUT);
iter->done_event->Signal(); iter->done_event->Signal();
} }
} }
...@@ -644,8 +644,8 @@ bool SyncChannel::Send(Message* message) { ...@@ -644,8 +644,8 @@ bool SyncChannel::Send(Message* message) {
scoped_refptr<mojo::SyncHandleRegistry> registry = sync_handle_registry_; scoped_refptr<mojo::SyncHandleRegistry> registry = sync_handle_registry_;
WaitForReply(registry.get(), context.get(), pump_messages); WaitForReply(registry.get(), context.get(), pump_messages);
TRACE_EVENT_FLOW_END0("toplevel.flow", "SyncChannel::Send", TRACE_EVENT_WITH_FLOW0("toplevel.flow", "SyncChannel::Send",
context->GetSendDoneEvent()); context->GetSendDoneEvent(), TRACE_EVENT_FLAG_FLOW_IN);
return context->Pop(); return context->Pop();
} }
......
...@@ -84,8 +84,8 @@ bool SyncMessageFilter::Send(Message* message) { ...@@ -84,8 +84,8 @@ bool SyncMessageFilter::Send(Message* message) {
const bool* stop_flags[] = {&done, &shutdown}; const bool* stop_flags[] = {&done, &shutdown};
registry->Wait(stop_flags, 2); registry->Wait(stop_flags, 2);
if (done) { if (done) {
TRACE_EVENT_FLOW_END0("toplevel.flow", "SyncMessageFilter::Send", TRACE_EVENT_WITH_FLOW0("toplevel.flow", "SyncMessageFilter::Send",
&done_event); &done_event, TRACE_EVENT_FLAG_FLOW_IN);
} }
} }
...@@ -132,9 +132,9 @@ bool SyncMessageFilter::OnMessageReceived(const Message& message) { ...@@ -132,9 +132,9 @@ bool SyncMessageFilter::OnMessageReceived(const Message& message) {
(*iter)->send_result = (*iter)->send_result =
(*iter)->deserializer->SerializeOutputParameters(message); (*iter)->deserializer->SerializeOutputParameters(message);
} }
TRACE_EVENT_FLOW_BEGIN0("toplevel.flow", TRACE_EVENT_WITH_FLOW0("toplevel.flow",
"SyncMessageFilter::OnMessageReceived", "SyncMessageFilter::OnMessageReceived",
(*iter)->done_event); (*iter)->done_event, TRACE_EVENT_FLAG_FLOW_OUT);
(*iter)->done_event->Signal(); (*iter)->done_event->Signal();
return true; return true;
} }
...@@ -170,9 +170,9 @@ void SyncMessageFilter::SignalAllEvents() { ...@@ -170,9 +170,9 @@ void SyncMessageFilter::SignalAllEvents() {
lock_.AssertAcquired(); lock_.AssertAcquired();
for (PendingSyncMessages::iterator iter = pending_sync_messages_.begin(); for (PendingSyncMessages::iterator iter = pending_sync_messages_.begin();
iter != pending_sync_messages_.end(); ++iter) { iter != pending_sync_messages_.end(); ++iter) {
TRACE_EVENT_FLOW_BEGIN0("toplevel.flow", TRACE_EVENT_WITH_FLOW0("toplevel.flow",
"SyncMessageFilter::SignalAllEvents", "SyncMessageFilter::SignalAllEvents",
(*iter)->done_event); (*iter)->done_event, TRACE_EVENT_FLAG_FLOW_OUT);
(*iter)->done_event->Signal(); (*iter)->done_event->Signal();
} }
} }
......
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