cc/metrics/event_latency_tracing_recorder.cc

   1 // Copyright 2022 The Chromium Authors
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "cc/metrics/event_latency_tracing_recorder.h"
   6
   7 #include "base/notreached.h"
   8 #include "base/ranges/algorithm.h"
   9 #include "base/time/time.h"
  10 #include "base/trace_event/trace_id_helper.h"
  11 #include "base/trace_event/typed_macros.h"
  12 #include "base/tracing/protos/chrome_track_event.pbzero.h"
  13 #include "cc/metrics/event_metrics.h"
  14 #include "third_party/perfetto/include/perfetto/tracing/track.h"
  15
  16 namespace cc {
  17 namespace {
  18
  19 constexpr char kTracingCategory[] = "cc,benchmark,input";
  20 constexpr base::TimeDelta high_latency_threshold = base::Milliseconds(90);
  21
  22 constexpr perfetto::protos::pbzero::EventLatency::EventType ToProtoEnum(
  23     EventMetrics::EventType event_type) {
  24 #define CASE(event_type, proto_event_type)  \
  25   case EventMetrics::EventType::event_type: \
  26     return perfetto::protos::pbzero::EventLatency::proto_event_type
  27   switch (event_type) {
  28     CASE(kMousePressed, MOUSE_PRESSED);
  29     CASE(kMouseReleased, MOUSE_RELEASED);
  30     CASE(kMouseWheel, MOUSE_WHEEL);
  31     CASE(kKeyPressed, KEY_PRESSED);
  32     CASE(kKeyReleased, KEY_RELEASED);
  33     CASE(kTouchPressed, TOUCH_PRESSED);
  34     CASE(kTouchReleased, TOUCH_RELEASED);
  35     CASE(kTouchMoved, TOUCH_MOVED);
  36     CASE(kGestureScrollBegin, GESTURE_SCROLL_BEGIN);
  37     CASE(kGestureScrollUpdate, GESTURE_SCROLL_UPDATE);
  38     CASE(kGestureScrollEnd, GESTURE_SCROLL_END);
  39     CASE(kGestureDoubleTap, GESTURE_DOUBLE_TAP);
  40     CASE(kGestureLongPress, GESTURE_LONG_PRESS);
  41     CASE(kGestureLongTap, GESTURE_LONG_TAP);
  42     CASE(kGestureShowPress, GESTURE_SHOW_PRESS);
  43     CASE(kGestureTap, GESTURE_TAP);
  44     CASE(kGestureTapCancel, GESTURE_TAP_CANCEL);
  45     CASE(kGestureTapDown, GESTURE_TAP_DOWN);
  46     CASE(kGestureTapUnconfirmed, GESTURE_TAP_UNCONFIRMED);
  47     CASE(kGestureTwoFingerTap, GESTURE_TWO_FINGER_TAP);
  48     CASE(kFirstGestureScrollUpdate, FIRST_GESTURE_SCROLL_UPDATE);
  49     CASE(kMouseDragged, MOUSE_DRAGGED);
  50     CASE(kGesturePinchBegin, GESTURE_PINCH_BEGIN);
  51     CASE(kGesturePinchEnd, GESTURE_PINCH_END);
  52     CASE(kGesturePinchUpdate, GESTURE_PINCH_UPDATE);
  53     CASE(kInertialGestureScrollUpdate, INERTIAL_GESTURE_SCROLL_UPDATE);
  54   }
  55 }
  56
  57 }  // namespace
  58
  59 // static
  60 const char* EventLatencyTracingRecorder::GetDispatchBreakdownName(
  61     EventMetrics::DispatchStage start_stage,
  62     EventMetrics::DispatchStage end_stage) {
  63   switch (start_stage) {
  64     case EventMetrics::DispatchStage::kGenerated:
  65       switch (end_stage) {
  66         case EventMetrics::DispatchStage::kArrivedInBrowserMain:
  67           return "GenerationToBrowserMain";
  68         case EventMetrics::DispatchStage::kArrivedInRendererCompositor:
  69           return "GenerationToRendererCompositor";
  70         default:
  71           NOTREACHED();
  72           return "";
  73       }
  74     case EventMetrics::DispatchStage::kArrivedInBrowserMain:
  75       DCHECK_EQ(end_stage,
  76                 EventMetrics::DispatchStage::kArrivedInRendererCompositor);
  77       return "BrowserMainToRendererCompositor";
  78     case EventMetrics::DispatchStage::kArrivedInRendererCompositor:
  79       switch (end_stage) {
  80         case EventMetrics::DispatchStage::kRendererCompositorStarted:
  81           return "RendererCompositorQueueingDelay";
  82         case EventMetrics::DispatchStage::kRendererMainStarted:
  83           return "RendererCompositorToMain";
  84         default:
  85           NOTREACHED();
  86           return "";
  87       }
  88     case EventMetrics::DispatchStage::kRendererCompositorStarted:
  89       DCHECK_EQ(end_stage,
  90                 EventMetrics::DispatchStage::kRendererCompositorFinished);
  91       return "RendererCompositorProcessing";
  92     case EventMetrics::DispatchStage::kRendererCompositorFinished:
  93       DCHECK_EQ(end_stage, EventMetrics::DispatchStage::kRendererMainStarted);
  94       return "RendererCompositorToMain";
  95     case EventMetrics::DispatchStage::kRendererMainStarted:
  96       DCHECK_EQ(end_stage, EventMetrics::DispatchStage::kRendererMainFinished);
  97       return "RendererMainProcessing";
  98     case EventMetrics::DispatchStage::kRendererMainFinished:
  99       NOTREACHED();
 100       return "";
 101   }
 102 }
 103
 104 // static
 105 const char* EventLatencyTracingRecorder::GetDispatchToCompositorBreakdownName(
 106     EventMetrics::DispatchStage dispatch_stage,
 107     CompositorFrameReporter::StageType compositor_stage) {
 108   switch (dispatch_stage) {
 109     case EventMetrics::DispatchStage::kRendererCompositorFinished:
 110       switch (compositor_stage) {
 111         case CompositorFrameReporter::StageType::
 112             kBeginImplFrameToSendBeginMainFrame:
 113           return "RendererCompositorFinishedToBeginImplFrame";
 114         case CompositorFrameReporter::StageType::kSendBeginMainFrameToCommit:
 115           return "RendererCompositorFinishedToSendBeginMainFrame";
 116         case CompositorFrameReporter::StageType::kCommit:
 117           return "RendererCompositorFinishedToCommit";
 118         case CompositorFrameReporter::StageType::kEndCommitToActivation:
 119           return "RendererCompositorFinishedToEndCommit";
 120         case CompositorFrameReporter::StageType::kActivation:
 121           return "RendererCompositorFinishedToActivation";
 122         case CompositorFrameReporter::StageType::
 123             kEndActivateToSubmitCompositorFrame:
 124           return "RendererCompositorFinishedToEndActivate";
 125         case CompositorFrameReporter::StageType::
 126             kSubmitCompositorFrameToPresentationCompositorFrame:
 127           return "RendererCompositorFinishedToSubmitCompositorFrame";
 128         default:
 129           // TODO(crbug.com/1366253): Logs are added to debug NOTREACHED() begin
 130           // hit in crbug/1366253. Remove after investigation is finished.
 131           NOTREACHED() << "Invalid CC stage after compositor thread: "
 132                        << static_cast<int>(compositor_stage);
 133           return "";
 134       }
 135     case EventMetrics::DispatchStage::kRendererMainFinished:
 136       switch (compositor_stage) {
 137         case CompositorFrameReporter::StageType::
 138             kBeginImplFrameToSendBeginMainFrame:
 139           return "RendererMainFinishedToBeginImplFrame";
 140         case CompositorFrameReporter::StageType::kSendBeginMainFrameToCommit:
 141           return "RendererMainFinishedToSendBeginMainFrame";
 142         case CompositorFrameReporter::StageType::kCommit:
 143           return "RendererMainFinishedToCommit";
 144         case CompositorFrameReporter::StageType::kEndCommitToActivation:
 145           return "RendererMainFinishedToEndCommit";
 146         case CompositorFrameReporter::StageType::kActivation:
 147           return "RendererMainFinishedToActivation";
 148         case CompositorFrameReporter::StageType::
 149             kEndActivateToSubmitCompositorFrame:
 150           return "RendererMainFinishedToEndActivate";
 151         case CompositorFrameReporter::StageType::
 152             kSubmitCompositorFrameToPresentationCompositorFrame:
 153           return "RendererMainFinishedToSubmitCompositorFrame";
 154         default:
 155           // TODO(crbug.com/1366253): Logs are added to debug NOTREACHED() begin
 156           // hit in crbug/1366253. Remove after investigation is finished.
 157           NOTREACHED() << "Invalid CC stage after main thread: "
 158                        << static_cast<int>(compositor_stage);
 159           return "";
 160       }
 161     default:
 162       NOTREACHED();
 163       return "";
 164   }
 165 }
 166
 167 // static
 168 const char* EventLatencyTracingRecorder::GetDispatchToTerminationBreakdownName(
 169     EventMetrics::DispatchStage dispatch_stage) {
 170   switch (dispatch_stage) {
 171     case EventMetrics::DispatchStage::kArrivedInRendererCompositor:
 172       return "ArrivedInRendererCompositorToTermination";
 173     case EventMetrics::DispatchStage::kRendererCompositorStarted:
 174       return "RendererCompositorStartedToTermination";
 175     case EventMetrics::DispatchStage::kRendererCompositorFinished:
 176       return "RendererCompositorFinishedToTermination";
 177     case EventMetrics::DispatchStage::kRendererMainStarted:
 178       return "RendererMainStartedToTermination";
 179     case EventMetrics::DispatchStage::kRendererMainFinished:
 180       return "RendererMainFinishedToTermination";
 181     default:
 182       NOTREACHED();
 183       return "";
 184   }
 185 }
 186
 187 // static
 188 void EventLatencyTracingRecorder::RecordEventLatencyTraceEvent(
 189     EventMetrics* event_metrics,
 190     base::TimeTicks termination_time,
 191     const std::vector<CompositorFrameReporter::StageData>* stage_history,
 192     const CompositorFrameReporter::ProcessedVizBreakdown* viz_breakdown) {
 193   DCHECK(event_metrics);
 194   DCHECK(event_metrics->should_record_tracing());
 195
 196   const base::TimeTicks generated_timestamp =
 197       event_metrics->GetDispatchStageTimestamp(
 198           EventMetrics::DispatchStage::kGenerated);
 199
 200   const auto trace_track =
 201       perfetto::Track(base::trace_event::GetNextGlobalTraceId());
 202   TRACE_EVENT_BEGIN(
 203       kTracingCategory, "EventLatency", trace_track, generated_timestamp,
 204       [&](perfetto::EventContext context) {
 205         auto* event =
 206             context.event<perfetto::protos::pbzero::ChromeTrackEvent>();
 207         auto* event_latency = event->set_event_latency();
 208         event_latency->set_event_type(ToProtoEnum(event_metrics->type()));
 209         bool has_high_latency =
 210             (termination_time - generated_timestamp) > high_latency_threshold;
 211         event_latency->set_has_high_latency(has_high_latency);
 212         for (auto stage : event_metrics->GetHighLatencyStages()) {
 213           // TODO(crbug.com/1334827): Consider changing the high_latency_stage
 214           // type from a string to enum type in chrome_track_event.proto,
 215           // similar to event_type.
 216           event_latency->add_high_latency_stage(stage);
 217         }
 218       });
 219
 220   // Event dispatch stages.
 221   EventMetrics::DispatchStage dispatch_stage =
 222       EventMetrics::DispatchStage::kGenerated;
 223   base::TimeTicks dispatch_timestamp =
 224       event_metrics->GetDispatchStageTimestamp(dispatch_stage);
 225   while (dispatch_stage != EventMetrics::DispatchStage::kMaxValue) {
 226     DCHECK(!dispatch_timestamp.is_null());
 227
 228     // Find the end dispatch stage.
 229     auto end_stage = static_cast<EventMetrics::DispatchStage>(
 230         static_cast<int>(dispatch_stage) + 1);
 231     base::TimeTicks end_timestamp =
 232         event_metrics->GetDispatchStageTimestamp(end_stage);
 233     while (end_timestamp.is_null() &&
 234            end_stage != EventMetrics::DispatchStage::kMaxValue) {
 235       end_stage = static_cast<EventMetrics::DispatchStage>(
 236           static_cast<int>(end_stage) + 1);
 237       end_timestamp = event_metrics->GetDispatchStageTimestamp(end_stage);
 238     }
 239     if (end_timestamp.is_null())
 240       break;
 241
 242     const char* breakdown_name =
 243         GetDispatchBreakdownName(dispatch_stage, end_stage);
 244     TRACE_EVENT_BEGIN(kTracingCategory, perfetto::StaticString{breakdown_name},
 245                       trace_track, dispatch_timestamp);
 246     TRACE_EVENT_END(kTracingCategory, trace_track, end_timestamp);
 247
 248     dispatch_stage = end_stage;
 249     dispatch_timestamp = end_timestamp;
 250   }
 251   if (stage_history) {
 252     DCHECK(viz_breakdown);
 253     // Find the first compositor stage that starts at the same time or after the
 254     // end of the final event dispatch stage.
 255     auto stage_it = base::ranges::lower_bound(
 256         *stage_history, dispatch_timestamp, {},
 257         &CompositorFrameReporter::StageData::start_time);
 258     // TODO(crbug.com/1330903): Ideally, at least the start time of
 259     // SubmitCompositorFrameToPresentationCompositorFrame stage should be
 260     // greater than or equal to the final event dispatch timestamp, but
 261     // apparently, this is not always the case (see crbug.com/1330903). Skip
 262     // recording compositor stages for now until we investigate the issue.
 263     if (stage_it != stage_history->end()) {
 264       DCHECK(dispatch_stage ==
 265                  EventMetrics::DispatchStage::kRendererCompositorFinished ||
 266              dispatch_stage ==
 267                  EventMetrics::DispatchStage::kRendererMainFinished);
 268
 269       // Record dispatch-to-compositor stage only if it has non-zero duration.
 270       if (dispatch_timestamp < stage_it->start_time) {
 271         const char* d2c_breakdown_name = GetDispatchToCompositorBreakdownName(
 272             dispatch_stage, stage_it->stage_type);
 273         TRACE_EVENT_BEGIN(kTracingCategory,
 274                           perfetto::StaticString{d2c_breakdown_name},
 275                           trace_track, dispatch_timestamp);
 276         TRACE_EVENT_END(kTracingCategory, trace_track, stage_it->start_time);
 277       }
 278
 279       // Compositor stages.
 280       for (; stage_it != stage_history->end(); ++stage_it) {
 281         if (stage_it->start_time >= termination_time)
 282           break;
 283         DCHECK_GE(stage_it->end_time, stage_it->start_time);
 284         if (stage_it->start_time == stage_it->end_time)
 285           continue;
 286         const char* stage_name =
 287             CompositorFrameReporter::GetStageName(stage_it->stage_type);
 288
 289         TRACE_EVENT_BEGIN(kTracingCategory, perfetto::StaticString{stage_name},
 290                           trace_track, stage_it->start_time);
 291
 292         if (stage_it->stage_type ==
 293             CompositorFrameReporter::StageType::
 294                 kSubmitCompositorFrameToPresentationCompositorFrame) {
 295           DCHECK(viz_breakdown);
 296           for (auto it = viz_breakdown->CreateIterator(true); it.IsValid();
 297                it.Advance()) {
 298             base::TimeTicks start_time = it.GetStartTime();
 299             base::TimeTicks end_time = it.GetEndTime();
 300             if (start_time >= end_time)
 301               continue;
 302             const char* breakdown_name =
 303                 CompositorFrameReporter::GetVizBreakdownName(it.GetBreakdown());
 304             TRACE_EVENT_BEGIN(kTracingCategory,
 305                               perfetto::StaticString{breakdown_name},
 306                               trace_track, start_time);
 307             TRACE_EVENT_END(kTracingCategory, trace_track, end_time);
 308           }
 309         }
 310
 311         TRACE_EVENT_END(kTracingCategory, trace_track, stage_it->end_time);
 312       }
 313     }
 314   } else {
 315     DCHECK(!viz_breakdown);
 316     const char* d2t_breakdown_name =
 317         GetDispatchToTerminationBreakdownName(dispatch_stage);
 318     TRACE_EVENT_BEGIN(kTracingCategory,
 319                       perfetto::StaticString{d2t_breakdown_name}, trace_track,
 320                       dispatch_timestamp);
 321     TRACE_EVENT_END(kTracingCategory, trace_track, termination_time);
 322   }
 323   TRACE_EVENT_END(kTracingCategory, trace_track, termination_time);
 324
 325   event_metrics->tracing_recorded();
 326 }
 327
 328 }  // namespace cc