tracing: Replace uses of TRACE_EVENT_ASYNC* in cc/

The deprecated TRACE_EVENT_ASYNC* macros have been superseded by
TRACE_EVENT_NESTABLE_ASYNC*.

Updating to the new macros is mostly straight-forward, except in cases
where STEP_INTO/PAST macros were used extensively: In those cases, the
steps have been converted into nested sub-events.

Note this also fixes an issue in CompositorFrameReporter where the
parent "PipelineReporter" event may have begin/end timestamps that
didn't match its child stage event's explicit timestamps.

Bug: 1038710
Change-Id: I127a266af023876a8653873108389c477da55c5f
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1986839
Commit-Queue: Eric Seckler <eseckler@chromium.org>
Reviewed-by: Eric Karl <ericrk@chromium.org>
Reviewed-by: Sami Kyöstilä <skyostil@chromium.org>
Cr-Commit-Position: refs/heads/master@{#732531}

base/trace_event/common/trace_event_common.h

@@ -802,6 +802,12 @@
   INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP(                          \
       TRACE_EVENT_PHASE_NESTABLE_ASYNC_BEGIN, category_group, name, id,        \
       TRACE_EVENT_API_CURRENT_THREAD_ID, timestamp, TRACE_EVENT_FLAG_NONE)
+#define TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP1(                  \
+    category_group, name, id, timestamp, arg1_name, arg1_val)              \
+  INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP(                      \
+      TRACE_EVENT_PHASE_NESTABLE_ASYNC_BEGIN, category_group, name, id,    \
+      TRACE_EVENT_API_CURRENT_THREAD_ID, timestamp, TRACE_EVENT_FLAG_NONE, \
+      arg1_name, arg1_val)
 #define TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(category_group, name, \
                                                        id, timestamp)        \
   INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP(                        \
@@ -813,6 +819,13 @@
       TRACE_EVENT_PHASE_NESTABLE_ASYNC_END, category_group, name, id,      \
       TRACE_EVENT_API_CURRENT_THREAD_ID, timestamp, TRACE_EVENT_FLAG_NONE, \
       arg1_name, arg1_val)
