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     base::TimeTicks timestamp_now = base::TimeTicks::Now();
 319     base::TimeTicks timestamp_original = base::TimeTicks() +
 320         base::TimeDelta::FromSecondsD(event.timeStampSeconds);
 321     // |event.timeStampSeconds| is the event's creation timestamp given
 322     // by the OS. On Windows, for non-touch input events the timestamp is
 323     // most likely from timeGetTime(), while in platform independent code
 324     // path we usually get timestamps by calling TimeTicks::Now(), which,
 325     // if using high-resolution timer as underlying implementation, could
 326     // have different time origin than timeGetTime(). To avoid the mismatching,
 327     // lets use TimeTicks::Now() instead of |event.timeStampSeconds| for
 328     // INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT so to be consistent with
 329     // other components.
 330     // TODO(miletus): Remove this hack. crbug.com/527128.
 331 #if defined(OS_WIN)
 332     if (!(blink::WebInputEvent::isTouchEventType(event.type) ||
 333           blink::WebInputEvent::isGestureEventType(event.type)))
 334       timestamp_original = timestamp_now;
 335 #endif  // defined(OS_WIN)
 336
 337     // Timestamp from platform input can wrap, e.g. 32 bits timestamp
 338     // for Xserver and Window MSG time will wrap about 49.6 days. Do a
 339     // sanity check here and if wrap does happen, use TimeTicks::Now()
 340     // as the timestamp instead.
 341     if ((timestamp_now - timestamp_original).InDays() > 0)
 342       timestamp_original = timestamp_now;
 343
 344     latency->AddLatencyNumberWithTimestamp(
 345         ui::INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT,
 346         0,
 347         0,
 348         timestamp_original,
 349         1);
 350   }
 351
 352   latency->AddLatencyNumberWithTraceName(
 353       ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT,
 354       latency_component_id_, ++last_event_id_,
 355       WebInputEventTraits::GetName(event.type));
 356
 357   UpdateLatencyCoordinates(event, device_scale_factor_, latency);
 358
 359   if (event.type == blink::WebInputEvent::GestureScrollBegin) {
 360     has_seent_first_gesture_scroll_update_ = false;
 361   } else if (event.type == blink::WebInputEvent::GestureScrollUpdate) {
 362     // Make a copy of the INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT with a
 363     // different name INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT.
 364     // So we can track the latency specifically for scroll update events.
 365     LatencyInfo::LatencyComponent original_component;
 366     if (latency->FindLatency(ui::INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT, 0,
 367                              &original_component)) {
 368       latency->AddLatencyNumberWithTimestamp(
 369           has_seent_first_gesture_scroll_update_
 370               ? ui::INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT
 371               : ui::INPUT_EVENT_LATENCY_FIRST_SCROLL_UPDATE_ORIGINAL_COMPONENT,
 372           latency_component_id_, original_component.sequence_number,
 373           original_component.event_time, original_component.event_count);
 374     }
 375
 376     has_seent_first_gesture_scroll_update_ = true;
 377   }
 378 }
 379
 380 void RenderWidgetHostLatencyTracker::OnInputEventAck(
 381     const blink::WebInputEvent& event,
 382     LatencyInfo* latency) {
 383   DCHECK(latency);
 384
 385   // Latency ends when it is acked but does not cause render scheduling.
 386   bool rendering_scheduled = latency->FindLatency(
 387       ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_MAIN_COMPONENT, 0, nullptr);
 388   rendering_scheduled |= latency->FindLatency(
 389       ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_IMPL_COMPONENT, 0, nullptr);
 390
 391   if (WebInputEvent::isGestureEventType(event.type)) {
 392     if (!rendering_scheduled) {
 393       latency->AddLatencyNumber(
 394           ui::INPUT_EVENT_LATENCY_TERMINATED_GESTURE_COMPONENT, 0, 0);
 395       // TODO(jdduke): Consider exposing histograms for gesture event types.
 396     }
 397     return;
 398   }
 399
 400   if (WebInputEvent::isTouchEventType(event.type)) {
 401     latency->AddLatencyNumber(ui::INPUT_EVENT_LATENCY_ACK_RWH_COMPONENT, 0, 0);
 402     if (!rendering_scheduled) {
 403       latency->AddLatencyNumber(
 404           ui::INPUT_EVENT_LATENCY_TERMINATED_TOUCH_COMPONENT, 0, 0);
 405     }
 406     ComputeInputLatencyHistograms(WebInputEvent::TouchTypeFirst,
 407                                   latency_component_id_, *latency);
 408     return;
 409   }
 410
 411   if (event.type == WebInputEvent::MouseWheel) {
 412     latency->AddLatencyNumber(ui::INPUT_EVENT_LATENCY_ACK_RWH_COMPONENT, 0, 0);
 413     if (!rendering_scheduled) {
 414       latency->AddLatencyNumber(
 415           ui::INPUT_EVENT_LATENCY_TERMINATED_MOUSE_WHEEL_COMPONENT, 0, 0);
 416     }
 417     ComputeInputLatencyHistograms(WebInputEvent::MouseWheel,
 418                                   latency_component_id_, *latency);
 419     return;
 420   }
 421
 422   if (WebInputEvent::isMouseEventType(event.type) && !rendering_scheduled) {
 423       latency->AddLatencyNumber(
 424           ui::INPUT_EVENT_LATENCY_TERMINATED_MOUSE_COMPONENT, 0, 0);
 425     return;
 426   }
 427
 428   if (WebInputEvent::isKeyboardEventType(event.type) && !rendering_scheduled) {
 429       latency->AddLatencyNumber(
 430           ui::INPUT_EVENT_LATENCY_TERMINATED_KEYBOARD_COMPONENT, 0, 0);
 431     return;
 432   }
 433 }
 434
 435 void RenderWidgetHostLatencyTracker::OnSwapCompositorFrame(
 436     std::vector<LatencyInfo>* latencies) {
 437   DCHECK(latencies);
 438   for (LatencyInfo& latency : *latencies) {
 439     AddLatencyInfoComponentIds(&latency, latency_component_id_);
 440     latency.AddLatencyNumber(
 441         ui::INPUT_EVENT_BROWSER_RECEIVED_RENDERER_SWAP_COMPONENT, 0, 0);
 442   }
 443 }
 444
 445 void RenderWidgetHostLatencyTracker::OnFrameSwapped(
 446     const LatencyInfo& latency) {
 447   LatencyInfo::LatencyComponent gpu_swap_end_component;
 448   if (!latency.FindLatency(
 449           ui::INPUT_EVENT_LATENCY_TERMINATED_FRAME_SWAP_COMPONENT, 0,
 450           &gpu_swap_end_component)) {
 451     return;
 452   }
 453
 454   LatencyInfo::LatencyComponent gpu_swap_begin_component;
 455   if (!latency.FindLatency(ui::INPUT_EVENT_GPU_SWAP_BUFFER_COMPONENT, 0,
 456                            &gpu_swap_begin_component)) {
 457     return;
 458   }
 459
 460   LatencyInfo::LatencyComponent tab_switch_component;
 461   if (latency.FindLatency(ui::TAB_SHOW_COMPONENT, latency_component_id_,
 462                           &tab_switch_component)) {
 463     base::TimeDelta delta =
 464         gpu_swap_end_component.event_time - tab_switch_component.event_time;
 465     for (size_t i = 0; i < tab_switch_component.event_count; i++) {
 466       UMA_HISTOGRAM_TIMES("MPArch.RWH_TabSwitchPaintDuration", delta);
 467     }
 468   }
 469
 470   if (!latency.FindLatency(ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT,
 471                            latency_component_id_, nullptr)) {
 472     return;
 473   }
 474
 475   ComputeScrollLatencyHistograms(gpu_swap_begin_component,
 476                                  gpu_swap_end_component, latency_component_id_,
 477                                  latency);
 478 }
 479
 480 }  // namespace content