910e62b5创建于 1月15日历史提交
// Copyright 2022 The Chromium Authors
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

#include "ash/metrics/ui_metrics_recorder.h"

#include <array>
#include <string_view>

#include "base/check_op.h"
#include "base/containers/span.h"
#include "base/logging.h"
#include "base/metrics/histogram_functions.h"
#include "base/metrics/histogram_macros.h"
#include "base/notreached.h"
#include "base/time/time.h"
#include "cc/metrics/event_metrics.h"
#include "components/viz/common/frame_sinks/begin_frame_args.h"

#undef ENABLED_VLOG_LEVEL
#define ENABLED_VLOG_LEVEL 1

using EventType = cc::EventMetrics::EventType;

namespace ash {

namespace {

using FpsBucket = UiMetricsRecorder::FpsBucket;
using CoreEventType = UiMetricsRecorder::CoreEventType;
constexpr int kMaxFpsBucketIndex = UiMetricsRecorder::kMaxFpsBucketIndex;
constexpr int kMaxCoreEventTypeIndex =
    UiMetricsRecorder::kMaxCoreEventTypeIndex;

// A fixed table of event latency histogram names. This is to avoid runtime
// string constructions and for better readability.
constexpr std::array<
    std::string_view,
    static_cast<size_t>(cc::EventMetrics::EventType::kMaxValue) + 1>
    kEventLatencyHistogramNames = {{
        "Ash.EventLatency.MousePressed.TotalLatency",
        "Ash.EventLatency.MouseReleased.TotalLatency",
        "Ash.EventLatency.MouseWheel.TotalLatency",
        "Ash.EventLatency.KeyPressed.TotalLatency",
        "Ash.EventLatency.KeyReleased.TotalLatency",
        "Ash.EventLatency.TouchPressed.TotalLatency",
        "Ash.EventLatency.TouchReleased.TotalLatency",
        "Ash.EventLatency.TouchMoved.TotalLatency",
        "Ash.EventLatency.GestureScrollBegin.TotalLatency",
        "Ash.EventLatency.GestureScrollUpdate.TotalLatency",
        "Ash.EventLatency.GestureScrollEnd.TotalLatency",
        "Ash.EventLatency.GestureDoubleTap.TotalLatency",
        "Ash.EventLatency.GestureLongPress.TotalLatency",
        "Ash.EventLatency.GestureLongTap.TotalLatency",
        "Ash.EventLatency.GestureShowPress.TotalLatency",
        "Ash.EventLatency.GestureTap.TotalLatency",
        "Ash.EventLatency.GestureTapCancel.TotalLatency",
        "Ash.EventLatency.GestureTapDown.TotalLatency",
        "Ash.EventLatency.GestureTapUnconfirmed.TotalLatency",
        "Ash.EventLatency.GestureTwoFingerTap.TotalLatency",
        "Ash.EventLatency.FirstGestureScrollUpdate.TotalLatency",
        "Ash.EventLatency.MouseDragged.TotalLatency",
        "Ash.EventLatency.GesturePinchBegin.TotalLatency",
        "Ash.EventLatency.GesturePinchEnd.TotalLatency",
        "Ash.EventLatency.GesturePinchUpdate.TotalLatency",
        "Ash.EventLatency.InertialGestureScrollUpdate.TotalLatency",
        "Ash.EventLatency.MouseMoved.TotalLatency",
        "Ash.EventLatency.InertialGestureScrollEnd.TotalLatency",
    }};

static_assert(kEventLatencyHistogramNames.size() ==
                  static_cast<size_t>(cc::EventMetrics::EventType::kMaxValue) +
                      1,
              "kEventLatencyHistogramNames needs to be updated to match "
              "cc::EventMetrics::EventType");

constexpr int kMaxEventTypeIndex =
    static_cast<int>(cc::EventMetrics::EventType::kMaxValue) + 1;

// A fixed table of core event latency + fps histogram names. This is to avoid
// runtime string constructions and for better readability.
constexpr std::array<std::string_view,
                     kMaxCoreEventTypeIndex * kMaxFpsBucketIndex>
    kCoreEventLatencyHistogramNames = {{
        // 30Fps
        "Ash.EventLatency.Core.KeyPressed.30Fps.TotalLatency",
        "Ash.EventLatency.Core.KeyReleased.30Fps.TotalLatency",
        "Ash.EventLatency.Core.MousePressed.30Fps.TotalLatency",
        "Ash.EventLatency.Core.MouseReleased.30Fps.TotalLatency",
        "Ash.EventLatency.Core.MouseDragged.30Fps.TotalLatency",
        // 60Fps
        "Ash.EventLatency.Core.KeyPressed.60Fps.TotalLatency",
        "Ash.EventLatency.Core.KeyReleased.60Fps.TotalLatency",
        "Ash.EventLatency.Core.MousePressed.60Fps.TotalLatency",
        "Ash.EventLatency.Core.MouseReleased.60Fps.TotalLatency",
        "Ash.EventLatency.Core.MouseDragged.60Fps.TotalLatency",
        // 120Fps
        "Ash.EventLatency.Core.KeyPressed.120Fps.TotalLatency",
        "Ash.EventLatency.Core.KeyReleased.120Fps.TotalLatency",
        "Ash.EventLatency.Core.MousePressed.120Fps.TotalLatency",
        "Ash.EventLatency.Core.MouseReleased.120Fps.TotalLatency",
        "Ash.EventLatency.Core.MouseDragged.120Fps.TotalLatency",
        // OtherFps
        "Ash.EventLatency.Core.KeyPressed.OtherFps.TotalLatency",
        "Ash.EventLatency.Core.KeyReleased.OtherFps.TotalLatency",
        "Ash.EventLatency.Core.MousePressed.OtherFps.TotalLatency",
        "Ash.EventLatency.Core.MouseReleased.OtherFps.TotalLatency",
        "Ash.EventLatency.Core.MouseDragged.OtherFps.TotalLatency",
        // UnsetFps
        "Ash.EventLatency.Core.KeyPressed.UnsetFps.TotalLatency",
        "Ash.EventLatency.Core.KeyReleased.UnsetFps.TotalLatency",
        "Ash.EventLatency.Core.MousePressed.UnsetFps.TotalLatency",
        "Ash.EventLatency.Core.MouseReleased.UnsetFps.TotalLatency",
        "Ash.EventLatency.Core.MouseDragged.UnsetFps.TotalLatency",
    }};

bool IsCoreMetric(EventType event_type) {
  return event_type == EventType::kMouseDragged ||
         event_type == EventType::kMousePressed ||
         event_type == EventType::kMouseReleased ||
         event_type == EventType::kKeyPressed ||
         event_type == EventType::kKeyReleased;
}

CoreEventType EventTypeToCoreEventType(cc::EventMetrics::EventType event_type) {
  switch (event_type) {
    case EventType::kKeyPressed:
      return CoreEventType::kKeyPressed;
    case EventType::kKeyReleased:
      return CoreEventType::kKeyReleased;
    case EventType::kMousePressed:
      return CoreEventType::kMousePressed;
    case EventType::kMouseReleased:
      return CoreEventType::kMouseReleased;
    case EventType::kMouseDragged:
      return CoreEventType::kMouseDragged;
    default:
      NOTREACHED();
  }
}

FpsBucket GetFpsBucket(base::TimeDelta interval) {
  if (interval.is_zero()) {
    return FpsBucket::kUnset;
  }

  constexpr base::TimeDelta k120FpsInterval = base::Hertz(120);
  constexpr base::TimeDelta k60FpsInterval = base::Hertz(60);
  constexpr base::TimeDelta k30FpsInterval = base::Hertz(30);

  // Use an epsilon to compare intervals to account for small variations.
  constexpr base::TimeDelta kEpsilonTimeDelta = base::Milliseconds(0.5);

  // Test 60fps first since it should be the more popular case.
  if ((interval - k60FpsInterval).magnitude() <= kEpsilonTimeDelta) {
    return FpsBucket::k60Fps;
  }

  if ((interval - k120FpsInterval).magnitude() <= kEpsilonTimeDelta) {
    return FpsBucket::k120Fps;
  }
  if ((interval - k30FpsInterval).magnitude() <= kEpsilonTimeDelta) {
    return FpsBucket::k30Fps;
  }
  return FpsBucket::kOtherFps;
}

int GetHistogramIndex(CoreEventType core_event_type, FpsBucket fps_bucket) {
  return static_cast<int>(fps_bucket) * kMaxCoreEventTypeIndex +
         static_cast<int>(core_event_type);
}

}  // namespace

UiMetricsRecorder::UiMetricsRecorder() = default;
UiMetricsRecorder::~UiMetricsRecorder() = default;

void UiMetricsRecorder::OnUserLoggedIn() {
  DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);

