Basic UkmService implementation

components/ukm/ukm_service.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 "components/ukm/ukm_service.h"
+
+#include <utility>
+
+#include "base/feature_list.h"
+#include "base/memory/ptr_util.h"
+#include "base/metrics/field_trial.h"
+#include "base/metrics/histogram_macros.h"
+#include "base/rand_util.h"
+#include "base/time/time.h"
+#include "components/metrics/metrics_log_uploader.h"
+#include "components/metrics/metrics_service_client.h"
+#include "components/metrics/proto/ukm/report.pb.h"
+#include "components/prefs/pref_registry_simple.h"
+#include "components/prefs/pref_service.h"
+#include "components/ukm/metrics_reporting_scheduler.h"
+#include "components/ukm/persisted_logs_metrics_impl.h"
+#include "components/ukm/ukm_pref_names.h"
+#include "components/variations/variations_associated_data.h"
+
+namespace ukm {
+
+namespace {
+
+const base::Feature kUkmFeature = {
+  "Ukm", base::FEATURE_DISABLED_BY_DEFAULT
+};
+
+const char kMimeType[] = "application/vnd.chrome.ukm";
+
+// Constants for the UKM rollout field trial.
+const char kUkmRolloutFieldTrialName[] = "UkmRollout";
+
+// Constant for the finch parameter name for the server URL

[rkaplow, 2017/01/02 23:23:04]

prefer not using finch since it's technically internal, would use variations.
also trailing period.

[Steven Holte, 2017/01/03 21:16:04]

Done.

+const char kUkmRolloutServerUrlParam[] = "ServerUrl";
+
+// The ukm server's URL.

[rkaplow, 2017/01/02 23:23:03]

UKM

[Steven Holte, 2017/01/03 21:16:03]

Done.

+const char kDefaultServerUrl[] = "https://clients4.google.com/ukm";
+
+// The number of UKM logs that must be stored.

[rkaplow, 2017/01/02 23:23:04]

comment

[Steven Holte, 2017/01/03 21:16:04]

Done.

+const int kInitializationDelaySeconds = 5;
+
+// The number of UKM logs that must be stored.

[rkaplow, 2017/01/02 23:23:04]

can you comment more on this

[Steven Holte, 2017/01/03 21:16:04]

Done.

+const int kMinPersistedLogs = 8;
+
+// The number of bytes UKM logs that must be stored.

[rkaplow, 2017/01/02 23:23:04]

would reword 

[Steven Holte, 2017/01/03 21:16:04]

Done.

+// This ensures that a reasonable amount of history will be stored even if there
+// is a long series of very small logs.
+const int kMinPersistedBytes = 300000;

[rkaplow, 2017/01/02 23:23:04]

how did you get this value.

I also think it might make sense to make some of these constant parametrized in
case we want to test them - for example this and the # persisted logs and the
max upload log size

[Steven Holte, 2017/01/03 21:16:04]

I've just copied these values from the ones being used in UMA for ongoing logs.

+
+// If an upload fails, and the transmission was over this byte count, then we
+// will discard the log, and not try to retransmit it.  We also don't persist
+// the log to the prefs for transmission during the next chrome session if this
+// limit is exceeded.
+const size_t kUploadLogAvoidRetransmitSize = 100 * 1024;

[rkaplow, 2017/01/02 23:23:03]

i see this is the same name as ni metrics_service but I kind of feel 'Max'
should be in the name somewhere. might be better to be consistant though

[Steven Holte, 2017/01/03 21:16:04]

Renamed to kMaxLogRetransmitSize

+
+std::string GetServerUrl() {
+  std::string server_url = variations::GetVariationParamValue(
+      kUkmRolloutFieldTrialName, kUkmRolloutServerUrlParam);
+  if (!server_url.empty())
+    return server_url;
+  else

[rkaplow, 2017/01/02 23:23:04]

nit, would prefer omitting the else

[Steven Holte, 2017/01/03 21:16:04]

Done.

+    return kDefaultServerUrl;
+}
+
+uint64_t LoadClientId(PrefService* pref_service) {

[rkaplow, 2017/01/02 23:23:04]

i wonder if this names hides a bit too much logic. Could be
LoadOrGenerateClientId - but that is a bit wordy. Up to you.

[Steven Holte, 2017/01/03 21:16:04]

Done.

+  uint64_t client_id = pref_service->GetInteger(prefs::kUkmClientId);
+  if (!client_id) {
+    // Generate and store a new client id.
+    client_id = base::RandUint64();

[rkaplow, 2017/01/02 23:23:04]

i know we keep a string GUID for UMA, which ends up being hashed. under the hood
GUID uses this method, so I assume it will work out to basically the same.

So this seems fine byut maybe there's some reason we should store as a string,
maybe alexei has more context in the history of the UMA id.

[Steven Holte, 2017/01/03 21:16:04]

GUIDs are actually 128 bits, our current proto only has a 64 bits.

+    pref_service->SetInteger(prefs::kUkmClientId, client_id);
+  }
+  return client_id;
+}
+
+}  // namespace
+
+UkmService::UkmService(
+    PrefService* pref_service,
+    metrics::MetricsServiceClient* client)
+    : pref_service_(pref_service),
+      client_(client),
+      persisted_logs_(std::unique_ptr<ukm::PersistedLogsMetricsImpl>(
+                             new ukm::PersistedLogsMetricsImpl()),
+                      pref_service,
+                      prefs::kUkmPersistedLogs,
+                      NULL,
+                      kMinPersistedLogs,
+                      kMinPersistedBytes,
+                      kUploadLogAvoidRetransmitSize),
+      initialize_started_(false),
+      self_ptr_factory_(this) {
+  DCHECK(pref_service_);
+  DCHECK(client_);
+
+  auto status = persisted_logs_.DeserializeLogs();
+  UMA_HISTOGRAM_ENUMERATION(
+      "Ukm.PersistedLogs.DeserializeLogs.Status",

[rkaplow, 2017/01/02 23:23:04]

UKM

[Steven Holte, 2017/01/03 21:16:04]

Removed this metric, since it's already recorded by the
PersistedLogsMetricsImpl.

+      status,
+      metrics::PersistedLogs::LogReadStatus::END_RECALL_STATUS);
+
+  base::Closure rotate_callback =
+      base::Bind(&UkmService::RotateLog,
+                 self_ptr_factory_.GetWeakPtr());
+  // MetricsServiceClient outlives MetricsService, and
+  // MetricsReportingScheduler is tied to the lifetime of |this|.
+  const base::Callback<base::TimeDelta(void)>& get_upload_interval_callback =
+      base::Bind(&metrics::MetricsServiceClient::GetStandardUploadInterval,
+                 base::Unretained(client_));
+  scheduler_.reset(new ukm::MetricsReportingScheduler(
+      rotate_callback, get_upload_interval_callback));
+}
+
+UkmService::~UkmService() {}
+
+void UkmService::Initialize() {
+  DCHECK(thread_checker_.CalledOnValidThread());
+  DVLOG(1) << "UkmService::Initialize";
+  initialize_started_ = true;
+
+  base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
+      FROM_HERE, base::Bind(&UkmService::StartInitTask,
+                            self_ptr_factory_.GetWeakPtr()),
+      base::TimeDelta::FromSeconds(kInitializationDelaySeconds));
+}
+
+void UkmService::EnableReporting() {
+  DCHECK(thread_checker_.CalledOnValidThread());
+  DVLOG(1) << "UkmService::EnableReporting";
+  if (!base::FeatureList::IsEnabled(kUkmFeature))
+    return;
+  if (!initialize_started_)
+    Initialize();
+  scheduler_->Start();
+}
+
+void UkmService::DisableReporting() {
+  DCHECK(thread_checker_.CalledOnValidThread());
+  DVLOG(1) << "UkmService::DisableReporting";
+  scheduler_->UploadCancelled();
+  scheduler_->Stop();
+}
+
+// static
+void UkmService::RegisterPrefs(PrefRegistrySimple* registry) {
+  registry->RegisterIntegerPref(prefs::kUkmClientId, 0);
+  registry->RegisterListPref(prefs::kUkmPersistedLogs);
+}
+
+void UkmService::StartInitTask() {
+  DCHECK(thread_checker_.CalledOnValidThread());
+  DVLOG(1) << "UkmService::StartInitTask";
+  client_id_ = LoadClientId(pref_service_);
+  client_->InitializeSystemProfileMetrics(
+      base::Bind(&UkmService::FinishedInitTask,
+                 self_ptr_factory_.GetWeakPtr()));
+}
+
+void UkmService::FinishedInitTask() {
+  DCHECK(thread_checker_.CalledOnValidThread());
+  DVLOG(1) << "UkmService::FinishedInitTask";
+  scheduler_->InitTaskComplete();
+}
+
+void UkmService::RotateLog() {
+  DCHECK(thread_checker_.CalledOnValidThread());
+  DCHECK(!log_upload_in_progress_);
+  DVLOG(1) << "UkmService::RotateLog";
+  if (persisted_logs_.empty()) {
+    BuildAndStoreLog();
+  }
+  StartScheduledUpload();
+}
+
+void UkmService::BuildAndStoreLog() {
+  DCHECK(thread_checker_.CalledOnValidThread());
+  DVLOG(1) << "UkmService::BuildAndStoreLog";
+  Report report;
+  report.set_client_id(client_id_);
+  // TODO(holte): Populate system_profile.
+  // TODO(zhenw): Populate sources.
+  std::string serialized_log;
+  report.SerializeToString(&serialized_log);
+  persisted_logs_.StoreLog(serialized_log);
+}
+
+void UkmService::StartScheduledUpload() {
+  DCHECK(thread_checker_.CalledOnValidThread());
+  DCHECK(!log_upload_in_progress_);
+  persisted_logs_.StageLog();

[rkaplow, 2017/01/02 23:23:03]

just as a reminder can you add a TODO for various bandwidth issues (cellular,
etc.)

[Steven Holte, 2017/01/03 21:16:04]

Done.

+  if (!log_uploader_) {
+    log_uploader_ = client_->CreateUploader(
+        GetServerUrl(), kMimeType,
+        base::Bind(&UkmService::OnLogUploadComplete,
+                   self_ptr_factory_.GetWeakPtr()));
+  }
+  log_upload_in_progress_ = true;
+  log_uploader_->UploadLog(persisted_logs_.staged_log(),
+                           persisted_logs_.staged_log_hash());
+}
+
+void UkmService::OnLogUploadComplete(int response_code) {
+  DCHECK(thread_checker_.CalledOnValidThread());
+  DCHECK(log_upload_in_progress_);
+  DVLOG(1) << "UkmService::OnLogUploadComplete";
+  log_upload_in_progress_ = false;
+
+  // Log a histogram to track response success vs. failure rates.

[rkaplow, 2017/01/02 23:23:04]

I'd omit this comment - in the original metrics_service it made more sense since
the code was filtered but since we don't filter it isn't helpful

[Steven Holte, 2017/01/03 21:16:04]

Done.

+  UMA_HISTOGRAM_SPARSE_SLOWLY("UKM.Upload.ResponseCode", response_code);
+
+  bool upload_succeeded = response_code == 200;
+
+  // Provide boolean for error recovery (allow us to ignore response_code).
+  bool discard_log = false;
+  const size_t log_size = persisted_logs_.staged_log().length();

[rkaplow, 2017/01/02 23:23:04]

nit, would add _bytes for clarity

[Steven Holte, 2017/01/03 21:16:04]

Done.

+  if (upload_succeeded) {
+    UMA_HISTOGRAM_COUNTS_10000("UKM.LogSize.OnSuccess", log_size / 1024);
+  } else if (log_size > kUploadLogAvoidRetransmitSize) {
+    UMA_HISTOGRAM_COUNTS("UKM.OversizeRejected.LogSize",

[rkaplow, 2017/01/02 23:23:03]

prefer UMA_HISTOGRAM_COUNTS_1M

[Steven Holte, 2017/01/03 21:16:04]

Done.

+                         static_cast<int>(log_size));
+    discard_log = true;
+  } else if (response_code == 400) {
+    // Bad syntax.  Retransmission won't work.
+    discard_log = true;

[rkaplow, 2017/01/02 23:23:04]

should we add a metric to see if this occurs?

[Steven Holte, 2017/01/03 21:16:04]

This should be covered by the ResponseCode histogram.

+  }
+
+  if (upload_succeeded || discard_log) {
+    persisted_logs_.DiscardStagedLog();
+    // Store the updated list to disk now that the removed log is uploaded.
+    persisted_logs_.SerializeLogs();
+  }
+
+  // Error 400 indicates a problem with the log, not with the server, so
+  // don't consider that a sign that the server is in trouble.
+  bool server_is_healthy = upload_succeeded || response_code == 400;
+  scheduler_->UploadFinished(server_is_healthy, !persisted_logs_.empty());
+
+  if (server_is_healthy)
+    client_->OnLogUploadComplete();

[rkaplow, 2017/01/02 23:23:04]

I was looking for what this was doing and it seems like it's recording some
extra UMA metrics:

https://codesearch.chromium.org/chromium/src/chrome/browser/metrics/chrome_me...

which calls this:
https://codesearch.chromium.org/chromium/src/chrome/browser/metrics/time_tick...

I don't think this is needed here (and in fact not sure this is needed at all,
we should follow up since the metrics are unowned)

[Steven Holte, 2017/01/03 21:16:04]

Done.

+}
+
+}  // namespace ukm