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