content/browser/renderer_host/input/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/input/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 // Touch to scroll latency that is mostly under 1 second.
 139 #define UMA_HISTOGRAM_TOUCH_TO_SCROLL_LATENCY(name, start, end)               \
 140   UMA_HISTOGRAM_CUSTOM_COUNTS(                                                \
 141       name, (end.event_time - start.event_time).InMicroseconds(), 1, 1000000, \
 142       100)
 143
 144 // Long scroll latency component that is mostly under 200ms.
 145 #define UMA_HISTOGRAM_SCROLL_LATENCY_LONG(name, start, end)        \
 146   UMA_HISTOGRAM_CUSTOM_COUNTS(                                     \
 147     name,                                                          \
 148     (end.event_time - start.event_time).InMicroseconds(),          \
 149     1000, 200000, 50)
 150
 151 // Short scroll latency component that is mostly under 50ms.
 152 #define UMA_HISTOGRAM_SCROLL_LATENCY_SHORT(name, start, end)       \
 153   UMA_HISTOGRAM_CUSTOM_COUNTS(                                     \
 154     name,                                                          \
 155     (end.event_time - start.event_time).InMicroseconds(),          \
 156     1, 50000, 50)
 157
 158 void ComputeScrollLatencyHistograms(
 159     const LatencyInfo::LatencyComponent& gpu_swap_begin_component,
 160     const LatencyInfo::LatencyComponent& gpu_swap_end_component,
 161     int64 latency_component_id,
 162     const LatencyInfo& latency) {
 163   DCHECK(!gpu_swap_begin_component.event_time.is_null());
 164   DCHECK(!gpu_swap_end_component.event_time.is_null());
 165   LatencyInfo::LatencyComponent first_original_component, original_component;
 166   if (latency.FindLatency(
 167           ui::INPUT_EVENT_LATENCY_FIRST_SCROLL_UPDATE_ORIGINAL_COMPONENT,
 168           latency_component_id, &first_original_component)) {
 169     // This UMA metric tracks the time between the final frame swap for the
 170     // first scroll event in a sequence and the original timestamp of that
 171     // scroll event's underlying touch event.
 172     for (size_t i = 0; i < first_original_component.event_count; i++) {
 173       UMA_HISTOGRAM_TOUCH_TO_SCROLL_LATENCY(
 174           "Event.Latency.TouchToFirstScrollUpdateSwapBegin",
 175           first_original_component, gpu_swap_begin_component);
 176       // TODO(brianderson): Remove this version once we have enough overlapping
 177       // data with the metric above. crbug.com/478845
 178       UMA_HISTOGRAM_TOUCH_TO_SCROLL_LATENCY(
 179           "Event.Latency.TouchToFirstScrollUpdateSwap",
 180           first_original_component, gpu_swap_end_component);
 181     }
 182     original_component = first_original_component;
 183   } else if (!latency.FindLatency(
 184                  ui::INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT,
 185                  latency_component_id, &original_component)) {
 186     return;
 187   }
 188
 189   // This UMA metric tracks the time from when the original touch event is
 190   // created (averaged if there are multiple) to when the scroll gesture
 191   // results in final frame swap.
 192   for (size_t i = 0; i < original_component.event_count; i++) {
 193     UMA_HISTOGRAM_TOUCH_TO_SCROLL_LATENCY(
 194         "Event.Latency.TouchToScrollUpdateSwapBegin", original_component,
 195         gpu_swap_begin_component);
 196     // TODO(brianderson): Remove this version once we have enough overlapping
 197     // data with the metric above. crbug.com/478845
 198     UMA_HISTOGRAM_TOUCH_TO_SCROLL_LATENCY(
 199         "Event.Latency.TouchToScrollUpdateSwap", original_component,
 200         gpu_swap_end_component);
 201   }
 202
 203   // TODO(miletus): Add validation for making sure the following components
 204   // are present and their event times are legit.
 205   LatencyInfo::LatencyComponent rendering_scheduled_component;
 206   bool rendering_scheduled_on_main = latency.FindLatency(
 207       ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_MAIN_COMPONENT,
 208       0, &rendering_scheduled_component);
 209
 210   if (!rendering_scheduled_on_main) {
 211     if (!latency.FindLatency(
 212             ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_IMPL_COMPONENT,
 213             0, &rendering_scheduled_component))
 214       return;
 215   }
 216
 217   if (rendering_scheduled_on_main) {
 218     UMA_HISTOGRAM_SCROLL_LATENCY_LONG(
 219         "Event.Latency.ScrollUpdate.TouchToHandled_Main",
 220         original_component, rendering_scheduled_component);
 221   } else {
 222     UMA_HISTOGRAM_SCROLL_LATENCY_LONG(
 223         "Event.Latency.ScrollUpdate.TouchToHandled_Impl",
 224         original_component, rendering_scheduled_component);
 225   }
 226
 227   LatencyInfo::LatencyComponent renderer_swap_component;
 228   if (!latency.FindLatency(ui::INPUT_EVENT_LATENCY_RENDERER_SWAP_COMPONENT,
 229                            0, &renderer_swap_component))
 230     return;
 231
 232   if (rendering_scheduled_on_main) {
 233     UMA_HISTOGRAM_SCROLL_LATENCY_LONG(
 234         "Event.Latency.ScrollUpdate.HandledToRendererSwap_Main",
 235         rendering_scheduled_component, renderer_swap_component);
 236   } else {
 237     UMA_HISTOGRAM_SCROLL_LATENCY_LONG(
 238         "Event.Latency.ScrollUpdate.HandledToRendererSwap_Impl",
 239         rendering_scheduled_component, renderer_swap_component);
 240   }
 241
 242   LatencyInfo::LatencyComponent browser_received_swap_component;
 243   if (!latency.FindLatency(
 244           ui::INPUT_EVENT_BROWSER_RECEIVED_RENDERER_SWAP_COMPONENT,
 245           0, &browser_received_swap_component))
 246     return;
 247
 248   UMA_HISTOGRAM_SCROLL_LATENCY_SHORT(
 249       "Event.Latency.ScrollUpdate.RendererSwapToBrowserNotified",
 250       renderer_swap_component, browser_received_swap_component);
 251
 252   UMA_HISTOGRAM_SCROLL_LATENCY_LONG(
 253       "Event.Latency.ScrollUpdate.BrowserNotifiedToBeforeGpuSwap",
 254       browser_received_swap_component, gpu_swap_begin_component);
 255
 256   UMA_HISTOGRAM_SCROLL_LATENCY_SHORT("Event.Latency.ScrollUpdate.GpuSwap",
 257                                      gpu_swap_begin_component,
 258                                      gpu_swap_end_component);
 259 }
 260
 261 // LatencyComponents generated in the renderer must have component IDs
 262 // provided to them by the browser process. This function adds the correct
 263 // component ID where necessary.
 264 void AddLatencyInfoComponentIds(LatencyInfo* latency,
 265                                 int64 latency_component_id) {
 266   LatencyInfo::LatencyMap new_components;
 267   auto lc = latency->latency_components.begin();
 268   while (lc != latency->latency_components.end()) {
 269     ui::LatencyComponentType component_type = lc->first.first;
 270     if (component_type == ui::WINDOW_SNAPSHOT_FRAME_NUMBER_COMPONENT) {
 271       // Generate a new component entry with the correct component ID
 272       auto key = std::make_pair(component_type, latency_component_id);
 273       new_components[key] = lc->second;
 274
 275       // Remove the old entry
 276       latency->latency_components.erase(lc++);
 277     } else {
 278       ++lc;
 279     }
 280   }
 281
 282   // Add newly generated components into the latency info
 283   for (lc = new_components.begin(); lc != new_components.end(); ++lc) {
 284     latency->latency_components[lc->first] = lc->second;
 285   }
 286 }
 287
 288 }  // namespace
 289
 290 RenderWidgetHostLatencyTracker::RenderWidgetHostLatencyTracker()
 291     : last_event_id_(0),
 292       latency_component_id_(0),
 293       device_scale_factor_(1),
 294       has_seent_first_gesture_scroll_update_(false),
 295       browser_composite_latency_history_(kBrowserCompositeLatencyHistorySize) {
 296 }
 297
 298 RenderWidgetHostLatencyTracker::~RenderWidgetHostLatencyTracker() {
 299 }
 300
 301 void RenderWidgetHostLatencyTracker::Initialize(int routing_id,
 302                                                 int process_id) {
 303   DCHECK_EQ(0, last_event_id_);
 304   DCHECK_EQ(0, latency_component_id_);
 305   last_event_id_ = static_cast<int64>(process_id) << 32;
 306   latency_component_id_ = routing_id | last_event_id_;
 307 }
 308
 309 void RenderWidgetHostLatencyTracker::OnInputEvent(
 310     const blink::WebInputEvent& event,
 311     LatencyInfo* latency) {
 312   DCHECK(latency);
 313   if (latency->FindLatency(ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT,
 314                            latency_component_id_, NULL)) {
 315     return;
 316   }
 317
 318   if (event.timeStampSeconds &&
 319       !latency->FindLatency(ui::INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT,
 320                             0, NULL)) {
 321     latency->AddLatencyNumberWithTimestamp(
 322         ui::INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT,
 323         0,
 324         0,
 325         base::TimeTicks() +
 326         base::TimeDelta::FromSecondsD(event.timeStampSeconds),
 327         1);
 328   }
 329
 330   latency->AddLatencyNumberWithTraceName(
 331       ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT,
 332       latency_component_id_, ++last_event_id_,
 333       WebInputEventTraits::GetName(event.type));
 334
 335   UpdateLatencyCoordinates(event, device_scale_factor_, latency);
 336
 337   if (event.type == blink::WebInputEvent::GestureScrollBegin) {
 338     has_seent_first_gesture_scroll_update_ = false;
 339   } else if (event.type == blink::WebInputEvent::GestureScrollUpdate) {
 340     // Make a copy of the INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT with a
 341     // different name INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT.
 342     // So we can track the latency specifically for scroll update events.
 343     LatencyInfo::LatencyComponent original_component;
 344     if (latency->FindLatency(ui::INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT, 0,
 345                              &original_component)) {
 346       latency->AddLatencyNumberWithTimestamp(
 347           has_seent_first_gesture_scroll_update_
 348               ? ui::INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT
 349               : ui::INPUT_EVENT_LATENCY_FIRST_SCROLL_UPDATE_ORIGINAL_COMPONENT,
 350           latency_component_id_, original_component.sequence_number,
 351           original_component.event_time, original_component.event_count);
 352     }
 353
 354     has_seent_first_gesture_scroll_update_ = true;
 355   }
 356 }
 357
 358 void RenderWidgetHostLatencyTracker::OnInputEventAck(
 359     const blink::WebInputEvent& event,
 360     LatencyInfo* latency) {
 361   DCHECK(latency);
 362
 363   // Latency ends when it is acked but does not cause render scheduling.
 364   bool rendering_scheduled = latency->FindLatency(
 365       ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_MAIN_COMPONENT, 0, nullptr);
 366   rendering_scheduled |= latency->FindLatency(
 367       ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_IMPL_COMPONENT, 0, nullptr);
 368
 369   if (WebInputEvent::isGestureEventType(event.type)) {
 370     if (!rendering_scheduled) {
 371       latency->AddLatencyNumber(
 372           ui::INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT, 0, 0);
 373       // TODO(jdduke): Consider exposing histograms for gesture event types.
 374     }
 375     return;
 376   }
 377
 378   if (WebInputEvent::isTouchEventType(event.type)) {
 379     latency->AddLatencyNumber(ui::INPUT_EVENT_LATENCY_ACK_RWH_COMPONENT, 0, 0);
 380     if (!rendering_scheduled) {
 381       latency->AddLatencyNumber(
 382           ui::INPUT_EVENT_LATENCY_TERMINATED_TOUCH_COMPONENT, 0, 0);
 383     }
 384     ComputeInputLatencyHistograms(WebInputEvent::TouchTypeFirst,
 385                                   latency_component_id_, *latency);
 386     return;
 387   }
 388
 389   if (event.type == WebInputEvent::MouseWheel) {
 390     latency->AddLatencyNumber(ui::INPUT_EVENT_LATENCY_ACK_RWH_COMPONENT, 0, 0);
 391     if (!rendering_scheduled) {
 392       latency->AddLatencyNumber(
 393           ui::INPUT_EVENT_LATENCY_TERMINATED_MOUSE_COMPONENT, 0, 0);
 394     }
 395     ComputeInputLatencyHistograms(WebInputEvent::MouseWheel,
 396                                   latency_component_id_, *latency);
 397     return;
 398   }
 399
 400   // TODO(jdduke): Determine if mouse and keyboard events are worth hooking
 401   // into LatencyInfo.
 402 }
 403
 404 void RenderWidgetHostLatencyTracker::OnSwapCompositorFrame(
 405     std::vector<LatencyInfo>* latencies) {
 406   DCHECK(latencies);
 407   for (LatencyInfo& latency : *latencies) {
 408     AddLatencyInfoComponentIds(&latency, latency_component_id_);
 409     latency.AddLatencyNumber(
 410         ui::INPUT_EVENT_BROWSER_RECEIVED_RENDERER_SWAP_COMPONENT, 0, 0);
 411   }
 412 }
 413
 414 void RenderWidgetHostLatencyTracker::OnFrameSwapped(
 415     const LatencyInfo& latency) {
 416   LatencyInfo::LatencyComponent gpu_swap_end_component;
 417   if (!latency.FindLatency(
 418           ui::INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT, 0,
 419           &gpu_swap_end_component)) {
 420     return;
 421   }
 422
 423   LatencyInfo::LatencyComponent gpu_swap_begin_component;
 424   if (!latency.FindLatency(ui::INPUT_EVENT_GPU_SWAP_BUFFER_COMPONENT, 0,
 425                            &gpu_swap_begin_component)) {
 426     return;
 427   }
 428
 429   LatencyInfo::LatencyComponent tab_switch_component;
 430   if (latency.FindLatency(ui::TAB_SHOW_COMPONENT, latency_component_id_,
 431                           &tab_switch_component)) {
 432     base::TimeDelta delta =
 433         gpu_swap_end_component.event_time - tab_switch_component.event_time;
 434     for (size_t i = 0; i < tab_switch_component.event_count; i++) {
 435       UMA_HISTOGRAM_TIMES("MPArch.RWH_TabSwitchPaintDuration", delta);
 436     }
 437   }
 438
 439   if (!latency.FindLatency(ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT,
 440                            latency_component_id_, nullptr)) {
 441     return;
 442   }
 443
 444   ComputeScrollLatencyHistograms(gpu_swap_begin_component,
 445                                  gpu_swap_end_component, latency_component_id_,
 446                                  latency);
 447
 448   LatencyInfo::LatencyComponent browser_swap_component;
 449   if (latency.FindLatency(
 450           ui::INPUT_EVENT_BROWSER_RECEIVED_RENDERER_SWAP_COMPONENT, 0,
 451           &browser_swap_component)) {
 452     base::TimeDelta delta =
 453         gpu_swap_begin_component.event_time - browser_swap_component.event_time;
 454     browser_composite_latency_history_.InsertSample(delta);
 455   }
 456 }
 457
 458 base::TimeDelta
 459 RenderWidgetHostLatencyTracker::GetEstimatedBrowserCompositeTime() const {
 460   // TODO(brianderson): Remove lower bound on estimate once we're sure it won't
 461   // cause regressions.
 462   return std::max(
 463       browser_composite_latency_history_.Percentile(
 464           kBrowserCompositeLatencyEstimationPercentile) *
 465           kBrowserCompositeLatencyEstimationSlack,
 466       base::TimeDelta::FromMicroseconds(
 467           (1.0f * base::Time::kMicrosecondsPerSecond) / (3.0f * 60)));
 468 }
 469
 470 }  // namespace content