+#define TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP2(                    \
+    category_group, name, id, timestamp, arg1_name, arg1_val, arg2_name,   \
+    arg2_val)                                                              \
+  INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP(                      \
+      TRACE_EVENT_PHASE_NESTABLE_ASYNC_END, category_group, name, id,      \
+      TRACE_EVENT_API_CURRENT_THREAD_ID, timestamp, TRACE_EVENT_FLAG_NONE, \
+      arg1_name, arg1_val, arg2_name, arg2_val)
 #define TRACE_EVENT_NESTABLE_ASYNC_INSTANT_WITH_TIMESTAMP0(               \
     category_group, name, id, timestamp)                                  \
   INTERNAL_TRACE_EVENT_ADD_WITH_ID_TID_AND_TIMESTAMP(                     \

cc/animation/keyframe_model.cc

@@ -123,8 +123,9 @@ void KeyframeModel::SetRunState(RunState run_state,
       run_state_ == WAITING_FOR_TARGET_AVAILABILITY || run_state_ == STARTING;
 
   if (is_controlling_instance_ && is_waiting_to_start && run_state == RUNNING) {
-    TRACE_EVENT_ASYNC_BEGIN1("cc", "KeyframeModel", this, "Name",
-                             TRACE_STR_COPY(name_buffer));
+    TRACE_EVENT_NESTABLE_ASYNC_BEGIN1("cc", "KeyframeModel",
+                                      TRACE_ID_LOCAL(this), "Name",
+                                      TRACE_STR_COPY(name_buffer));
   }
 
   bool was_finished = is_finished();
@@ -139,8 +140,10 @@ void KeyframeModel::SetRunState(RunState run_state,
 
   const char* new_run_state_name = s_runStateNames[run_state];
 
-  if (is_controlling_instance_ && !was_finished && is_finished())
-    TRACE_EVENT_ASYNC_END0("cc", "KeyframeModel", this);
+  if (is_controlling_instance_ && !was_finished && is_finished()) {
+    TRACE_EVENT_NESTABLE_ASYNC_END0("cc", "KeyframeModel",
+                                    TRACE_ID_LOCAL(this));
+  }
 
   char state_buffer[256];
   base::snprintf(state_buffer, sizeof(state_buffer), "%s->%s",

cc/metrics/compositor_frame_reporter.cc

@@ -158,10 +158,7 @@ CompositorFrameReporter::CompositorFrameReporter(
     : frame_id_(id),
       is_single_threaded_(is_single_threaded),
       active_trackers_(active_trackers),
-      latency_ukm_reporter_(latency_ukm_reporter) {
-  TRACE_EVENT_ASYNC_BEGIN1("cc,benchmark", "PipelineReporter", this,
-                           "is_single_threaded", is_single_threaded);
-}
+      latency_ukm_reporter_(latency_ukm_reporter) {}
 
 CompositorFrameReporter::~CompositorFrameReporter() {
   TerminateReporter();
@@ -179,19 +176,31 @@ void CompositorFrameReporter::StartStage(
     CompositorFrameReporter::StageType stage_type,
     base::TimeTicks start_time) {
   EndCurrentStage(start_time);
+  if (stage_history_.empty()) {
+    // Use first stage's start timestamp to ensure correct event nesting.
+    TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP1(
+        "cc,benchmark", "PipelineReporter", TRACE_ID_LOCAL(this), start_time,
+        "is_single_threaded", is_single_threaded_);
+  }
   current_stage_.stage_type = stage_type;
   current_stage_.start_time = start_time;
   int stage_type_index = static_cast<int>(current_stage_.stage_type);
   CHECK_LT(stage_type_index, static_cast<int>(StageType::kStageTypeCount));
   CHECK_GE(stage_type_index, 0);
-  TRACE_EVENT_ASYNC_STEP_INTO_WITH_TIMESTAMP0(
-      "cc,benchmark", "PipelineReporter", this, GetStageName(stage_type_index),
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN_WITH_TIMESTAMP0(
+      "cc,benchmark", GetStageName(stage_type_index), TRACE_ID_LOCAL(this),
       start_time);
 }
 
 void CompositorFrameReporter::EndCurrentStage(base::TimeTicks end_time) {
   if (current_stage_.start_time == base::TimeTicks())
     return;
+  int stage_type_index = static_cast<int>(current_stage_.stage_type);
+  CHECK_LT(stage_type_index, static_cast<int>(StageType::kStageTypeCount));
+  CHECK_GE(stage_type_index, 0);
+  TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP0(
+      "cc,benchmark", GetStageName(stage_type_index), TRACE_ID_LOCAL(this),
+      end_time);
   current_stage_.end_time = end_time;
   stage_history_.push_back(current_stage_);
   current_stage_.start_time = base::TimeTicks();
@@ -236,8 +245,9 @@ void CompositorFrameReporter::SetVizBreakdown(
 }
 
 void CompositorFrameReporter::TerminateReporter() {
-  if (frame_termination_status_ != FrameTerminationStatus::kUnknown)
-    DCHECK_EQ(current_stage_.start_time, base::TimeTicks());
+  if (frame_termination_status_ == FrameTerminationStatus::kUnknown)
+    TerminateFrame(FrameTerminationStatus::kUnknown, base::TimeTicks::Now());
+  DCHECK_EQ(current_stage_.start_time, base::TimeTicks());
   bool report_latency = false;
   const char* termination_status_str = nullptr;
   switch (frame_termination_status_) {
@@ -262,12 +272,17 @@ void CompositorFrameReporter::TerminateReporter() {
       termination_status_str = "terminated_before_ending";
       break;
   }
-  const char* submission_status_str =
-      submitted_frame_missed_deadline_ ? "missed_frame" : "non_missed_frame";
-  TRACE_EVENT_ASYNC_END_WITH_TIMESTAMP2(
-      "cc,benchmark", "PipelineReporter", this, frame_termination_time_,
-      "termination_status", termination_status_str,
-      "compositor_frame_submission_status", submission_status_str);
+
+  // If we don't have any stage data, we haven't emitted the corresponding start
+  // event, so skip emitting the end event, too.
+  if (!stage_history_.empty()) {
+    const char* submission_status_str =
+        submitted_frame_missed_deadline_ ? "missed_frame" : "non_missed_frame";
+    TRACE_EVENT_NESTABLE_ASYNC_END_WITH_TIMESTAMP2(
+        "cc,benchmark", "PipelineReporter", TRACE_ID_LOCAL(this),
+        frame_termination_time_, "termination_status", termination_status_str,
+        "compositor_frame_submission_status", submission_status_str);
+  }
 
   // Only report histograms if the frame was presented.
   if (report_latency) {

cc/metrics/frame_sequence_tracker.cc

@@ -129,8 +129,8 @@ FrameSequenceMetrics::FrameSequenceMetrics(FrameSequenceTrackerType type,
     : type_(type),
       ukm_manager_(ukm_manager),
       throughput_ukm_reporter_(ukm_reporter) {
-  TRACE_EVENT_ASYNC_BEGIN1(
-      "cc,benchmark", "FrameSequenceTracker", this, "name",
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN1(
+      "cc,benchmark", "FrameSequenceTracker", TRACE_ID_LOCAL(this), "name",
       FrameSequenceTracker::GetFrameSequenceTrackerTypeName(type_));
 }
 
@@ -166,8 +166,8 @@ bool FrameSequenceMetrics::HasDataLeftForReporting() const {
 void FrameSequenceMetrics::ReportMetrics(const std::string& debug_trace) {
   DCHECK_LE(impl_throughput_.frames_produced, impl_throughput_.frames_expected);
   DCHECK_LE(main_throughput_.frames_produced, main_throughput_.frames_expected);
-  TRACE_EVENT_ASYNC_END2(
-      "cc,benchmark", "FrameSequenceTracker", this, "args",
+  TRACE_EVENT_NESTABLE_ASYNC_END2(
+      "cc,benchmark", "FrameSequenceTracker", TRACE_ID_LOCAL(this), "args",
       ThroughputData::ToTracedValue(impl_throughput_, main_throughput_),
       "checkerboard", frames_checkerboarded_);
 
@@ -687,8 +687,8 @@ void FrameSequenceTracker::ReportFramePresented(
   if (ignored_frame_tokens_.contains(frame_token))
     return;
 
-  TRACE_EVENT_ASYNC_STEP_INTO_WITH_TIMESTAMP0(
-      "cc,benchmark", "FrameSequenceTracker", metrics_.get(), "FramePresented",
+  TRACE_EVENT_NESTABLE_ASYNC_INSTANT_WITH_TIMESTAMP0(
+      "cc,benchmark", "FramePresented", TRACE_ID_LOCAL(metrics_.get()),
       feedback.timestamp);
   const bool was_presented = !feedback.timestamp.is_null();
   if (was_presented && last_submitted_frame_) {

cc/scheduler/scheduler_state_machine.cc

@@ -1356,8 +1356,9 @@ void SchedulerStateMachine::SetNeedsPrepareTiles() {
   }
 }
 void SchedulerStateMachine::DidSubmitCompositorFrame() {
-  TRACE_EVENT_ASYNC_BEGIN1("cc", "Scheduler:pending_submit_frames", this,
-                           "pending_frames", pending_submit_frames_);
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN1("cc", "Scheduler:pending_submit_frames",
+                                    TRACE_ID_LOCAL(this), "pending_frames",
+                                    pending_submit_frames_);
   DCHECK_LT(pending_submit_frames_, kMaxPendingSubmitFrames);
 
   pending_submit_frames_++;
@@ -1368,8 +1369,9 @@ void SchedulerStateMachine::DidSubmitCompositorFrame() {
 }
 
 void SchedulerStateMachine::DidReceiveCompositorFrameAck() {
-  TRACE_EVENT_ASYNC_END1("cc", "Scheduler:pending_submit_frames", this,
-                         "pending_frames", pending_submit_frames_);
+  TRACE_EVENT_NESTABLE_ASYNC_END1("cc", "Scheduler:pending_submit_frames",
+                                  TRACE_ID_LOCAL(this), "pending_frames",
+                                  pending_submit_frames_);
   pending_submit_frames_--;
 }
 

cc/tiles/checker_image_tracker.cc

@@ -227,8 +227,8 @@ void CheckerImageTracker::DidFinishImageDecode(
     ImageController::ImageDecodeResult result) {
   TRACE_EVENT0(TRACE_DISABLED_BY_DEFAULT("cc.debug"),
                "CheckerImageTracker::DidFinishImageDecode");
-  TRACE_EVENT_ASYNC_END0("cc", "CheckerImageTracker::DeferImageDecode",
-                         image_id);
+  TRACE_EVENT_NESTABLE_ASYNC_END0("cc", "CheckerImageTracker::DeferImageDecode",
+                                  TRACE_ID_LOCAL(image_id));
 
   DCHECK_NE(ImageController::ImageDecodeResult::DECODE_NOT_REQUIRED, result);
   DCHECK_EQ(outstanding_image_decode_.value().stable_id(), image_id);
@@ -427,8 +427,8 @@ void CheckerImageTracker::ScheduleNextImageDecode() {
 
   PaintImage::Id image_id = outstanding_image_decode_.value().stable_id();
   DCHECK_EQ(image_id_to_decode_.count(image_id), 0u);
-  TRACE_EVENT_ASYNC_BEGIN0("cc", "CheckerImageTracker::DeferImageDecode",
-                           image_id);
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0(
+      "cc", "CheckerImageTracker::DeferImageDecode", TRACE_ID_LOCAL(image_id));
   ImageController::ImageDecodeRequestId request_id =
       image_controller_->QueueImageDecode(
           draw_image, base::BindOnce(&CheckerImageTracker::DidFinishImageDecode,

cc/tiles/tile_manager.cc

@@ -465,8 +465,9 @@ void TileManager::Release(Tile* tile) {
 void TileManager::DidFinishRunningTileTasksRequiredForActivation() {
   TRACE_EVENT0("cc",
                "TileManager::DidFinishRunningTileTasksRequiredForActivation");
-  TRACE_EVENT_ASYNC_STEP_INTO1("cc", "ScheduledTasks", this, "running", "state",
-                               ScheduledTasksStateAsValue());
+  TRACE_EVENT_NESTABLE_ASYNC_INSTANT1("cc", "ScheduledTasksState",
+                                      TRACE_ID_LOCAL(this), "state",
+                                      ScheduledTasksStateAsValue());
   // TODO(vmpstr): Temporary check to debug crbug.com/642927.
   CHECK(tile_task_manager_);
   signals_.activate_tile_tasks_completed = true;
@@ -475,8 +476,9 @@ void TileManager::DidFinishRunningTileTasksRequiredForActivation() {
 
 void TileManager::DidFinishRunningTileTasksRequiredForDraw() {
   TRACE_EVENT0("cc", "TileManager::DidFinishRunningTileTasksRequiredForDraw");
-  TRACE_EVENT_ASYNC_STEP_INTO1("cc", "ScheduledTasks", this, "running", "state",
-                               ScheduledTasksStateAsValue());
+  TRACE_EVENT_NESTABLE_ASYNC_INSTANT1("cc", "ScheduledTasksState",
+                                      TRACE_ID_LOCAL(this), "state",
+                                      ScheduledTasksStateAsValue());
   // TODO(vmpstr): Temporary check to debug crbug.com/642927.
   CHECK(tile_task_manager_);
   signals_.draw_tile_tasks_completed = true;
@@ -485,7 +487,7 @@ void TileManager::DidFinishRunningTileTasksRequiredForDraw() {
 
 void TileManager::DidFinishRunningAllTileTasks(bool has_pending_queries) {
   TRACE_EVENT0("cc", "TileManager::DidFinishRunningAllTileTasks");
-  TRACE_EVENT_ASYNC_END0("cc", "ScheduledTasks", this);
+  TRACE_EVENT_NESTABLE_ASYNC_END0("cc", "ScheduledTasks", TRACE_ID_LOCAL(this));
   DCHECK(resource_pool_);
   DCHECK(tile_task_manager_);
 
@@ -950,7 +952,8 @@ void TileManager::ScheduleTasks(PrioritizedWorkToSchedule work_to_schedule) {
   DCHECK(did_check_for_completed_tasks_since_last_schedule_tasks_);
 
   if (!has_scheduled_tile_tasks_) {
-    TRACE_EVENT_ASYNC_BEGIN0("cc", "ScheduledTasks", this);
+    TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("cc", "ScheduledTasks",
+                                      TRACE_ID_LOCAL(this));
   }
 
   // Cancel existing OnTaskSetFinished callbacks.
@@ -1115,8 +1118,9 @@ void TileManager::ScheduleTasks(PrioritizedWorkToSchedule work_to_schedule) {
 
   did_check_for_completed_tasks_since_last_schedule_tasks_ = false;
 
-  TRACE_EVENT_ASYNC_STEP_INTO1("cc", "ScheduledTasks", this, "running", "state",
-                               ScheduledTasksStateAsValue());
+  TRACE_EVENT_NESTABLE_ASYNC_INSTANT1("cc", "ScheduledTasksState",
+                                      TRACE_ID_LOCAL(this), "state",
+                                      ScheduledTasksStateAsValue());
 }
 
 scoped_refptr<TileTask> TileManager::CreateRasterTask(

cc/trees/layer_tree_host_impl.cc

@@ -178,12 +178,14 @@ viz::ResourceFormat TileRasterBufferFormat(
 
 void DidVisibilityChange(LayerTreeHostImpl* id, bool visible) {
   if (visible) {
-    TRACE_EVENT_ASYNC_BEGIN1("cc", "LayerTreeHostImpl::SetVisible", id,
-                             "LayerTreeHostImpl", id);
+    TRACE_EVENT_NESTABLE_ASYNC_BEGIN1("cc", "LayerTreeHostImpl::SetVisible",
+                                      TRACE_ID_LOCAL(id), "LayerTreeHostImpl",
+                                      id);
     return;
   }
 
-  TRACE_EVENT_ASYNC_END0("cc", "LayerTreeHostImpl::SetVisible", id);
+  TRACE_EVENT_NESTABLE_ASYNC_END0("cc", "LayerTreeHostImpl::SetVisible",
+                                  TRACE_ID_LOCAL(id));
 }
 
 enum ScrollThread { MAIN_THREAD, CC_THREAD };
@@ -2972,7 +2974,8 @@ void LayerTreeHostImpl::CreatePendingTree() {
   pending_tree_fully_painted_ = false;
 
   client_->OnCanDrawStateChanged(CanDraw());
-  TRACE_EVENT_ASYNC_BEGIN0("cc", "PendingTree:waiting", pending_tree_.get());
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("cc", "PendingTree:waiting",
+                                    TRACE_ID_LOCAL(pending_tree_.get()));
 
   DCHECK(!pending_tree_duration_timer_);
   pending_tree_duration_timer_.reset(new PendingTreeDurationHistogramTimer());
@@ -3009,7 +3012,8 @@ void LayerTreeHostImpl::PushScrollbarOpacitiesFromActiveToPending() {
 void LayerTreeHostImpl::ActivateSyncTree() {
   TRACE_EVENT0("cc,benchmark", "LayerTreeHostImpl::ActivateSyncTree()");
   if (pending_tree_) {
-    TRACE_EVENT_ASYNC_END0("cc", "PendingTree:waiting", pending_tree_.get());
+    TRACE_EVENT_NESTABLE_ASYNC_END0("cc", "PendingTree:waiting",
+                                    TRACE_ID_LOCAL(pending_tree_.get()));
     active_tree_->lifecycle().AdvanceTo(LayerTreeLifecycle::kBeginningSync);
 
     DCHECK(pending_tree_duration_timer_);

cc/trees/proxy_main.cc

@@ -446,9 +446,11 @@ void ProxyMain::SetDeferMainFrameUpdate(bool defer_main_frame_update) {
 
   defer_main_frame_update_ = defer_main_frame_update;
   if (defer_main_frame_update_) {
-    TRACE_EVENT_ASYNC_BEGIN0("cc", "ProxyMain::SetDeferMainFrameUpdate", this);
+    TRACE_EVENT_NESTABLE_ASYNC_BEGIN0(
+        "cc", "ProxyMain::SetDeferMainFrameUpdate", TRACE_ID_LOCAL(this));
   } else {
-    TRACE_EVENT_ASYNC_END0("cc", "ProxyMain::SetDeferMainFrameUpdate", this);
+    TRACE_EVENT_NESTABLE_ASYNC_END0("cc", "ProxyMain::SetDeferMainFrameUpdate",
+                                    TRACE_ID_LOCAL(this));
   }
 
   // Notify dependent systems that the deferral status has changed.
@@ -469,7 +471,8 @@ void ProxyMain::StartDeferringCommits(base::TimeDelta timeout) {
   if (defer_commits_)
     return;
 
-  TRACE_EVENT_ASYNC_BEGIN0("cc", "ProxyMain::SetDeferCommits", this);
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("cc", "ProxyMain::SetDeferCommits",
+                                    TRACE_ID_LOCAL(this));
 
   defer_commits_ = true;
   commits_restart_time_ = base::TimeTicks::Now() + timeout;
@@ -484,7 +487,8 @@ void ProxyMain::StopDeferringCommits(PaintHoldingCommitTrigger trigger) {
   defer_commits_ = false;
   UMA_HISTOGRAM_ENUMERATION("PaintHolding.CommitTrigger2", trigger);
   commits_restart_time_ = base::TimeTicks();
-  TRACE_EVENT_ASYNC_END0("cc", "ProxyMain::SetDeferCommits", this);
+  TRACE_EVENT_NESTABLE_ASYNC_END0("cc", "ProxyMain::SetDeferCommits",
+                                  TRACE_ID_LOCAL(this));
 
   // Notify depended systems that the deferral status has changed.
   layer_tree_host_->OnDeferCommitsChanged(defer_commits_);

cc/trees/single_thread_proxy.cc

@@ -268,11 +268,13 @@ void SingleThreadProxy::SetDeferMainFrameUpdate(bool defer_main_frame_update) {
     return;
 
   if (defer_main_frame_update) {
-    TRACE_EVENT_ASYNC_BEGIN0("cc", "SingleThreadProxy::SetDeferMainFrameUpdate",
-                             this);
+    TRACE_EVENT_NESTABLE_ASYNC_BEGIN0(
+        "cc", "SingleThreadProxy::SetDeferMainFrameUpdate",
+        TRACE_ID_LOCAL(this));
   } else {
-    TRACE_EVENT_ASYNC_END0("cc", "SingleThreadProxy::SetDeferMainFrameUpdate",
-                           this);
+    TRACE_EVENT_NESTABLE_ASYNC_END0(
+        "cc", "SingleThreadProxy::SetDeferMainFrameUpdate",
+        TRACE_ID_LOCAL(this));
   }
 
   defer_main_frame_update_ = defer_main_frame_update;
@@ -292,7 +294,8 @@ void SingleThreadProxy::StartDeferringCommits(base::TimeDelta timeout) {
   if (defer_commits_)
     return;
 
-  TRACE_EVENT_ASYNC_BEGIN0("cc", "SingleThreadProxy::SetDeferCommits", this);
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("cc", "SingleThreadProxy::SetDeferCommits",
+                                    TRACE_ID_LOCAL(this));
 
   defer_commits_ = true;
   commits_restart_time_ = base::TimeTicks::Now() + timeout;
@@ -308,7 +311,8 @@ void SingleThreadProxy::StopDeferringCommits(
   defer_commits_ = false;
   commits_restart_time_ = base::TimeTicks();
   UMA_HISTOGRAM_ENUMERATION("PaintHolding.CommitTrigger2", trigger);
-  TRACE_EVENT_ASYNC_END0("cc", "SingleThreadProxy::SetDeferCommits", this);
+  TRACE_EVENT_NESTABLE_ASYNC_END0("cc", "SingleThreadProxy::SetDeferCommits",
+                                  TRACE_ID_LOCAL(this));
 
   // Notify dependent systems that the deferral status has changed.
   layer_tree_host_->OnDeferCommitsChanged(defer_commits_);