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