  // OnUserLoggedIn could be called multiple times from any states.
  // e.g.
  //   from kBeforeLogin: sign-in from the login screen and on cryptohome mount
  //   from kDuringLogin: during user profile loading after checking ownership
  //   from kInSession: adding a new user to the existing session.
  // Only set kDuringLogin on first OnUserLoggedIn call from kBeforeLogin so
  // that kDuringLogin starts from cryptohome mount.
  if (state_ == State::kBeforeLogin) {
    state_ = State::kDuringLogin;
    user_logged_in_time_ = base::TimeTicks::Now();
  }
}

void UiMetricsRecorder::OnPostLoginAnimationFinish() {
  DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);

  // This happens when adding a user to the existing session. Ignore it to
  // treat secondary user login as in session since multiple profile feature is
  // deprecating.
  if (state_ == State::kInSession)
    return;

  DCHECK_EQ(State::kDuringLogin, state_);
  state_ = State::kInSession;
  user_session_start_time_ = base::TimeTicks::Now();
}

void UiMetricsRecorder::ReportPercentDroppedFramesInOneSecondWindow2(
    double percent) {
  UMA_HISTOGRAM_PERCENTAGE("Ash.Smoothness.PercentDroppedFrames_1sWindow2",
                           percent);

  // Time to exclude from user session to be reported under "InSession" metric.
  constexpr base::TimeDelta chopped_user_session_time = base::Minutes(1);
  if (user_session_start_time_ &&
      base::TimeTicks::Now() - user_session_start_time_.value() >=
          chopped_user_session_time) {
    UMA_HISTOGRAM_PERCENTAGE(
        "Ash.Smoothness.PercentDroppedFrames_1sWindow2.InSession", percent);
  }
}

