latency_tracker.cc

// Copyright 2017 The Chromium Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

#include "ui/latency/latency_tracker.h"

#include <algorithm>
#include "base/metrics/histogram_functions.h"
#include "base/metrics/histogram_macros.h"
#include "base/no_destructor.h"
#include "base/rand_util.h"
#include "base/strings/strcat.h"
#include "base/trace_event/trace_event.h"
#include "services/metrics/public/cpp/ukm_entry_builder.h"
#include "services/metrics/public/cpp/ukm_recorder.h"
#include "ui/latency/latency_histogram_macros.h"

// Impose some restrictions for tests etc, but also be lenient since some of the
// data come from untrusted sources.
#define DCHECK_AND_RETURN_ON_FAIL(x) \
  DCHECK(x);                         \
  if (!(x))                          \
    return;

namespace ui {
namespace {

std::string LatencySourceEventTypeToInputModalityString(
    ui::SourceEventType type) {
  switch (type) {
    case ui::SourceEventType::WHEEL:
      return "Wheel";
    case ui::SourceEventType::MOUSE:
      return "Mouse";
    case ui::SourceEventType::TOUCH:
    case ui::SourceEventType::INERTIAL:
      return "Touch";
    case ui::SourceEventType::KEY_PRESS:
      return "KeyPress";
    case ui::SourceEventType::TOUCHPAD:
      return "Touchpad";
    case ui::SourceEventType::SCROLLBAR:
      return "Scrollbar";
    default:
      return "";
  }
}

bool IsInertialScroll(const LatencyInfo& latency) {
  return latency.source_event_type() == ui::SourceEventType::INERTIAL;
}

// This UMA metric tracks the time from when the original wheel event is created
// to when the scroll gesture results in final frame swap. All scroll events are
// included in this metric.
void RecordUmaEventLatencyScrollWheelTimeToScrollUpdateSwapBegin2Histogram(
    base::TimeTicks start,
    base::TimeTicks end) {
  CONFIRM_EVENT_TIMES_EXIST(start, end);
  UMA_HISTOGRAM_CUSTOM_COUNTS(
      "Event.Latency.Scroll.Wheel.TimeToScrollUpdateSwapBegin2",
      std::max(static_cast<int64_t>(0), (end - start).InMicroseconds()), 1,
      1000000, 100);
}

bool LatencyTraceIdCompare(const LatencyInfo& i, const LatencyInfo& j) {
  return i.trace_id() < j.trace_id();
}

}  // namespace

LatencyTracker::LatencyTracker() = default;
LatencyTracker::~LatencyTracker() = default;

void LatencyTracker::OnGpuSwapBuffersCompleted(
    const std::vector<ui::LatencyInfo>& latency_info,
    bool top_controls_visible_height_changed) {
  // Sort latency_info as they can be in incorrect order.
  std::vector<ui::LatencyInfo> latency_infos(latency_info);
  std::sort(latency_infos.begin(), latency_infos.end(), LatencyTraceIdCompare);
  for (const auto& latency : latency_infos)
    OnGpuSwapBuffersCompleted(latency, top_controls_visible_height_changed);
}

void LatencyTracker::OnGpuSwapBuffersCompleted(
    const LatencyInfo& latency,
    bool top_controls_visible_height_changed) {
  base::TimeTicks gpu_swap_end_timestamp;
  if (!latency.FindLatency(INPUT_EVENT_LATENCY_FRAME_SWAP_COMPONENT,
                           &gpu_swap_end_timestamp)) {
    return;
  }

  base::TimeTicks gpu_swap_begin_timestamp;
  bool found_component = latency.FindLatency(
      ui::INPUT_EVENT_GPU_SWAP_BUFFER_COMPONENT, &gpu_swap_begin_timestamp);
  DCHECK_AND_RETURN_ON_FAIL(found_component);

  if (!latency.FindLatency(ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT,
                           nullptr)) {
    return;
  }

  ui::SourceEventType source_event_type = latency.source_event_type();
  if (source_event_type == ui::SourceEventType::WHEEL ||
      source_event_type == ui::SourceEventType::MOUSE ||
      source_event_type == ui::SourceEventType::TOUCH ||
      source_event_type == ui::SourceEventType::INERTIAL ||
      source_event_type == ui::SourceEventType::KEY_PRESS ||
      source_event_type == ui::SourceEventType::TOUCHPAD ||
      source_event_type == ui::SourceEventType::SCROLLBAR) {
    ComputeEndToEndLatencyHistograms(gpu_swap_begin_timestamp,
                                     gpu_swap_end_timestamp, latency,
                                     top_controls_visible_height_changed);
  }
}

void LatencyTracker::ReportUkmScrollLatency(
    const InputMetricEvent& metric_event,
    base::TimeTicks start_timestamp,
    base::TimeTicks time_to_scroll_update_swap_begin_timestamp,
    base::TimeTicks time_to_handled_timestamp,
    bool is_main_thread,
    const ukm::SourceId ukm_source_id) {
  CONFIRM_EVENT_TIMES_EXIST(start_timestamp,
                            time_to_scroll_update_swap_begin_timestamp)
  CONFIRM_EVENT_TIMES_EXIST(start_timestamp, time_to_handled_timestamp)

  ukm::UkmRecorder* ukm_recorder = ukm::UkmRecorder::Get();
  if (ukm_source_id == ukm::kInvalidSourceId || !ukm_recorder)
    return;

  std::string event_name = "";
  switch (metric_event) {
    case InputMetricEvent::SCROLL_BEGIN_TOUCH:
      event_name = "Event.ScrollBegin.Touch";
      break;
    case InputMetricEvent::SCROLL_UPDATE_TOUCH:
      event_name = "Event.ScrollUpdate.Touch";
      break;
    case InputMetricEvent::SCROLL_BEGIN_WHEEL:
      event_name = "Event.ScrollBegin.Wheel";
      break;
    case InputMetricEvent::SCROLL_UPDATE_WHEEL:
      event_name = "Event.ScrollUpdate.Wheel";
      break;
  }

  ukm::UkmEntryBuilder builder(ukm_source_id, event_name.c_str());
  builder.SetMetric(
      "TimeToScrollUpdateSwapBegin",
      std::max(static_cast<int64_t>(0),
               (time_to_scroll_update_swap_begin_timestamp - start_timestamp)
                   .InMicroseconds()));
  builder.SetMetric(
      "TimeToHandled",
      std::max(static_cast<int64_t>(0),
               (time_to_handled_timestamp - start_timestamp).InMicroseconds()));
  builder.SetMetric("IsMainThread", is_main_thread);
  builder.Record(ukm_recorder);
}

void LatencyTracker::ComputeEndToEndLatencyHistograms(
    base::TimeTicks gpu_swap_begin_timestamp,
    base::TimeTicks gpu_swap_end_timestamp,
    const ui::LatencyInfo& latency,
    bool top_controls_visible_height_changed) {
  DCHECK_AND_RETURN_ON_FAIL(!latency.coalesced());

  base::TimeTicks original_timestamp;
  std::string scroll_name = "Uninitialized";

  const std::string input_modality =
      LatencySourceEventTypeToInputModalityString(latency.source_event_type());

  if (latency.FindLatency(
          ui::INPUT_EVENT_LATENCY_FIRST_SCROLL_UPDATE_ORIGINAL_COMPONENT,
          &original_timestamp)) {
    DCHECK(input_modality == "Wheel" || input_modality == "Touch" ||
           input_modality == "Scrollbar");

    // For inertial scrolling we don't separate the first event from the rest of
    // them.
    scroll_name = IsInertialScroll(latency) ? "ScrollInertial" : "ScrollBegin";

    // This UMA metric tracks the performance of overall scrolling as a high
    // level metric.
    UMA_HISTOGRAM_INPUT_LATENCY_5_SECONDS_MAX_MICROSECONDS(
        "Event.Latency.ScrollBegin.TimeToScrollUpdateSwapBegin2",
        original_timestamp, gpu_swap_begin_timestamp);

    // This UMA metric tracks the time between the final frame swap for the
    // first scroll event in a sequence and the original timestamp of that
    // scroll event's underlying touch/wheel event.
    std::string metric_name =
        base::StrCat({"Event.Latency.", scroll_name, ".", input_modality,
                      ".TimeToScrollUpdateSwapBegin4"});
    UMA_HISTOGRAM_INPUT_LATENCY_5_SECONDS_MAX_MICROSECONDS(
        metric_name, original_timestamp, gpu_swap_begin_timestamp);

    // Report whether the top-controls visible height changed from this scroll
    // event.
    UMA_HISTOGRAM_BOOLEAN("Event.Latency.ScrollBegin.TopControlsMoved",
                          top_controls_visible_height_changed);
    // Also report the latency metric separately for the scrolls that caused the
    // top-controls to scroll and the ones that didn't.
    if (top_controls_visible_height_changed)
      base::StrAppend(&metric_name, {".TopControlsMoved"});
    else
      base::StrAppend(&metric_name, {".NoTopControlsMoved"});
    UMA_HISTOGRAM_INPUT_LATENCY_5_SECONDS_MAX_MICROSECONDS(
        metric_name, original_timestamp, gpu_swap_begin_timestamp);

    if (input_modality == "Wheel") {
      RecordUmaEventLatencyScrollWheelTimeToScrollUpdateSwapBegin2Histogram(
          original_timestamp, gpu_swap_begin_timestamp);
    }

  } else if (latency.FindLatency(
                 ui::INPUT_EVENT_LATENCY_SCROLL_UPDATE_ORIGINAL_COMPONENT,
                 &original_timestamp)) {
    DCHECK(input_modality == "Wheel" || input_modality == "Touch" ||
           input_modality == "Scrollbar");
    // For inertial scrolling we don't separate the first event from the rest of
    // them.
    scroll_name = IsInertialScroll(latency) ? "ScrollInertial" : "ScrollUpdate";

    // This UMA metric tracks the performance of overall scrolling as a high
    // level metric.
    UMA_HISTOGRAM_INPUT_LATENCY_5_SECONDS_MAX_MICROSECONDS(
        "Event.Latency.ScrollUpdate.TimeToScrollUpdateSwapBegin2",
        original_timestamp, gpu_swap_begin_timestamp);

    // This UMA metric tracks the time from when the original touch/wheel event
    // is created to when the scroll gesture results in final frame swap.
    // First scroll events are excluded from this metric.
    std::string metric_name =
        base::StrCat({"Event.Latency.", scroll_name, ".", input_modality,
                      ".TimeToScrollUpdateSwapBegin4"});
    UMA_HISTOGRAM_INPUT_LATENCY_5_SECONDS_MAX_MICROSECONDS(
        metric_name, original_timestamp, gpu_swap_begin_timestamp);

    // Report whether the top-controls visible height changed from this scroll
    // event.
    UMA_HISTOGRAM_BOOLEAN("Event.Latency.ScrollUpdate.TopControlsMoved",
                          top_controls_visible_height_changed);

    // Also report the latency metric separately for the scrolls that caused the
    // top-controls to scroll and the ones that didn't.
    if (top_controls_visible_height_changed)
      base::StrAppend(&metric_name, {".TopControlsMoved"});
    else
      base::StrAppend(&metric_name, {".NoTopControlsMoved"});
    UMA_HISTOGRAM_INPUT_LATENCY_5_SECONDS_MAX_MICROSECONDS(
        metric_name, original_timestamp, gpu_swap_begin_timestamp);

    if (input_modality == "Wheel") {
      RecordUmaEventLatencyScrollWheelTimeToScrollUpdateSwapBegin2Histogram(
          original_timestamp, gpu_swap_begin_timestamp);
    }
  } else if (latency.FindLatency(ui::INPUT_EVENT_LATENCY_ORIGINAL_COMPONENT,
                                 &original_timestamp)) {
    if (latency.source_event_type() == SourceEventType::KEY_PRESS) {
      UMA_HISTOGRAM_INPUT_LATENCY_HIGH_RESOLUTION_MICROSECONDS(
          "Event.Latency.EndToEnd.KeyPress", original_timestamp,
          gpu_swap_begin_timestamp);
    } else if (latency.source_event_type() == SourceEventType::MOUSE) {
      UMA_HISTOGRAM_INPUT_LATENCY_HIGH_RESOLUTION_MICROSECONDS(
          "Event.Latency.EndToEnd.Mouse", original_timestamp,
          gpu_swap_begin_timestamp);
    } else if (latency.source_event_type() == SourceEventType::TOUCHPAD) {
      base::TimeTicks timestamp;
      if (latency.FindLatency(ui::INPUT_EVENT_LATENCY_BEGIN_RWH_COMPONENT,
                              &timestamp)) {
        UMA_HISTOGRAM_INPUT_LATENCY_CUSTOM_MICROSECONDS(
            "Event.Latency.EventToRender.TouchpadPinch", original_timestamp,
            timestamp);
      }
      {
        // TODO(nburris): Deprecate Event.Latency.EndToEnd.TouchpadPinch in
        // favor of TouchpadPinch2 once we have stable data for that one.
        UMA_HISTOGRAM_INPUT_LATENCY_CUSTOM_MICROSECONDS(
            "Event.Latency.EndToEnd.TouchpadPinch", original_timestamp,
            gpu_swap_begin_timestamp);
      }
      UMA_HISTOGRAM_INPUT_LATENCY_CUSTOM_1_SECOND_MAX_MICROSECONDS(
          "Event.Latency.EndToEnd.TouchpadPinch2", original_timestamp,
          gpu_swap_begin_timestamp);
    }
    return;
  } else {
    // No original component found.
    return;
  }

  // Record scroll latency metrics.
  DCHECK(scroll_name == "ScrollBegin" || scroll_name == "ScrollUpdate" ||
         (IsInertialScroll(latency) && scroll_name == "ScrollInertial"));

  base::TimeTicks rendering_scheduled_timestamp;
  bool rendering_scheduled_on_main = latency.FindLatency(
      ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_MAIN_COMPONENT,
      &rendering_scheduled_timestamp);
  if (!rendering_scheduled_on_main) {
    bool found_component = latency.FindLatency(
        ui::INPUT_EVENT_LATENCY_RENDERING_SCHEDULED_IMPL_COMPONENT,
        &rendering_scheduled_timestamp);
    DCHECK_AND_RETURN_ON_FAIL(found_component);
  }

  if (!IsInertialScroll(latency) && input_modality == "Touch") {
    average_lag_tracker_.AddLatencyInFrame(latency, gpu_swap_begin_timestamp,
                                           scroll_name);
  }

  // Inertial and scrollbar scrolls are excluded from Ukm metrics.
  if ((input_modality == "Touch" && !IsInertialScroll(latency)) ||
      input_modality == "Wheel") {
    InputMetricEvent input_metric_event;
    if (scroll_name == "ScrollBegin") {
      input_metric_event = input_modality == "Touch"
                               ? InputMetricEvent::SCROLL_BEGIN_TOUCH
                               : InputMetricEvent::SCROLL_BEGIN_WHEEL;
    } else {
      DCHECK_EQ(scroll_name, "ScrollUpdate");
      input_metric_event = input_modality == "Touch"
                               ? InputMetricEvent::SCROLL_UPDATE_TOUCH
                               : InputMetricEvent::SCROLL_UPDATE_WHEEL;
    }
    ReportUkmScrollLatency(
        input_metric_event, original_timestamp, gpu_swap_begin_timestamp,
        rendering_scheduled_timestamp, rendering_scheduled_on_main,
        latency.ukm_source_id());
  }

  const std::string thread_name = rendering_scheduled_on_main ? "Main" : "Impl";

  UMA_HISTOGRAM_SCROLL_LATENCY_LONG_2(
      "Event.Latency." + scroll_name + "." + input_modality +
          ".TimeToHandled2_" + thread_name,
      original_timestamp, rendering_scheduled_timestamp);

  if (input_modality == "Wheel") {
    UMA_HISTOGRAM_SCROLL_LATENCY_LONG_2(
        "Event.Latency.Scroll.Wheel.TimeToHandled2_" + thread_name,
        original_timestamp, rendering_scheduled_timestamp);
  }

  base::TimeTicks renderer_swap_timestamp;
  bool found_renderer_swap_component =
      latency.FindLatency(ui::INPUT_EVENT_LATENCY_RENDERER_SWAP_COMPONENT,
                          &renderer_swap_timestamp);

  base::TimeTicks browser_received_swap_timestamp;
  bool found_received_frame_component =
      latency.FindLatency(ui::DISPLAY_COMPOSITOR_RECEIVED_FRAME_COMPONENT,
                          &browser_received_swap_timestamp);
  DCHECK_AND_RETURN_ON_FAIL(found_received_frame_component);

  // If we're committing to the active tree, there will never be a renderer
  // swap. In this case, don't record the two histogram values for the periods
  // surrounding the renderer swap. We could assign the total time to one or the
  // other of them, but that would likely skew statistics.
  if (found_renderer_swap_component) {
    UMA_HISTOGRAM_SCROLL_LATENCY_LONG_2(
        "Event.Latency." + scroll_name + "." + input_modality +
            ".HandledToRendererSwap2_" + thread_name,
        rendering_scheduled_timestamp, renderer_swap_timestamp);

    UMA_HISTOGRAM_SCROLL_LATENCY_SHORT_2(
        "Event.Latency." + scroll_name + "." + input_modality +
            ".RendererSwapToBrowserNotified2",
        renderer_swap_timestamp, browser_received_swap_timestamp);
  }

  UMA_HISTOGRAM_SCROLL_LATENCY_LONG_2(
      "Event.Latency." + scroll_name + "." + input_modality +
          ".BrowserNotifiedToBeforeGpuSwap2",
      browser_received_swap_timestamp, gpu_swap_begin_timestamp);

  UMA_HISTOGRAM_SCROLL_LATENCY_SHORT_2(
      "Event.Latency." + scroll_name + "." + input_modality + ".GpuSwap2",
      gpu_swap_begin_timestamp, gpu_swap_end_timestamp);
}

}  // namespace ui