content/browser/renderer_host/render_widget_host_latency_tracker.cc

   1 // Copyright 2014 The Chromium Authors. All rights reserved.
   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 "content/browser/renderer_host/render_widget_host_latency_tracker.h"
   6
   7 #include "base/logging.h"
   8 #include "base/metrics/histogram.h"
   9 #include "content/browser/renderer_host/render_widget_host_impl.h"
  10
  11 using blink::WebGestureEvent;
  12 using blink::WebInputEvent;
  13 using blink::WebMouseEvent;
  14 using blink::WebMouseWheelEvent;
  15 using blink::WebTouchEvent;
  16 using ui::LatencyInfo;
  17
  18 namespace content {
  19 namespace {
  20
  21 const uint32 kMaxInputCoordinates = LatencyInfo::kMaxInputCoordinates;
  22 const size_t kBrowserCompositeLatencyHistorySize = 60;
  23 const double kBrowserCompositeLatencyEstimationPercentile = 90.0;
  24 const double kBrowserCompositeLatencyEstimationSlack = 1.1;
  25
  26 void UpdateLatencyCoordinatesImpl(const blink::WebTouchEvent& touch,
  27                                   LatencyInfo* latency) {
  28   latency->input_coordinates_size =
  29       std::min(kMaxInputCoordinates, touch.touchesLength);
  30   for (uint32 i = 0; i < latency->input_coordinates_size; ++i) {
  31     latency->input_coordinates[i] = LatencyInfo::InputCoordinate(
  32         touch.touches[i].position.x, touch.touches[i].position.y);
  33   }
  34 }
  35
  36 void UpdateLatencyCoordinatesImpl(const WebGestureEvent& gesture,
  37                                   LatencyInfo* latency) {
  38   latency->input_coordinates_size = 1;
  39   latency->input_coordinates[0] =
  40       LatencyInfo::InputCoordinate(gesture.x, gesture.y);
  41 }
  42
  43 void UpdateLatencyCoordinatesImpl(const WebMouseEvent& mouse,
  44                                   LatencyInfo* latency) {
  45   latency->input_coordinates_size = 1;
  46   latency->input_coordinates[0] =
  47       LatencyInfo::InputCoordinate(mouse.x, mouse.y);
  48 }
  49
  50 void UpdateLatencyCoordinatesImpl(const WebMouseWheelEvent& wheel,
  51                                   LatencyInfo* latency) {
  52   latency->input_coordinates_size = 1;
  53   latency->input_coordinates[0] =
  54       LatencyInfo::InputCoordinate(wheel.x, wheel.y);
  55 }
  56
  57 void UpdateLatencyCoordinates(const WebInputEvent& event,
  58                               float device_scale_factor,
  59                               LatencyInfo* latency) {
  60   if (WebInputEvent::isMouseEventType(event.type)) {
  61     UpdateLatencyCoordinatesImpl(static_cast<const WebMouseEvent&>(event),
  62                                  latency);
  63   } else if (WebInputEvent::isGestureEventType(event.type)) {
  64     UpdateLatencyCoordinatesImpl(static_cast<const WebGestureEvent&>(event),
  65                                  latency);
  66   } else if (WebInputEvent::isTouchEventType(event.type)) {
  67     UpdateLatencyCoordinatesImpl(static_cast<const WebTouchEvent&>(event),
  68                                  latency);
  69   } else if (event.type == WebInputEvent::MouseWheel) {
  70     UpdateLatencyCoordinatesImpl(static_cast<const WebMouseWheelEvent&>(event),
  71                                  latency);
  72   }
  73   if (device_scale_factor == 1)
  74     return;
  75   for (uint32 i = 0; i < latency->input_coordinates_size; ++i) {
  76     latency->input_coordinates[i].x *= device_scale_factor;
  77     latency->input_coordinates[i].y *= device_scale_factor;
  78   }
  79 }
  80
  81 void ComputeInputLatencyHistograms(WebInputEvent::Type type,
  82                                    int64 latency_component_id,
  83                                    const LatencyInfo& latency) {
  84   LatencyInfo::LatencyComponent rwh_component;
  85   if (!latency.FindLatency(ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT,
  86                            latency_component_id, &rwh_component)) {
  87     return;
  88   }
  89   DCHECK_EQ(rwh_component.event_count, 1u);
  90
  91   LatencyInfo::LatencyComponent ui_component;
  92   if (latency.FindLatency(ui::INPUT_EVENT_LATENCY_UI_COMPONENT, 0,
  93                           &ui_component)) {
  94     DCHECK_EQ(ui_component.event_count, 1u);
  95     base::TimeDelta ui_delta =
  96         rwh_component.event_time - ui_component.event_time;
  97     switch (type) {
  98       case blink::WebInputEvent::MouseWheel:
  99         UMA_HISTOGRAM_CUSTOM_COUNTS(
 100             "Event.Latency.Browser.WheelUI",
 101             ui_delta.InMicroseconds(), 1, 20000, 100);
 102         break;
 103       case blink::WebInputEvent::TouchTypeFirst:
 104         UMA_HISTOGRAM_CUSTOM_COUNTS(
 105             "Event.Latency.Browser.TouchUI",
 106             ui_delta.InMicroseconds(), 1, 20000, 100);
 107         break;
 108       default:
 109         NOTREACHED();
 110         break;
 111     }
 112   }
 113
 114   LatencyInfo::LatencyComponent acked_component;
 115   if (latency.FindLatency(ui::INPUT_EVENT_LATENCY_ACK_RWH_COMPONENT, 0,
 116                           &acked_component)) {
 117     DCHECK_EQ(acked_component.event_count, 1u);
 118     base::TimeDelta acked_delta =
 119         acked_component.event_time - rwh_component.event_time;
 120     switch (type) {
 121       case blink::WebInputEvent::MouseWheel:
 122         UMA_HISTOGRAM_CUSTOM_COUNTS(
 123             "Event.Latency.Browser.WheelAcked",
 124             acked_delta.InMicroseconds(), 1, 1000000, 100);
 125         break;
 126       case blink::WebInputEvent::TouchTypeFirst:
 127         UMA_HISTOGRAM_CUSTOM_COUNTS(
 128             "Event.Latency.Browser.TouchAcked",
 129             acked_delta.InMicroseconds(), 1, 1000000, 100);
 130         break;
 131       default:
 132         NOTREACHED();
 133         break;
 134     }
 135   }
 136 }
 137
 138 // Long scroll latency component that is mostly under 200ms.
 139 #define UMA_HISTOGRAM_SCROLL_LATENCY_LONG(name, start, end)        \
 140   UMA_HISTOGRAM_CUSTOM_COUNTS(                                     \
 141     name,                                                          \
 142     (end.event_time - start.event_time).InMicroseconds(),          \
 143     1000, 200000, 50)
 144
 145 // Short scroll latency component that is mostly under 50ms.
 146 #define UMA_HISTOGRAM_SCROLL_LATENCY_SHORT(name, start, end)       \
 147   UMA_HISTOGRAM_CUSTOM_COUNTS(                                     \
 148     name,                                                          \
 149     (end.event_time - start.event_time).InMicroseconds(),          \
 150     1, 50000, 50)
 151
 152 void ComputeScrollLatencyHistograms(
 153     const LatencyInfo::LatencyComponent& gpu_swap_component,
 154     int64 latency_component_id,
 155     const LatencyInfo& latency) {
 156   DCHECK(!gpu_swap_component.event_time.is_null());
 157   LatencyInfo::LatencyComponent first_original_component, original_component;
 158   if (latency.FindLatency(
 159           ui::INPUT_EVENT_LATENCY_FIRST_SCROLL_UPDATE_ORIGINAL_COMPONENT,
 160           latency_component_id, &first_original_component)) {
 161     // This UMA metric tracks the time between the final frame swap for the
 162     // first scroll event in a sequence and the original timestamp of that
 163     // scroll event's underlying touch event.
 164     for (size_t i = 0; i < first_original_component.event_count; i++) {
 165       UMA_HISTOGRAM_CUSTOM_COUNTS(
 166           "Event.Latency.TouchToFirstScrollUpdateSwap",
 167           (gpu_swap_component.event_time - first_original_component.event_time)
 168               .InMicroseconds(),
 169           1, 1000000, 100);
 170     }
 171     original_component = first_original_component;
 172   } else if (!latency.FindLatency(
 173                  ui::INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT,
 174                  latency_component_id, &original_component)) {
 175     return;
 176   }
 177
 178   // This UMA metric tracks the time from when the original touch event is
 179   // created (averaged if there are multiple) to when the scroll gesture
 180   // results in final frame swap.
 181   for (size_t i = 0; i < original_component.event_count; i++) {
 182     UMA_HISTOGRAM_CUSTOM_COUNTS(
 183         "Event.Latency.TouchToScrollUpdateSwap",
 184         (gpu_swap_component.event_time - original_component.event_time)
 185             .InMicroseconds(),
 186         1, 1000000, 100);
 187   }
 188
 189   // TODO(miletus): Add validation for making sure the following components
 190   // are present and their event times are legit.
 191   LatencyInfo::LatencyComponent rendering_scheduled_component;
 192   bool rendering_scheduled_on_main = latency.FindLatency(
 193       ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_MAIN_COMPONENT,
 194       0, &rendering_scheduled_component);
 195
 196   if (!rendering_scheduled_on_main) {
 197     if (!latency.FindLatency(
 198             ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_IMPL_COMPONENT,
 199             0, &rendering_scheduled_component))
 200       return;
 201   }
 202
 203   if (rendering_scheduled_on_main) {
 204     UMA_HISTOGRAM_SCROLL_LATENCY_LONG(
 205         "Event.Latency.ScrollUpdate.TouchToHandled_Main",
 206         original_component, rendering_scheduled_component);
 207   } else {
 208     UMA_HISTOGRAM_SCROLL_LATENCY_LONG(
 209         "Event.Latency.ScrollUpdate.TouchToHandled_Impl",
 210         original_component, rendering_scheduled_component);
 211   }
 212
 213   LatencyInfo::LatencyComponent renderer_swap_component;
 214   if (!latency.FindLatency(ui::INPUT_EVENT_LATENCY_RENDERER_SWAP_COMPONENT,
 215                            0, &renderer_swap_component))
 216     return;
 217
 218   if (rendering_scheduled_on_main) {
 219     UMA_HISTOGRAM_SCROLL_LATENCY_LONG(
 220         "Event.Latency.ScrollUpdate.HandledToRendererSwap_Main",
 221         rendering_scheduled_component, renderer_swap_component);
 222   } else {
 223     UMA_HISTOGRAM_SCROLL_LATENCY_LONG(
 224         "Event.Latency.ScrollUpdate.HandledToRendererSwap_Impl",
 225         rendering_scheduled_component, renderer_swap_component);
 226   }
 227
 228   LatencyInfo::LatencyComponent browser_received_swap_component;
 229   if (!latency.FindLatency(
 230           ui::INPUT_EVENT_BROWSER_RECEIVED_RENDERER_SWAP_COMPONENT,
 231           0, &browser_received_swap_component))
 232     return;
 233
 234   UMA_HISTOGRAM_SCROLL_LATENCY_SHORT(
 235       "Event.Latency.ScrollUpdate.RendererSwapToBrowserNotified",
 236       renderer_swap_component, browser_received_swap_component);
 237
 238   UMA_HISTOGRAM_SCROLL_LATENCY_LONG(
 239       "Event.Latency.ScrollUpdate.BrowserNotifiedToBeforeGpuSwap",
 240       browser_received_swap_component, gpu_swap_component);
 241
 242   LatencyInfo::LatencyComponent gpu_swap_ack_component;
 243   if (!latency.FindLatency(
 244           ui::INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT, 0,
 245           &gpu_swap_ack_component))
 246     return;
 247
 248   UMA_HISTOGRAM_SCROLL_LATENCY_SHORT("Event.Latency.ScrollUpdate.GpuSwap",
 249                                      gpu_swap_component,
 250                                      gpu_swap_ack_component);
 251 }
 252
 253 // LatencyComponents generated in the renderer must have component IDs
 254 // provided to them by the browser process. This function adds the correct
 255 // component ID where necessary.
 256 void AddLatencyInfoComponentIds(LatencyInfo* latency,
 257                                 int64 latency_component_id) {
 258   LatencyInfo::LatencyMap new_components;
 259   auto lc = latency->latency_components.begin();
 260   while (lc != latency->latency_components.end()) {
 261     ui::LatencyComponentType component_type = lc->first.first;
 262     if (component_type == ui::WINDOW_SNAPSHOT_FRAME_NUMBER_COMPONENT) {
 263       // Generate a new component entry with the correct component ID
 264       auto key = std::make_pair(component_type, latency_component_id);
 265       new_components[key] = lc->second;
 266
 267       // Remove the old entry
 268       latency->latency_components.erase(lc++);
 269     } else {
 270       ++lc;
 271     }
 272   }
 273
 274   // Add newly generated components into the latency info
 275   for (lc = new_components.begin(); lc != new_components.end(); ++lc) {
 276     latency->latency_components[lc->first] = lc->second;
 277   }
 278 }
 279
 280 }  // namespace
 281
 282 RenderWidgetHostLatencyTracker::RenderWidgetHostLatencyTracker()
 283     : last_event_id_(0),
 284       latency_component_id_(0),
 285       device_scale_factor_(1),
 286       has_seent_first_gesture_scroll_update_(false),
 287       browser_composite_latency_history_(kBrowserCompositeLatencyHistorySize) {
 288 }
 289
 290 RenderWidgetHostLatencyTracker::~RenderWidgetHostLatencyTracker() {
 291 }
 292
 293 void RenderWidgetHostLatencyTracker::Initialize(int routing_id,
 294                                                 int process_id) {
 295   DCHECK_EQ(0, last_event_id_);
 296   DCHECK_EQ(0, latency_component_id_);
 297   last_event_id_ = static_cast<int64>(process_id) << 32;
 298   latency_component_id_ = routing_id | last_event_id_;
 299 }
 300
 301 void RenderWidgetHostLatencyTracker::OnInputEvent(
 302     const blink::WebInputEvent& event,
 303     LatencyInfo* latency) {
 304   DCHECK(latency);
 305   if (latency->FindLatency(ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT,
 306                            latency_component_id_, NULL)) {
 307     return;
 308   }
 309
 310   latency->AddLatencyNumber(ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT,
 311                             latency_component_id_, ++last_event_id_);
 312   latency->TraceEventType(WebInputEventTraits::GetName(event.type));
 313   UpdateLatencyCoordinates(event, device_scale_factor_, latency);
 314
 315   if (event.type == blink::WebInputEvent::GestureScrollBegin) {
 316     has_seent_first_gesture_scroll_update_ = false;
 317   } else if (event.type == blink::WebInputEvent::GestureScrollUpdate) {
 318     // Make a copy of the INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT with a
 319     // different name INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT.
 320     // So we can track the latency specifically for scroll update events.
 321     LatencyInfo::LatencyComponent original_component;
 322     if (latency->FindLatency(ui::INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT, 0,
 323                              &original_component)) {
 324       latency->AddLatencyNumberWithTimestamp(
 325           has_seent_first_gesture_scroll_update_
 326               ? ui::INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT
 327               : ui::INPUT_EVENT_LATENCY_FIRST_SCROLL_UPDATE_ORIGINAL_COMPONENT,
 328           latency_component_id_, original_component.sequence_number,
 329           original_component.event_time, original_component.event_count);
 330     }
 331
 332     has_seent_first_gesture_scroll_update_ = true;
 333   }
 334 }
 335
 336 void RenderWidgetHostLatencyTracker::OnInputEventAck(
 337     const blink::WebInputEvent& event,
 338     LatencyInfo* latency) {
 339   DCHECK(latency);
 340
 341   // Latency ends when it is acked but does not cause render scheduling.
 342   bool rendering_scheduled = latency->FindLatency(
 343       ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_MAIN_COMPONENT, 0, nullptr);
 344   rendering_scheduled |= latency->FindLatency(
 345       ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_IMPL_COMPONENT, 0, nullptr);
 346
 347   if (WebInputEvent::isGestureEventType(event.type)) {
 348     if (!rendering_scheduled) {
 349       latency->AddLatencyNumber(
 350           ui::INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT, 0, 0);
 351       // TODO(jdduke): Consider exposing histograms for gesture event types.
 352     }
 353     return;
 354   }
 355
 356   if (WebInputEvent::isTouchEventType(event.type)) {
 357     latency->AddLatencyNumber(ui::INPUT_EVENT_LATENCY_ACK_RWH_COMPONENT, 0, 0);
 358     if (!rendering_scheduled) {
 359       latency->AddLatencyNumber(
 360           ui::INPUT_EVENT_LATENCY_TERMINATED_TOUCH_COMPONENT, 0, 0);
 361     }
 362     ComputeInputLatencyHistograms(WebInputEvent::TouchTypeFirst,
 363                                   latency_component_id_, *latency);
 364     return;
 365   }
 366
 367   if (event.type == WebInputEvent::MouseWheel) {
 368     latency->AddLatencyNumber(ui::INPUT_EVENT_LATENCY_ACK_RWH_COMPONENT, 0, 0);
 369     if (!rendering_scheduled) {
 370       latency->AddLatencyNumber(
 371           ui::INPUT_EVENT_LATENCY_TERMINATED_MOUSE_COMPONENT, 0, 0);
 372     }
 373     ComputeInputLatencyHistograms(WebInputEvent::MouseWheel,
 374                                   latency_component_id_, *latency);
 375     return;
 376   }
 377
 378   // TODO(jdduke): Determine if mouse and keyboard events are worth hooking
 379   // into LatencyInfo.
 380 }
 381
 382 void RenderWidgetHostLatencyTracker::OnSwapCompositorFrame(
 383     std::vector<LatencyInfo>* latencies) {
 384   DCHECK(latencies);
 385   for (LatencyInfo& latency : *latencies) {
 386     AddLatencyInfoComponentIds(&latency, latency_component_id_);
 387     latency.AddLatencyNumber(
 388         ui::INPUT_EVENT_BROWSER_RECEIVED_RENDERER_SWAP_COMPONENT, 0, 0);
 389   }
 390 }
 391
 392 void RenderWidgetHostLatencyTracker::OnFrameSwapped(
 393     const LatencyInfo& latency) {
 394   LatencyInfo::LatencyComponent gpu_swap_component;
 395   if (!latency.FindLatency(ui::INPUT_EVENT_GPU_SWAP_BUFFER_COMPONENT, 0,
 396                            &gpu_swap_component)) {
 397     return;
 398   }
 399
 400   LatencyInfo::LatencyComponent tab_switch_component;
 401   if (latency.FindLatency(ui::TAB_SHOW_COMPONENT, latency_component_id_,
 402                           &tab_switch_component)) {
 403     base::TimeDelta delta =
 404         gpu_swap_component.event_time - tab_switch_component.event_time;
 405     for (size_t i = 0; i < tab_switch_component.event_count; i++) {
 406       UMA_HISTOGRAM_TIMES("MPArch.RWH_TabSwitchPaintDuration", delta);
 407     }
 408   }
 409
 410   if (!latency.FindLatency(ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT,
 411                            latency_component_id_, nullptr)) {
 412     return;
 413   }
 414
 415   ComputeScrollLatencyHistograms(gpu_swap_component, latency_component_id_,
 416                                  latency);
 417
 418   LatencyInfo::LatencyComponent browser_swap_component;
 419   if (latency.FindLatency(
 420           ui::INPUT_EVENT_BROWSER_RECEIVED_RENDERER_SWAP_COMPONENT, 0,
 421           &browser_swap_component)) {
 422     base::TimeDelta delta =
 423         gpu_swap_component.event_time - browser_swap_component.event_time;
 424     browser_composite_latency_history_.InsertSample(delta);
 425   }
 426 }
 427
 428 base::TimeDelta
 429 RenderWidgetHostLatencyTracker::GetEstimatedBrowserCompositeTime() const {
 430   // TODO(brianderson): Remove lower bound on estimate once we're sure it won't
 431   // cause regressions.
 432   return std::max(
 433       browser_composite_latency_history_.Percentile(
 434           kBrowserCompositeLatencyEstimationPercentile) *
 435           kBrowserCompositeLatencyEstimationSlack,
 436       base::TimeDelta::FromMicroseconds(
 437           (1.0f * base::Time::kMicrosecondsPerSecond) / (3.0f * 60)));
 438 }
 439
 440 }  // namespace content