void UiMetricsRecorder::ReportEventLatency(
    const viz::BeginFrameArgs& args,
    std::vector<cc::EventLatencyTracker::LatencyData> latencies) {
  DCHECK_CALLED_ON_VALID_SEQUENCE(sequence_checker_);

  constexpr base::TimeDelta kMaxLatency = base::Seconds(5);
  constexpr base::TimeDelta kLongLatency = base::Milliseconds(500);
  const FpsBucket fps_bucket = GetFpsBucket(args.interval);

  for (auto& latency : latencies) {
    const char* event_type = cc::EventMetrics::GetTypeName(latency.event_type);

    const int event_type_histogram_index = static_cast<int>(latency.event_type);
    const std::string_view event_type_histogram_name =
        kEventLatencyHistogramNames[event_type_histogram_index];
    STATIC_HISTOGRAM_POINTER_GROUP(
        event_type_histogram_name, event_type_histogram_index,
        kMaxEventTypeIndex,
        AddTimeMicrosecondsGranularity(latency.total_latency),
        base::Histogram::FactoryMicrosecondsTimeGet(
            event_type_histogram_name, base::Milliseconds(1), kMaxLatency, 100,
            base::HistogramBase::kUmaTargetedHistogramFlag));

    UMA_HISTOGRAM_CUSTOM_TIMES("Ash.EventLatency.TotalLatency",
                               latency.total_latency, base::Milliseconds(1),
                               kMaxLatency, 100);

    if (IsCoreMetric(latency.event_type)) {
      UMA_HISTOGRAM_CUSTOM_TIMES("Ash.EventLatency.Core.TotalLatency",
                                 latency.total_latency, base::Milliseconds(1),
                                 kMaxLatency, 100);

      // Breakdown by event type and fps.
      const CoreEventType core_event_type =
          EventTypeToCoreEventType(latency.event_type);
      const int core_event_type_fps_histogram_index =
          GetHistogramIndex(core_event_type, fps_bucket);
      const std::string_view core_event_type_fps_histogram_name =
          kCoreEventLatencyHistogramNames[core_event_type_fps_histogram_index];
      STATIC_HISTOGRAM_POINTER_GROUP(
          core_event_type_fps_histogram_name,
          core_event_type_fps_histogram_index,
          kMaxCoreEventTypeIndex * kMaxFpsBucketIndex,
          AddTimeMicrosecondsGranularity(latency.total_latency),
          base::Histogram::FactoryMicrosecondsTimeGet(
              core_event_type_fps_histogram_name, base::Milliseconds(1),
              kMaxLatency, 100,
              base::HistogramBase::kUmaTargetedHistogramFlag));
    }

    if (latency.event_type != EventType::kGestureLongPress &&
        latency.event_type != EventType::kGestureLongTap &&
        latency.total_latency > kLongLatency) {
      VLOG(1) << "Ash event latency is longer than usual"
              << ", type=" << event_type
              << ", latency= " << latency.total_latency.InMilliseconds()
              << " ms";
    }
  }
}

// static
base::span<const std::string_view>
UiMetricsRecorder::GetEventLatencyHistogramNamesForTest() {
  return kEventLatencyHistogramNames;
}

// static
base::span<const std::string_view>
UiMetricsRecorder::GetCoreEventLatencyHistogramNamesForTest() {
  return kCoreEventLatencyHistogramNames;
}

}  // namespace ash