chromecast/base/metrics/cast_metrics_helper.cc

// Copyright 2014 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 "chromecast/base/metrics/cast_metrics_helper.h"

#include <utility>
#include <vector>

#include "base/bind.h"
#include "base/bind_helpers.h"
#include "base/json/json_writer.h"
#include "base/location.h"
#include "base/metrics/histogram.h"
#include "base/metrics/user_metrics.h"
#include "base/sequenced_task_runner.h"
#include "base/strings/string_split.h"
#include "base/time/tick_clock.h"
#include "chromecast/base/metrics/cast_histograms.h"
#include "chromecast/base/metrics/grouped_histogram.h"

namespace chromecast {
namespace metrics {

// A useful macro to make sure current member function runs on the valid thread.
#define MAKE_SURE_SEQUENCE(callback, ...)                                  \
  if (!task_runner_->RunsTasksInCurrentSequence()) {                       \
    task_runner_->PostTask(                                                \
        FROM_HERE, base::BindOnce(&CastMetricsHelper::callback,            \
                                  base::Unretained(this), ##__VA_ARGS__)); \
    return;                                                                \
  }

namespace {

const char kMetricsNameAppInfoDelimiter = '#';

constexpr base::TimeDelta kAppLoadTimeout = base::TimeDelta::FromMinutes(5);

}  // namespace

// NOTE(gfhuang): This is a hacky way to encode/decode app infos into a
// string. Mainly because it's hard to add another metrics serialization type
// into components/metrics/serialization/.
// static
bool CastMetricsHelper::DecodeAppInfoFromMetricsName(
    const std::string& metrics_name,
    std::string* action_name,
    std::string* app_id,
    std::string* session_id,
    std::string* sdk_version) {
  DCHECK(action_name);
  DCHECK(app_id);
  DCHECK(session_id);
  DCHECK(sdk_version);
  if (metrics_name.find(kMetricsNameAppInfoDelimiter) == std::string::npos)
    return false;

  std::vector<std::string> tokens = base::SplitString(
      metrics_name, std::string(1, kMetricsNameAppInfoDelimiter),
      base::TRIM_WHITESPACE, base::SPLIT_WANT_ALL);
  DCHECK_EQ(tokens.size(), 4u);
  // The order of tokens should match EncodeAppInfoIntoMetricsName().
  *action_name = tokens[0];
  *app_id = tokens[1];
  *session_id = tokens[2];
  *sdk_version = tokens[3];
  return true;
}

// static
std::string CastMetricsHelper::EncodeAppInfoIntoMetricsName(
    const std::string& action_name,
    const std::string& app_id,
    const std::string& session_id,
    const std::string& sdk_version) {
  std::string result(action_name);
  result.push_back(kMetricsNameAppInfoDelimiter);
  result.append(app_id);
  result.push_back(kMetricsNameAppInfoDelimiter);
  result.append(session_id);
  result.push_back(kMetricsNameAppInfoDelimiter);
  result.append(sdk_version);
  return result;
}

// static
CastMetricsHelper* CastMetricsHelper::GetInstance() {
  static base::NoDestructor<CastMetricsHelper> instance;
  return instance.get();
}

CastMetricsHelper::CastMetricsHelper(
    scoped_refptr<base::SequencedTaskRunner> task_runner,
    const base::TickClock* tick_clock)
    : task_runner_(std::move(task_runner)),
      tick_clock_(tick_clock),
      metrics_sink_(nullptr),
      logged_first_audio_(false),
      record_action_callback_(
          base::BindRepeating(&base::RecordComputedAction)) {
  DCHECK(task_runner_);
}

CastMetricsHelper::~CastMetricsHelper() {}

void CastMetricsHelper::DidStartLoad(const std::string& app_id) {
  MAKE_SURE_SEQUENCE(DidStartLoad, app_id);
  const base::TimeTicks now = Now();

  // Remove start times for apps that never became the current app.
  for (auto it = app_load_start_times_.cbegin();
       it != app_load_start_times_.cend();) {
    if (now - it->second >= kAppLoadTimeout) {
      it = app_load_start_times_.erase(it);
    } else {
      ++it;
    }
  }

  app_load_start_times_[app_id] = now;
}

void CastMetricsHelper::DidCompleteLoad(const std::string& app_id,
                                        const std::string& session_id) {
  MAKE_SURE_SEQUENCE(DidCompleteLoad, app_id, session_id);
  auto it = app_load_start_times_.find(app_id);
  if (it == app_load_start_times_.end()) {
    LOG(ERROR) << "No start time for app: app_id=" << app_id;
    return;
  }
  app_id_ = app_id;
  session_id_ = session_id;
  app_start_time_ = it->second;
  app_load_start_times_.erase(it);
  logged_first_audio_ = false;
  TagAppStartForGroupedHistograms(app_id_);
  sdk_version_.clear();
}

void CastMetricsHelper::UpdateSDKInfo(const std::string& sdk_version) {
  MAKE_SURE_SEQUENCE(UpdateSDKInfo, sdk_version);
  sdk_version_ = sdk_version;
}

void CastMetricsHelper::LogMediaPlay() {
  MAKE_SURE_SEQUENCE(LogMediaPlay);
  RecordSimpleAction(EncodeAppInfoIntoMetricsName(
      "MediaPlay",
      app_id_,
      session_id_,
      sdk_version_));
}

void CastMetricsHelper::LogMediaPause() {
  MAKE_SURE_SEQUENCE(LogMediaPause);
  RecordSimpleAction(EncodeAppInfoIntoMetricsName(
      "MediaPause",
      app_id_,
      session_id_,
      sdk_version_));
}

void CastMetricsHelper::LogTimeToFirstPaint() {
  MAKE_SURE_SEQUENCE(LogTimeToFirstPaint);
  if (app_id_.empty())
    return;
  base::TimeDelta launch_time = Now() - app_start_time_;
  const std::string uma_name(GetMetricsNameWithAppName("Startup",
                                                       "TimeToFirstPaint"));
  LogMediumTimeHistogramEvent(uma_name, launch_time);
  LOG(INFO) << uma_name << " is " << launch_time.InSecondsF() << " seconds.";
}

void CastMetricsHelper::LogTimeToFirstAudio() {
  MAKE_SURE_SEQUENCE(LogTimeToFirstAudio);
  if (logged_first_audio_)
    return;
  if (app_id_.empty())
    return;
  base::TimeDelta time_to_first_audio = Now() - app_start_time_;
  const std::string uma_name(
      GetMetricsNameWithAppName("Startup", "TimeToFirstAudio"));
  LogMediumTimeHistogramEvent(uma_name, time_to_first_audio);
  LOG(INFO) << uma_name << " is " << time_to_first_audio.InSecondsF()
            << " seconds.";
  logged_first_audio_ = true;
}

void CastMetricsHelper::LogTimeToBufferAv(BufferingType buffering_type,
                                          base::TimeDelta time) {
  MAKE_SURE_SEQUENCE(LogTimeToBufferAv, buffering_type, time);
  if (time < base::TimeDelta()) {
    LOG(WARNING) << "Negative time";
    return;
  }

  const std::string uma_name(GetMetricsNameWithAppName(
      "Media",
      (buffering_type == kInitialBuffering ? "TimeToBufferAv" :
       buffering_type == kBufferingAfterUnderrun ?
           "TimeToBufferAvAfterUnderrun" :
       buffering_type == kAbortedBuffering ? "TimeToBufferAvAfterAbort" : "")));

  // Histogram from 250ms to 30s with 50 buckets.
  // The ratio between 2 consecutive buckets is:
  // exp( (ln(30000) - ln(250)) / 50 ) = 1.1
  LogTimeHistogramEvent(
      uma_name,
      time,
      base::TimeDelta::FromMilliseconds(250),
      base::TimeDelta::FromMilliseconds(30000),
      50);
}

std::string CastMetricsHelper::GetMetricsNameWithAppName(
    const std::string& prefix,
    const std::string& suffix) const {
  DCHECK(task_runner_->RunsTasksInCurrentSequence());
  std::string metrics_name(prefix);
  if (!app_id_.empty()) {
    if (!metrics_name.empty())
      metrics_name.push_back('.');
    metrics_name.append(app_id_);
  }
  if (!suffix.empty()) {
    if (!metrics_name.empty())
      metrics_name.push_back('.');
    metrics_name.append(suffix);
  }
  return metrics_name;
}

void CastMetricsHelper::SetMetricsSink(MetricsSink* delegate) {
  MAKE_SURE_SEQUENCE(SetMetricsSink, delegate);
  metrics_sink_ = delegate;
}

void CastMetricsHelper::SetRecordActionCallback(RecordActionCallback callback) {
  DCHECK(task_runner_->RunsTasksInCurrentSequence());
  record_action_callback_ = std::move(callback);
}

void CastMetricsHelper::SetDummySessionIdForTesting() {
  DCHECK(task_runner_->RunsTasksInCurrentSequence());
  session_id_ = "00000000-0000-0000-0000-000000000000";
}

void CastMetricsHelper::RecordSimpleAction(const std::string& action) {
  MAKE_SURE_SEQUENCE(RecordSimpleAction, action);

  if (metrics_sink_) {
    metrics_sink_->OnAction(action);
  } else {
    record_action_callback_.Run(action);
  }
}

void CastMetricsHelper::LogEnumerationHistogramEvent(
    const std::string& name, int value, int num_buckets) {
  MAKE_SURE_SEQUENCE(LogEnumerationHistogramEvent, name, value, num_buckets);

  if (metrics_sink_) {
    metrics_sink_->OnEnumerationEvent(name, value, num_buckets);
  } else {
    UMA_HISTOGRAM_ENUMERATION_NO_CACHE(name, value, num_buckets);
  }
}

void CastMetricsHelper::LogTimeHistogramEvent(const std::string& name,
                                              base::TimeDelta value,
                                              base::TimeDelta min,
                                              base::TimeDelta max,
                                              int num_buckets) {
  MAKE_SURE_SEQUENCE(LogTimeHistogramEvent, name, value, min, max, num_buckets);

  if (metrics_sink_) {
    metrics_sink_->OnTimeEvent(name, value, min, max, num_buckets);
  } else {
    UMA_HISTOGRAM_CUSTOM_TIMES_NO_CACHE(name, value, min, max, num_buckets);
  }
}

void CastMetricsHelper::LogMediumTimeHistogramEvent(const std::string& name,
                                                    base::TimeDelta value) {
  // Follow UMA_HISTOGRAM_MEDIUM_TIMES definition.
  LogTimeHistogramEvent(name, value,
                        base::TimeDelta::FromMilliseconds(10),
                        base::TimeDelta::FromMinutes(3),
                        50);
}

base::Value CastMetricsHelper::CreateEventBase(const std::string& name) {
  base::Value cast_event(base::Value::Type::DICTIONARY);
  cast_event.SetKey("name", base::Value(name));
  const double time = (Now() - base::TimeTicks()).InMicroseconds();
  cast_event.SetKey("time", base::Value(time));
  return cast_event;
}

void CastMetricsHelper::RecordEventWithValue(const std::string& event,
                                             int value) {
  base::Value cast_event = CreateEventBase(event);
  cast_event.SetKey("value", base::Value(value));
  std::string message;
  base::JSONWriter::Write(cast_event, &message);
  RecordSimpleAction(message);
}

void CastMetricsHelper::RecordApplicationEvent(const std::string& event) {
  base::Value cast_event = CreateEventBase(event);
  cast_event.SetKey("app_id", base::Value(app_id_));
  cast_event.SetKey("session_id", base::Value(session_id_));
  cast_event.SetKey("sdk_version", base::Value(sdk_version_));
  std::string message;
  base::JSONWriter::Write(cast_event, &message);
  RecordSimpleAction(message);
}

void CastMetricsHelper::RecordApplicationEventWithValue(
    const std::string& event,
    int value) {
  base::Value cast_event = CreateEventBase(event);
  cast_event.SetKey("app_id", base::Value(app_id_));
  cast_event.SetKey("session_id", base::Value(session_id_));
  cast_event.SetKey("sdk_version", base::Value(sdk_version_));
  cast_event.SetKey("value", base::Value(value));
  std::string message;
  base::JSONWriter::Write(cast_event, &message);
  RecordSimpleAction(message);
}

base::TimeTicks CastMetricsHelper::Now() {
  return tick_clock_ ? tick_clock_->NowTicks() : base::TimeTicks::Now();
}

}  // namespace metrics
}  // namespace chromecast