components/metrics/metrics_service.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 //------------------------------------------------------------------------------
   6 // Description of the life cycle of a instance of MetricsService.
   7 //
   8 //  OVERVIEW
   9 //
  10 // A MetricsService instance is typically created at application startup.  It is
  11 // the central controller for the acquisition of log data, and the automatic
  12 // transmission of that log data to an external server.  Its major job is to
  13 // manage logs, grouping them for transmission, and transmitting them.  As part
  14 // of its grouping, MS finalizes logs by including some just-in-time gathered
  15 // memory statistics, snapshotting the current stats of numerous histograms,
  16 // closing the logs, translating to protocol buffer format, and compressing the
  17 // results for transmission.  Transmission includes submitting a compressed log
  18 // as data in a URL-post, and retransmitting (or retaining at process
  19 // termination) if the attempted transmission failed.  Retention across process
  20 // terminations is done using the the PrefServices facilities. The retained logs
  21 // (the ones that never got transmitted) are compressed and base64-encoded
  22 // before being persisted.
  23 //
  24 // Logs fall into one of two categories: "initial logs," and "ongoing logs."
  25 // There is at most one initial log sent for each complete run of Chrome (from
  26 // startup, to browser shutdown).  An initial log is generally transmitted some
  27 // short time (1 minute?) after startup, and includes stats such as recent crash
  28 // info, the number and types of plugins, etc.  The external server's response
  29 // to the initial log conceptually tells this MS if it should continue
  30 // transmitting logs (during this session). The server response can actually be
  31 // much more detailed, and always includes (at a minimum) how often additional
  32 // ongoing logs should be sent.
  33 //
  34 // After the above initial log, a series of ongoing logs will be transmitted.
  35 // The first ongoing log actually begins to accumulate information stating when
  36 // the MS was first constructed.  Note that even though the initial log is
  37 // commonly sent a full minute after startup, the initial log does not include
  38 // much in the way of user stats.   The most common interlog period (delay)
  39 // is 30 minutes. That time period starts when the first user action causes a
  40 // logging event.  This means that if there is no user action, there may be long
  41 // periods without any (ongoing) log transmissions.  Ongoing logs typically
  42 // contain very detailed records of user activities (ex: opened tab, closed
  43 // tab, fetched URL, maximized window, etc.)  In addition, just before an
  44 // ongoing log is closed out, a call is made to gather memory statistics.  Those
  45 // memory statistics are deposited into a histogram, and the log finalization
  46 // code is then called.  In the finalization, a call to a Histogram server
  47 // acquires a list of all local histograms that have been flagged for upload
  48 // to the UMA server.  The finalization also acquires the most recent number
  49 // of page loads, along with any counts of renderer or plugin crashes.
  50 //
  51 // When the browser shuts down, there will typically be a fragment of an ongoing
  52 // log that has not yet been transmitted.  At shutdown time, that fragment is
  53 // closed (including snapshotting histograms), and persisted, for potential
  54 // transmission during a future run of the product.
  55 //
  56 // There are two slightly abnormal shutdown conditions.  There is a
  57 // "disconnected scenario," and a "really fast startup and shutdown" scenario.
  58 // In the "never connected" situation, the user has (during the running of the
  59 // process) never established an internet connection.  As a result, attempts to
  60 // transmit the initial log have failed, and a lot(?) of data has accumulated in
  61 // the ongoing log (which didn't yet get closed, because there was never even a
  62 // contemplation of sending it).  There is also a kindred "lost connection"
  63 // situation, where a loss of connection prevented an ongoing log from being
  64 // transmitted, and a (still open) log was stuck accumulating a lot(?) of data,
  65 // while the earlier log retried its transmission.  In both of these
  66 // disconnected situations, two logs need to be, and are, persistently stored
  67 // for future transmission.
  68 //
  69 // The other unusual shutdown condition, termed "really fast startup and
  70 // shutdown," involves the deliberate user termination of the process before
  71 // the initial log is even formed or transmitted. In that situation, no logging
  72 // is done, but the historical crash statistics remain (unlogged) for inclusion
  73 // in a future run's initial log.  (i.e., we don't lose crash stats).
  74 //
  75 // With the above overview, we can now describe the state machine's various
  76 // states, based on the State enum specified in the state_ member.  Those states
  77 // are:
  78 //
  79 //  INITIALIZED,          // Constructor was called.
  80 //  INIT_TASK_SCHEDULED,  // Waiting for deferred init tasks to finish.
  81 //  INIT_TASK_DONE,       // Waiting for timer to send initial log.
  82 //  SENDING_LOGS,         // Sending logs and creating new ones when we run out.
  83 //
  84 // In more detail, we have:
  85 //
  86 //    INITIALIZED,            // Constructor was called.
  87 // The MS has been constructed, but has taken no actions to compose the
  88 // initial log.
  89 //
  90 //    INIT_TASK_SCHEDULED,    // Waiting for deferred init tasks to finish.
  91 // Typically about 30 seconds after startup, a task is sent to a second thread
  92 // (the file thread) to perform deferred (lower priority and slower)
  93 // initialization steps such as getting the list of plugins.  That task will
  94 // (when complete) make an async callback (via a Task) to indicate the
  95 // completion.
  96 //
  97 //    INIT_TASK_DONE,         // Waiting for timer to send initial log.
  98 // The callback has arrived, and it is now possible for an initial log to be
  99 // created.  This callback typically arrives back less than one second after
 100 // the deferred init task is dispatched.
 101 //
 102 //    SENDING_LOGS,  // Sending logs an creating new ones when we run out.
 103 // Logs from previous sessions have been loaded, and initial logs have been
 104 // created (an optional stability log and the first metrics log).  We will
 105 // send all of these logs, and when run out, we will start cutting new logs
 106 // to send.  We will also cut a new log if we expect a shutdown.
 107 //
 108 // The progression through the above states is simple, and sequential.
 109 // States proceed from INITIAL to SENDING_LOGS, and remain in the latter until
 110 // shutdown.
 111 //
 112 // Also note that whenever we successfully send a log, we mirror the list
 113 // of logs into the PrefService. This ensures that IF we crash, we won't start
 114 // up and retransmit our old logs again.
 115 //
 116 // Due to race conditions, it is always possible that a log file could be sent
 117 // twice.  For example, if a log file is sent, but not yet acknowledged by
 118 // the external server, and the user shuts down, then a copy of the log may be
 119 // saved for re-transmission.  These duplicates could be filtered out server
 120 // side, but are not expected to be a significant problem.
 121 //
 122 //
 123 //------------------------------------------------------------------------------
 124
 125 #include "components/metrics/metrics_service.h"
 126
 127 #include <algorithm>
 128
 129 #include "base/bind.h"
 130 #include "base/callback.h"
 131 #include "base/location.h"
 132 #include "base/metrics/histogram.h"
 133 #include "base/metrics/histogram_base.h"
 134 #include "base/metrics/histogram_samples.h"
 135 #include "base/metrics/sparse_histogram.h"
 136 #include "base/metrics/statistics_recorder.h"
 137 #include "base/prefs/pref_registry_simple.h"
 138 #include "base/prefs/pref_service.h"
 139 #include "base/single_thread_task_runner.h"
 140 #include "base/strings/string_number_conversions.h"
 141 #include "base/strings/utf_string_conversions.h"
 142 #include "base/thread_task_runner_handle.h"
 143 #include "base/threading/platform_thread.h"
 144 #include "base/threading/thread.h"
 145 #include "base/threading/thread_restrictions.h"
 146 #include "base/time/time.h"
 147 #include "base/tracked_objects.h"
 148 #include "base/values.h"
 149 #include "components/metrics/metrics_log.h"
 150 #include "components/metrics/metrics_log_manager.h"
 151 #include "components/metrics/metrics_log_uploader.h"
 152 #include "components/metrics/metrics_pref_names.h"
 153 #include "components/metrics/metrics_reporting_scheduler.h"
 154 #include "components/metrics/metrics_service_client.h"
 155 #include "components/metrics/metrics_state_manager.h"
 156 #include "components/variations/entropy_provider.h"
 157
 158 namespace metrics {
 159
 160 namespace {
 161
 162 // Check to see that we're being called on only one thread.
 163 bool IsSingleThreaded() {
 164   static base::PlatformThreadId thread_id = 0;
 165   if (!thread_id)
 166     thread_id = base::PlatformThread::CurrentId();
 167   return base::PlatformThread::CurrentId() == thread_id;
 168 }
 169
 170 // The delay, in seconds, after starting recording before doing expensive
 171 // initialization work.
 172 #if defined(OS_ANDROID) || defined(OS_IOS)
 173 // On mobile devices, a significant portion of sessions last less than a minute.
 174 // Use a shorter timer on these platforms to avoid losing data.
 175 // TODO(dfalcantara): To avoid delaying startup, tighten up initialization so
 176 //                    that it occurs after the user gets their initial page.
 177 const int kInitializationDelaySeconds = 5;
 178 #else
 179 const int kInitializationDelaySeconds = 30;
 180 #endif
 181
 182 // The maximum number of events in a log uploaded to the UMA server.
 183 const int kEventLimit = 2400;
 184
 185 // If an upload fails, and the transmission was over this byte count, then we
 186 // will discard the log, and not try to retransmit it.  We also don't persist
 187 // the log to the prefs for transmission during the next chrome session if this
 188 // limit is exceeded.
 189 const size_t kUploadLogAvoidRetransmitSize = 100 * 1024;
 190
 191 // Interval, in minutes, between state saves.
 192 const int kSaveStateIntervalMinutes = 5;
 193
 194 enum ResponseStatus {
 195   UNKNOWN_FAILURE,
 196   SUCCESS,
 197   BAD_REQUEST,  // Invalid syntax or log too large.
 198   NO_RESPONSE,
 199   NUM_RESPONSE_STATUSES
 200 };
 201
 202 ResponseStatus ResponseCodeToStatus(int response_code) {
 203   switch (response_code) {
 204     case -1:
 205       return NO_RESPONSE;
 206     case 200:
 207       return SUCCESS;
 208     case 400:
 209       return BAD_REQUEST;
 210     default:
 211       return UNKNOWN_FAILURE;
 212   }
 213 }
 214
 215 #if defined(OS_ANDROID) || defined(OS_IOS)
 216 void MarkAppCleanShutdownAndCommit(CleanExitBeacon* clean_exit_beacon,
 217                                    PrefService* local_state) {
 218   clean_exit_beacon->WriteBeaconValue(true);
 219   local_state->SetInteger(prefs::kStabilityExecutionPhase,
 220                           MetricsService::SHUTDOWN_COMPLETE);
 221   // Start writing right away (write happens on a different thread).
 222   local_state->CommitPendingWrite();
 223 }
 224 #endif  // defined(OS_ANDROID) || defined(OS_IOS)
 225
 226 }  // namespace
 227
 228
 229 SyntheticTrialGroup::SyntheticTrialGroup(uint32 trial, uint32 group) {
 230   id.name = trial;
 231   id.group = group;
 232 }
 233
 234 SyntheticTrialGroup::~SyntheticTrialGroup() {
 235 }
 236
 237 // static
 238 MetricsService::ShutdownCleanliness MetricsService::clean_shutdown_status_ =
 239     MetricsService::CLEANLY_SHUTDOWN;
 240
 241 MetricsService::ExecutionPhase MetricsService::execution_phase_ =
 242     MetricsService::UNINITIALIZED_PHASE;
 243
 244 // static
 245 void MetricsService::RegisterPrefs(PrefRegistrySimple* registry) {
 246   DCHECK(IsSingleThreaded());
 247   MetricsStateManager::RegisterPrefs(registry);
 248   MetricsLog::RegisterPrefs(registry);
 249
 250   registry->RegisterInt64Pref(prefs::kInstallDate, 0);
 251
 252   registry->RegisterInt64Pref(prefs::kStabilityLaunchTimeSec, 0);
 253   registry->RegisterInt64Pref(prefs::kStabilityLastTimestampSec, 0);
 254   registry->RegisterStringPref(prefs::kStabilityStatsVersion, std::string());
 255   registry->RegisterInt64Pref(prefs::kStabilityStatsBuildTime, 0);
 256   registry->RegisterBooleanPref(prefs::kStabilityExitedCleanly, true);
 257   registry->RegisterIntegerPref(prefs::kStabilityExecutionPhase,
 258                                 UNINITIALIZED_PHASE);
 259   registry->RegisterBooleanPref(prefs::kStabilitySessionEndCompleted, true);
 260   registry->RegisterIntegerPref(prefs::kMetricsSessionID, -1);
 261
 262   registry->RegisterListPref(prefs::kMetricsInitialLogs);
 263   registry->RegisterListPref(prefs::kMetricsOngoingLogs);
 264
 265   registry->RegisterInt64Pref(prefs::kUninstallLaunchCount, 0);
 266   registry->RegisterInt64Pref(prefs::kUninstallMetricsUptimeSec, 0);
 267 }
 268
 269 MetricsService::MetricsService(MetricsStateManager* state_manager,
 270                                MetricsServiceClient* client,
 271                                PrefService* local_state)
 272     : log_manager_(local_state, kUploadLogAvoidRetransmitSize),
 273       histogram_snapshot_manager_(this),
 274       state_manager_(state_manager),
 275       client_(client),
 276       local_state_(local_state),
 277       clean_exit_beacon_(client->GetRegistryBackupKey(), local_state),
 278       recording_active_(false),
 279       reporting_active_(false),
 280       test_mode_active_(false),
 281       state_(INITIALIZED),
 282       log_upload_in_progress_(false),
 283       idle_since_last_transmission_(false),
 284       session_id_(-1),
 285       self_ptr_factory_(this),
 286       state_saver_factory_(this) {
 287   DCHECK(IsSingleThreaded());
 288   DCHECK(state_manager_);
 289   DCHECK(client_);
 290   DCHECK(local_state_);
 291
 292   // Set the install date if this is our first run.
 293   int64 install_date = local_state_->GetInt64(prefs::kInstallDate);
 294   if (install_date == 0)
 295     local_state_->SetInt64(prefs::kInstallDate, base::Time::Now().ToTimeT());
 296 }
 297
 298 MetricsService::~MetricsService() {
 299   DisableRecording();
 300 }
 301
 302 void MetricsService::InitializeMetricsRecordingState() {
 303   InitializeMetricsState();
 304
 305   base::Closure upload_callback =
 306       base::Bind(&MetricsService::StartScheduledUpload,
 307                  self_ptr_factory_.GetWeakPtr());
 308   scheduler_.reset(
 309       new MetricsReportingScheduler(
 310           upload_callback,
 311           // MetricsServiceClient outlives MetricsService, and
 312           // MetricsReportingScheduler is tied to the lifetime of |this|.
 313           base::Bind(&MetricsServiceClient::GetStandardUploadInterval,
 314                      base::Unretained(client_))));
 315 }
 316
 317 void MetricsService::Start() {
 318   HandleIdleSinceLastTransmission(false);
 319   EnableRecording();
 320   EnableReporting();
 321 }
 322
 323 bool MetricsService::StartIfMetricsReportingEnabled() {
 324   const bool enabled = state_manager_->IsMetricsReportingEnabled();
 325   if (enabled)
 326     Start();
 327   return enabled;
 328 }
 329
 330 void MetricsService::StartRecordingForTests() {
 331   test_mode_active_ = true;
 332   EnableRecording();
 333   DisableReporting();
 334 }
 335
 336 void MetricsService::Stop() {
 337   HandleIdleSinceLastTransmission(false);
 338   DisableReporting();
 339   DisableRecording();
 340 }
 341
 342 void MetricsService::EnableReporting() {
 343   if (reporting_active_)
 344     return;
 345   reporting_active_ = true;
 346   StartSchedulerIfNecessary();
 347 }
 348
 349 void MetricsService::DisableReporting() {
 350   reporting_active_ = false;
 351 }
 352
 353 std::string MetricsService::GetClientId() {
 354   return state_manager_->client_id();
 355 }
 356
 357 int64 MetricsService::GetInstallDate() {
 358   return local_state_->GetInt64(prefs::kInstallDate);
 359 }
 360
 361 int64 MetricsService::GetMetricsReportingEnabledDate() {
 362   return local_state_->GetInt64(prefs::kMetricsReportingEnabledTimestamp);
 363 }
 364
 365 scoped_ptr<const base::FieldTrial::EntropyProvider>
 366 MetricsService::CreateEntropyProvider() {
 367   // TODO(asvitkine): Refactor the code so that MetricsService does not expose
 368   // this method.
 369   return state_manager_->CreateEntropyProvider();
 370 }
 371
 372 void MetricsService::EnableRecording() {
 373   DCHECK(IsSingleThreaded());
 374
 375   if (recording_active_)
 376     return;
 377   recording_active_ = true;
 378
 379   state_manager_->ForceClientIdCreation();
 380   client_->SetMetricsClientId(state_manager_->client_id());
 381   if (!log_manager_.current_log())
 382     OpenNewLog();
 383
 384   for (size_t i = 0; i < metrics_providers_.size(); ++i)
 385     metrics_providers_[i]->OnRecordingEnabled();
 386
 387   base::RemoveActionCallback(action_callback_);
 388   action_callback_ = base::Bind(&MetricsService::OnUserAction,
 389                                 base::Unretained(this));
 390   base::AddActionCallback(action_callback_);
 391 }
 392
 393 void MetricsService::DisableRecording() {
 394   DCHECK(IsSingleThreaded());
 395
 396   if (!recording_active_)
 397     return;
 398   recording_active_ = false;
 399
 400   client_->OnRecordingDisabled();
 401
 402   base::RemoveActionCallback(action_callback_);
 403
 404   for (size_t i = 0; i < metrics_providers_.size(); ++i)
 405     metrics_providers_[i]->OnRecordingDisabled();
 406
 407   PushPendingLogsToPersistentStorage();
 408 }
 409
 410 bool MetricsService::recording_active() const {
 411   DCHECK(IsSingleThreaded());
 412   return recording_active_;
 413 }
 414
 415 bool MetricsService::reporting_active() const {
 416   DCHECK(IsSingleThreaded());
 417   return reporting_active_;
 418 }
 419
 420 void MetricsService::RecordDelta(const base::HistogramBase& histogram,
 421                                  const base::HistogramSamples& snapshot) {
 422   log_manager_.current_log()->RecordHistogramDelta(histogram.histogram_name(),
 423                                                    snapshot);
 424 }
 425
 426 void MetricsService::InconsistencyDetected(
 427     base::HistogramBase::Inconsistency problem) {
 428   UMA_HISTOGRAM_ENUMERATION("Histogram.InconsistenciesBrowser",
 429                             problem, base::HistogramBase::NEVER_EXCEEDED_VALUE);
 430 }
 431
 432 void MetricsService::UniqueInconsistencyDetected(
 433     base::HistogramBase::Inconsistency problem) {
 434   UMA_HISTOGRAM_ENUMERATION("Histogram.InconsistenciesBrowserUnique",
 435                             problem, base::HistogramBase::NEVER_EXCEEDED_VALUE);
 436 }
 437
 438 void MetricsService::InconsistencyDetectedInLoggedCount(int amount) {
 439   UMA_HISTOGRAM_COUNTS("Histogram.InconsistentSnapshotBrowser",
 440                        std::abs(amount));
 441 }
 442
 443 void MetricsService::HandleIdleSinceLastTransmission(bool in_idle) {
 444   // If there wasn't a lot of action, maybe the computer was asleep, in which
 445   // case, the log transmissions should have stopped.  Here we start them up
 446   // again.
 447   if (!in_idle && idle_since_last_transmission_)
 448     StartSchedulerIfNecessary();
 449   idle_since_last_transmission_ = in_idle;
 450 }
 451
 452 void MetricsService::OnApplicationNotIdle() {
 453   if (recording_active_)
 454     HandleIdleSinceLastTransmission(false);
 455 }
 456
 457 void MetricsService::RecordStartOfSessionEnd() {
 458   LogCleanShutdown();
 459   RecordBooleanPrefValue(prefs::kStabilitySessionEndCompleted, false);
 460 }
 461
 462 void MetricsService::RecordCompletedSessionEnd() {
 463   LogCleanShutdown();
 464   RecordBooleanPrefValue(prefs::kStabilitySessionEndCompleted, true);
 465 }
 466
 467 #if defined(OS_ANDROID) || defined(OS_IOS)
 468 void MetricsService::OnAppEnterBackground() {
 469   scheduler_->Stop();
 470
 471   MarkAppCleanShutdownAndCommit(&clean_exit_beacon_, local_state_);
 472
 473   // At this point, there's no way of knowing when the process will be
 474   // killed, so this has to be treated similar to a shutdown, closing and
 475   // persisting all logs. Unlinke a shutdown, the state is primed to be ready
 476   // to continue logging and uploading if the process does return.
 477   if (recording_active() && state_ >= SENDING_LOGS) {
 478     PushPendingLogsToPersistentStorage();
 479     // Persisting logs closes the current log, so start recording a new log
 480     // immediately to capture any background work that might be done before the
 481     // process is killed.
 482     OpenNewLog();
 483   }
 484 }
 485
 486 void MetricsService::OnAppEnterForeground() {
 487   clean_exit_beacon_.WriteBeaconValue(false);
 488   StartSchedulerIfNecessary();
 489 }
 490 #else
 491 void MetricsService::LogNeedForCleanShutdown() {
 492   clean_exit_beacon_.WriteBeaconValue(false);
 493   // Redundant setting to be sure we call for a clean shutdown.
 494   clean_shutdown_status_ = NEED_TO_SHUTDOWN;
 495 }
 496 #endif  // defined(OS_ANDROID) || defined(OS_IOS)
 497
 498 // static
 499 void MetricsService::SetExecutionPhase(ExecutionPhase execution_phase,
 500                                        PrefService* local_state) {
 501   execution_phase_ = execution_phase;
 502   local_state->SetInteger(prefs::kStabilityExecutionPhase, execution_phase_);
 503 }
 504
 505 void MetricsService::RecordBreakpadRegistration(bool success) {
 506   if (!success)
 507     IncrementPrefValue(prefs::kStabilityBreakpadRegistrationFail);
 508   else
 509     IncrementPrefValue(prefs::kStabilityBreakpadRegistrationSuccess);
 510 }
 511
 512 void MetricsService::RecordBreakpadHasDebugger(bool has_debugger) {
 513   if (!has_debugger)
 514     IncrementPrefValue(prefs::kStabilityDebuggerNotPresent);
 515   else
 516     IncrementPrefValue(prefs::kStabilityDebuggerPresent);
 517 }
 518
 519 void MetricsService::ClearSavedStabilityMetrics() {
 520   for (size_t i = 0; i < metrics_providers_.size(); ++i)
 521     metrics_providers_[i]->ClearSavedStabilityMetrics();
 522
 523   // Reset the prefs that are managed by MetricsService/MetricsLog directly.
 524   local_state_->SetInteger(prefs::kStabilityCrashCount, 0);
 525   local_state_->SetInteger(prefs::kStabilityExecutionPhase,
 526                            UNINITIALIZED_PHASE);
 527   local_state_->SetInteger(prefs::kStabilityIncompleteSessionEndCount, 0);
 528   local_state_->SetInteger(prefs::kStabilityLaunchCount, 0);
 529   local_state_->SetBoolean(prefs::kStabilitySessionEndCompleted, true);
 530 }
 531
 532 void MetricsService::PushExternalLog(const std::string& log) {
 533   log_manager_.StoreLog(log, MetricsLog::ONGOING_LOG);
 534 }
 535
 536 //------------------------------------------------------------------------------
 537 // private methods
 538 //------------------------------------------------------------------------------
 539
 540
 541 //------------------------------------------------------------------------------
 542 // Initialization methods
 543
 544 void MetricsService::InitializeMetricsState() {
 545   const int64 buildtime = MetricsLog::GetBuildTime();
 546   const std::string version = client_->GetVersionString();
 547   bool version_changed = false;
 548   if (local_state_->GetInt64(prefs::kStabilityStatsBuildTime) != buildtime ||
 549       local_state_->GetString(prefs::kStabilityStatsVersion) != version) {
 550     local_state_->SetString(prefs::kStabilityStatsVersion, version);
 551     local_state_->SetInt64(prefs::kStabilityStatsBuildTime, buildtime);
 552     version_changed = true;
 553   }
 554
 555   log_manager_.LoadPersistedUnsentLogs();
 556
 557   session_id_ = local_state_->GetInteger(prefs::kMetricsSessionID);
 558
 559   if (!clean_exit_beacon_.exited_cleanly()) {
 560     IncrementPrefValue(prefs::kStabilityCrashCount);
 561     // Reset flag, and wait until we call LogNeedForCleanShutdown() before
 562     // monitoring.
 563     clean_exit_beacon_.WriteBeaconValue(true);
 564   }
 565
 566   bool has_initial_stability_log = false;
 567   if (!clean_exit_beacon_.exited_cleanly() ||
 568       ProvidersHaveInitialStabilityMetrics()) {
 569     // TODO(rtenneti): On windows, consider saving/getting execution_phase from
 570     // the registry.
 571     int execution_phase =
 572         local_state_->GetInteger(prefs::kStabilityExecutionPhase);
 573     UMA_HISTOGRAM_SPARSE_SLOWLY("Chrome.Browser.CrashedExecutionPhase",
 574                                 execution_phase);
 575
 576     // If the previous session didn't exit cleanly, or if any provider
 577     // explicitly requests it, prepare an initial stability log -
 578     // provided UMA is enabled.
 579     if (state_manager_->IsMetricsReportingEnabled())
 580       has_initial_stability_log = PrepareInitialStabilityLog();
 581   }
 582
 583   // If no initial stability log was generated and there was a version upgrade,
 584   // clear the stability stats from the previous version (so that they don't get
 585   // attributed to the current version). This could otherwise happen due to a
 586   // number of different edge cases, such as if the last version crashed before
 587   // it could save off a system profile or if UMA reporting is disabled (which
 588   // normally results in stats being accumulated).
 589   if (!has_initial_stability_log && version_changed)
 590     ClearSavedStabilityMetrics();
 591
 592   // Update session ID.
 593   ++session_id_;
 594   local_state_->SetInteger(prefs::kMetricsSessionID, session_id_);
 595
 596   // Stability bookkeeping
 597   IncrementPrefValue(prefs::kStabilityLaunchCount);
 598
 599   DCHECK_EQ(UNINITIALIZED_PHASE, execution_phase_);
 600   SetExecutionPhase(START_METRICS_RECORDING, local_state_);
 601
 602   if (!local_state_->GetBoolean(prefs::kStabilitySessionEndCompleted)) {
 603     IncrementPrefValue(prefs::kStabilityIncompleteSessionEndCount);
 604     // This is marked false when we get a WM_ENDSESSION.
 605     local_state_->SetBoolean(prefs::kStabilitySessionEndCompleted, true);
 606   }
 607
 608   // Call GetUptimes() for the first time, thus allowing all later calls
 609   // to record incremental uptimes accurately.
 610   base::TimeDelta ignored_uptime_parameter;
 611   base::TimeDelta startup_uptime;
 612   GetUptimes(local_state_, &startup_uptime, &ignored_uptime_parameter);
 613   DCHECK_EQ(0, startup_uptime.InMicroseconds());
 614   // For backwards compatibility, leave this intact in case Omaha is checking
 615   // them.  prefs::kStabilityLastTimestampSec may also be useless now.
 616   // TODO(jar): Delete these if they have no uses.
 617   local_state_->SetInt64(prefs::kStabilityLaunchTimeSec,
 618                          base::Time::Now().ToTimeT());
 619
 620   // Bookkeeping for the uninstall metrics.
 621   IncrementLongPrefsValue(prefs::kUninstallLaunchCount);
 622
 623   // Kick off the process of saving the state (so the uptime numbers keep
 624   // getting updated) every n minutes.
 625   ScheduleNextStateSave();
 626 }
 627
 628 void MetricsService::OnUserAction(const std::string& action) {
 629   if (!ShouldLogEvents())
 630     return;
 631
 632   log_manager_.current_log()->RecordUserAction(action);
 633   HandleIdleSinceLastTransmission(false);
 634 }
 635
 636 void MetricsService::FinishedGatheringInitialMetrics() {
 637   DCHECK_EQ(INIT_TASK_SCHEDULED, state_);
 638   state_ = INIT_TASK_DONE;
 639
 640   // Create the initial log.
 641   if (!initial_metrics_log_.get()) {
 642     initial_metrics_log_ = CreateLog(MetricsLog::ONGOING_LOG);
 643     NotifyOnDidCreateMetricsLog();
 644   }
 645
 646   scheduler_->InitTaskComplete();
 647 }
 648
 649 void MetricsService::GetUptimes(PrefService* pref,
 650                                 base::TimeDelta* incremental_uptime,
 651                                 base::TimeDelta* uptime) {
 652   base::TimeTicks now = base::TimeTicks::Now();
 653   // If this is the first call, init |first_updated_time_| and
 654   // |last_updated_time_|.
 655   if (last_updated_time_.is_null()) {
 656     first_updated_time_ = now;
 657     last_updated_time_ = now;
 658   }
 659   *incremental_uptime = now - last_updated_time_;
 660   *uptime = now - first_updated_time_;
 661   last_updated_time_ = now;
 662
 663   const int64 incremental_time_secs = incremental_uptime->InSeconds();
 664   if (incremental_time_secs > 0) {
 665     int64 metrics_uptime = pref->GetInt64(prefs::kUninstallMetricsUptimeSec);
 666     metrics_uptime += incremental_time_secs;
 667     pref->SetInt64(prefs::kUninstallMetricsUptimeSec, metrics_uptime);
 668   }
 669 }
 670
 671 void MetricsService::NotifyOnDidCreateMetricsLog() {
 672   DCHECK(IsSingleThreaded());
 673   for (size_t i = 0; i < metrics_providers_.size(); ++i)
 674     metrics_providers_[i]->OnDidCreateMetricsLog();
 675 }
 676
 677 //------------------------------------------------------------------------------
 678 // State save methods
 679
 680 void MetricsService::ScheduleNextStateSave() {
 681   state_saver_factory_.InvalidateWeakPtrs();
 682
 683   base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
 684       FROM_HERE, base::Bind(&MetricsService::SaveLocalState,
 685                             state_saver_factory_.GetWeakPtr()),
 686       base::TimeDelta::FromMinutes(kSaveStateIntervalMinutes));
 687 }
 688
 689 void MetricsService::SaveLocalState() {
 690   RecordCurrentState(local_state_);
 691
 692   // TODO(jar):110021 Does this run down the batteries????
 693   ScheduleNextStateSave();
 694 }
 695
 696
 697 //------------------------------------------------------------------------------
 698 // Recording control methods
 699
 700 void MetricsService::OpenNewLog() {
 701   DCHECK(!log_manager_.current_log());
 702
 703   log_manager_.BeginLoggingWithLog(CreateLog(MetricsLog::ONGOING_LOG));
 704   NotifyOnDidCreateMetricsLog();
 705   if (state_ == INITIALIZED) {
 706     // We only need to schedule that run once.
 707     state_ = INIT_TASK_SCHEDULED;
 708
 709     base::ThreadTaskRunnerHandle::Get()->PostDelayedTask(
 710         FROM_HERE, base::Bind(&MetricsService::StartGatheringMetrics,
 711                               self_ptr_factory_.GetWeakPtr()),
 712         base::TimeDelta::FromSeconds(kInitializationDelaySeconds));
 713   }
 714 }
 715
 716 void MetricsService::StartGatheringMetrics() {
 717   client_->StartGatheringMetrics(
 718       base::Bind(&MetricsService::FinishedGatheringInitialMetrics,
 719                  self_ptr_factory_.GetWeakPtr()));
 720 }
 721
 722 void MetricsService::CloseCurrentLog() {
 723   if (!log_manager_.current_log())
 724     return;
 725
 726   // TODO(jar): Integrate bounds on log recording more consistently, so that we
 727   // can stop recording logs that are too big much sooner.
 728   if (log_manager_.current_log()->num_events() > kEventLimit) {
 729     UMA_HISTOGRAM_COUNTS("UMA.Discarded Log Events",
 730                          log_manager_.current_log()->num_events());
 731     log_manager_.DiscardCurrentLog();
 732     OpenNewLog();  // Start trivial log to hold our histograms.
 733   }
 734
 735   // Put incremental data (histogram deltas, and realtime stats deltas) at the
 736   // end of all log transmissions (initial log handles this separately).
 737   // RecordIncrementalStabilityElements only exists on the derived
 738   // MetricsLog class.
 739   MetricsLog* current_log = log_manager_.current_log();
 740   DCHECK(current_log);
 741   RecordCurrentEnvironment(current_log);
 742   base::TimeDelta incremental_uptime;
 743   base::TimeDelta uptime;
 744   GetUptimes(local_state_, &incremental_uptime, &uptime);
 745   current_log->RecordStabilityMetrics(metrics_providers_.get(),
 746                                       incremental_uptime, uptime);
 747
 748   current_log->RecordGeneralMetrics(metrics_providers_.get());
 749   RecordCurrentHistograms();
 750
 751   log_manager_.FinishCurrentLog();
 752 }
 753
 754 void MetricsService::PushPendingLogsToPersistentStorage() {
 755   if (state_ < SENDING_LOGS)
 756     return;  // We didn't and still don't have time to get plugin list etc.
 757
 758   CloseCurrentLog();
 759   log_manager_.PersistUnsentLogs();
 760 }
 761
 762 //------------------------------------------------------------------------------
 763 // Transmission of logs methods
 764
 765 void MetricsService::StartSchedulerIfNecessary() {
 766   // Never schedule cutting or uploading of logs in test mode.
 767   if (test_mode_active_)
 768     return;
 769
 770   // Even if reporting is disabled, the scheduler is needed to trigger the
 771   // creation of the initial log, which must be done in order for any logs to be
 772   // persisted on shutdown or backgrounding.
 773   if (recording_active() &&
 774       (reporting_active() || state_ < SENDING_LOGS)) {
 775     scheduler_->Start();
 776   }
 777 }
 778
 779 void MetricsService::StartScheduledUpload() {
 780   DCHECK(state_ >= INIT_TASK_DONE);
 781   // If we're getting no notifications, then the log won't have much in it, and
 782   // it's possible the computer is about to go to sleep, so don't upload and
 783   // stop the scheduler.
 784   // If recording has been turned off, the scheduler doesn't need to run.
 785   // If reporting is off, proceed if the initial log hasn't been created, since
 786   // that has to happen in order for logs to be cut and stored when persisting.
 787   // TODO(stuartmorgan): Call Stop() on the scheduler when reporting and/or
 788   // recording are turned off instead of letting it fire and then aborting.
 789   if (idle_since_last_transmission_ ||
 790       !recording_active() ||
 791       (!reporting_active() && state_ >= SENDING_LOGS)) {
 792     scheduler_->Stop();
 793     scheduler_->UploadCancelled();
 794     return;
 795   }
 796
 797   // If there are unsent logs, send the next one. If not, start the asynchronous
 798   // process of finalizing the current log for upload.
 799   if (state_ == SENDING_LOGS && log_manager_.has_unsent_logs()) {
 800     SendNextLog();
 801   } else {
 802     // There are no logs left to send, so start creating a new one.
 803     client_->CollectFinalMetrics(
 804         base::Bind(&MetricsService::OnFinalLogInfoCollectionDone,
 805                    self_ptr_factory_.GetWeakPtr()));
 806   }
 807 }
 808
 809 void MetricsService::OnFinalLogInfoCollectionDone() {
 810   // If somehow there is a log upload in progress, we return and hope things
 811   // work out. The scheduler isn't informed since if this happens, the scheduler
 812   // will get a response from the upload.
 813   DCHECK(!log_upload_in_progress_);
 814   if (log_upload_in_progress_)
 815     return;
 816
 817   // Abort if metrics were turned off during the final info gathering.
 818   if (!recording_active()) {
 819     scheduler_->Stop();
 820     scheduler_->UploadCancelled();
 821     return;
 822   }
 823
 824   if (state_ == INIT_TASK_DONE) {
 825     PrepareInitialMetricsLog();
 826   } else {
 827     DCHECK_EQ(SENDING_LOGS, state_);
 828     CloseCurrentLog();
 829     OpenNewLog();
 830   }
 831   SendNextLog();
 832 }
 833
 834 void MetricsService::SendNextLog() {
 835   DCHECK_EQ(SENDING_LOGS, state_);
 836   if (!reporting_active()) {
 837     scheduler_->Stop();
 838     scheduler_->UploadCancelled();
 839     return;
 840   }
 841   if (!log_manager_.has_unsent_logs()) {
 842     // Should only get here if serializing the log failed somehow.
 843     // Just tell the scheduler it was uploaded and wait for the next log
 844     // interval.
 845     scheduler_->UploadFinished(true, log_manager_.has_unsent_logs());
 846     return;
 847   }
 848   if (!log_manager_.has_staged_log())
 849     log_manager_.StageNextLogForUpload();
 850   SendStagedLog();
 851 }
 852
 853 bool MetricsService::ProvidersHaveInitialStabilityMetrics() {
 854   // Check whether any metrics provider has initial stability metrics.
 855   for (size_t i = 0; i < metrics_providers_.size(); ++i) {
 856     if (metrics_providers_[i]->HasInitialStabilityMetrics())
 857       return true;
 858   }
 859
 860   return false;
 861 }
 862
 863 bool MetricsService::PrepareInitialStabilityLog() {
 864   DCHECK_EQ(INITIALIZED, state_);
 865
 866   scoped_ptr<MetricsLog> initial_stability_log(
 867       CreateLog(MetricsLog::INITIAL_STABILITY_LOG));
 868
 869   // Do not call NotifyOnDidCreateMetricsLog here because the stability
 870   // log describes stats from the _previous_ session.
 871
 872   if (!initial_stability_log->LoadSavedEnvironmentFromPrefs())
 873     return false;
 874
 875   log_manager_.PauseCurrentLog();
 876   log_manager_.BeginLoggingWithLog(initial_stability_log.Pass());
 877
 878   // Note: Some stability providers may record stability stats via histograms,
 879   //       so this call has to be after BeginLoggingWithLog().
 880   log_manager_.current_log()->RecordStabilityMetrics(
 881       metrics_providers_.get(), base::TimeDelta(), base::TimeDelta());
 882   RecordCurrentStabilityHistograms();
 883
 884   // Note: RecordGeneralMetrics() intentionally not called since this log is for
 885   //       stability stats from a previous session only.
 886
 887   log_manager_.FinishCurrentLog();
 888   log_manager_.ResumePausedLog();
 889
 890   // Store unsent logs, including the stability log that was just saved, so
 891   // that they're not lost in case of a crash before upload time.
 892   log_manager_.PersistUnsentLogs();
 893
 894   return true;
 895 }
 896
 897 void MetricsService::PrepareInitialMetricsLog() {
 898   DCHECK_EQ(INIT_TASK_DONE, state_);
 899
 900   RecordCurrentEnvironment(initial_metrics_log_.get());
 901   base::TimeDelta incremental_uptime;
 902   base::TimeDelta uptime;
 903   GetUptimes(local_state_, &incremental_uptime, &uptime);
 904
 905   // Histograms only get written to the current log, so make the new log current
 906   // before writing them.
 907   log_manager_.PauseCurrentLog();
 908   log_manager_.BeginLoggingWithLog(initial_metrics_log_.Pass());
 909
 910   // Note: Some stability providers may record stability stats via histograms,
 911   //       so this call has to be after BeginLoggingWithLog().
 912   MetricsLog* current_log = log_manager_.current_log();
 913   current_log->RecordStabilityMetrics(metrics_providers_.get(),
 914                                       base::TimeDelta(), base::TimeDelta());
 915   current_log->RecordGeneralMetrics(metrics_providers_.get());
 916   RecordCurrentHistograms();
 917
 918   log_manager_.FinishCurrentLog();
 919   log_manager_.ResumePausedLog();
 920
 921   // Store unsent logs, including the initial log that was just saved, so
 922   // that they're not lost in case of a crash before upload time.
 923   log_manager_.PersistUnsentLogs();
 924
 925   state_ = SENDING_LOGS;
 926 }
 927
 928 void MetricsService::SendStagedLog() {
 929   DCHECK(log_manager_.has_staged_log());
 930   if (!log_manager_.has_staged_log())
 931     return;
 932
 933   DCHECK(!log_upload_in_progress_);
 934   log_upload_in_progress_ = true;
 935
 936   if (!log_uploader_) {
 937     log_uploader_ = client_->CreateUploader(
 938         base::Bind(&MetricsService::OnLogUploadComplete,
 939                    self_ptr_factory_.GetWeakPtr()));
 940   }
 941
 942   const std::string hash =
 943       base::HexEncode(log_manager_.staged_log_hash().data(),
 944                       log_manager_.staged_log_hash().size());
 945   bool success = log_uploader_->UploadLog(log_manager_.staged_log(), hash);
 946   UMA_HISTOGRAM_BOOLEAN("UMA.UploadCreation", success);
 947   if (!success) {
 948     // Skip this upload and hope things work out next time.
 949     log_manager_.DiscardStagedLog();
 950     scheduler_->UploadCancelled();
 951     log_upload_in_progress_ = false;
 952     return;
 953   }
 954
 955   HandleIdleSinceLastTransmission(true);
 956 }
 957
 958
 959 void MetricsService::OnLogUploadComplete(int response_code) {
 960   DCHECK_EQ(SENDING_LOGS, state_);
 961   DCHECK(log_upload_in_progress_);
 962   log_upload_in_progress_ = false;
 963
 964   // Log a histogram to track response success vs. failure rates.
 965   UMA_HISTOGRAM_ENUMERATION("UMA.UploadResponseStatus.Protobuf",
 966                             ResponseCodeToStatus(response_code),
 967                             NUM_RESPONSE_STATUSES);
 968
 969   bool upload_succeeded = response_code == 200;
 970
 971   // Provide boolean for error recovery (allow us to ignore response_code).
 972   bool discard_log = false;
 973   const size_t log_size = log_manager_.staged_log().length();
 974   if (upload_succeeded) {
 975     UMA_HISTOGRAM_COUNTS_10000("UMA.LogSize.OnSuccess", log_size / 1024);
 976   } else if (log_size > kUploadLogAvoidRetransmitSize) {
 977     UMA_HISTOGRAM_COUNTS("UMA.Large Rejected Log was Discarded",
 978                          static_cast<int>(log_size));
 979     discard_log = true;
 980   } else if (response_code == 400) {
 981     // Bad syntax.  Retransmission won't work.
 982     discard_log = true;
 983   }
 984
 985   if (upload_succeeded || discard_log) {
 986     log_manager_.DiscardStagedLog();
 987     // Store the updated list to disk now that the removed log is uploaded.
 988     log_manager_.PersistUnsentLogs();
 989   }
 990
 991   // Error 400 indicates a problem with the log, not with the server, so
 992   // don't consider that a sign that the server is in trouble.
 993   bool server_is_healthy = upload_succeeded || response_code == 400;
 994   scheduler_->UploadFinished(server_is_healthy, log_manager_.has_unsent_logs());
 995
 996   if (server_is_healthy)
 997     client_->OnLogUploadComplete();
 998 }
 999
1000 void MetricsService::IncrementPrefValue(const char* path) {
1001   int value = local_state_->GetInteger(path);
1002   local_state_->SetInteger(path, value + 1);
1003 }
1004
1005 void MetricsService::IncrementLongPrefsValue(const char* path) {
1006   int64 value = local_state_->GetInt64(path);
1007   local_state_->SetInt64(path, value + 1);
1008 }
1009
1010 bool MetricsService::UmaMetricsProperlyShutdown() {
1011   CHECK(clean_shutdown_status_ == CLEANLY_SHUTDOWN ||
1012         clean_shutdown_status_ == NEED_TO_SHUTDOWN);
1013   return clean_shutdown_status_ == CLEANLY_SHUTDOWN;
1014 }
1015
1016 void MetricsService::AddSyntheticTrialObserver(
1017     SyntheticTrialObserver* observer) {
1018   synthetic_trial_observer_list_.AddObserver(observer);
1019   if (!synthetic_trial_groups_.empty())
1020     observer->OnSyntheticTrialsChanged(synthetic_trial_groups_);
1021 }
1022
1023 void MetricsService::RemoveSyntheticTrialObserver(
1024     SyntheticTrialObserver* observer) {
1025   synthetic_trial_observer_list_.RemoveObserver(observer);
1026 }
1027
1028 void MetricsService::RegisterSyntheticFieldTrial(
1029     const SyntheticTrialGroup& trial) {
1030   for (size_t i = 0; i < synthetic_trial_groups_.size(); ++i) {
1031     if (synthetic_trial_groups_[i].id.name == trial.id.name) {
1032       if (synthetic_trial_groups_[i].id.group != trial.id.group) {
1033         synthetic_trial_groups_[i].id.group = trial.id.group;
1034         synthetic_trial_groups_[i].start_time = base::TimeTicks::Now();
1035         NotifySyntheticTrialObservers();
1036       }
1037       return;
1038     }
1039   }
1040
1041   SyntheticTrialGroup trial_group = trial;
1042   trial_group.start_time = base::TimeTicks::Now();
1043   synthetic_trial_groups_.push_back(trial_group);
1044   NotifySyntheticTrialObservers();
1045 }
1046
1047 void MetricsService::RegisterMetricsProvider(
1048     scoped_ptr<MetricsProvider> provider) {
1049   DCHECK_EQ(INITIALIZED, state_);
1050   metrics_providers_.push_back(provider.Pass());
1051 }
1052
1053 void MetricsService::CheckForClonedInstall(
1054     scoped_refptr<base::SingleThreadTaskRunner> task_runner) {
1055   state_manager_->CheckForClonedInstall(task_runner);
1056 }
1057
1058 void MetricsService::NotifySyntheticTrialObservers() {
1059   FOR_EACH_OBSERVER(SyntheticTrialObserver, synthetic_trial_observer_list_,
1060                     OnSyntheticTrialsChanged(synthetic_trial_groups_));
1061 }
1062
1063 void MetricsService::GetCurrentSyntheticFieldTrials(
1064     std::vector<variations::ActiveGroupId>* synthetic_trials) {
1065   DCHECK(synthetic_trials);
1066   synthetic_trials->clear();
1067   const MetricsLog* current_log = log_manager_.current_log();
1068   for (size_t i = 0; i < synthetic_trial_groups_.size(); ++i) {
1069     if (synthetic_trial_groups_[i].start_time <= current_log->creation_time())
1070       synthetic_trials->push_back(synthetic_trial_groups_[i].id);
1071   }
1072 }
1073
1074 scoped_ptr<MetricsLog> MetricsService::CreateLog(MetricsLog::LogType log_type) {
1075   return make_scoped_ptr(new MetricsLog(state_manager_->client_id(),
1076                                         session_id_,
1077                                         log_type,
1078                                         client_,
1079                                         local_state_));
1080 }
1081
1082 void MetricsService::RecordCurrentEnvironment(MetricsLog* log) {
1083   std::vector<variations::ActiveGroupId> synthetic_trials;
1084   GetCurrentSyntheticFieldTrials(&synthetic_trials);
1085   log->RecordEnvironment(metrics_providers_.get(), synthetic_trials,
1086                          GetInstallDate(), GetMetricsReportingEnabledDate());
1087   UMA_HISTOGRAM_COUNTS_100("UMA.SyntheticTrials.Count",
1088                            synthetic_trials.size());
1089 }
1090
1091 void MetricsService::RecordCurrentHistograms() {
1092   DCHECK(log_manager_.current_log());
1093   histogram_snapshot_manager_.PrepareDeltas(
1094       base::Histogram::kNoFlags, base::Histogram::kUmaTargetedHistogramFlag);
1095 }
1096
1097 void MetricsService::RecordCurrentStabilityHistograms() {
1098   DCHECK(log_manager_.current_log());
1099   histogram_snapshot_manager_.PrepareDeltas(
1100       base::Histogram::kNoFlags, base::Histogram::kUmaStabilityHistogramFlag);
1101 }
1102
1103 void MetricsService::LogCleanShutdown() {
1104   // Redundant setting to assure that we always reset this value at shutdown
1105   // (and that we don't use some alternate path, and not call LogCleanShutdown).
1106   clean_shutdown_status_ = CLEANLY_SHUTDOWN;
1107
1108   clean_exit_beacon_.WriteBeaconValue(true);
1109   RecordCurrentState(local_state_);
1110   local_state_->SetInteger(prefs::kStabilityExecutionPhase,
1111                            MetricsService::SHUTDOWN_COMPLETE);
1112 }
1113
1114 bool MetricsService::ShouldLogEvents() {
1115   // We simply don't log events to UMA if there is a single incognito
1116   // session visible. The problem is that we always notify using the orginal
1117   // profile in order to simplify notification processing.
1118   return !client_->IsOffTheRecordSessionActive();
1119 }
1120
1121 void MetricsService::RecordBooleanPrefValue(const char* path, bool value) {
1122   DCHECK(IsSingleThreaded());
1123   local_state_->SetBoolean(path, value);
1124   RecordCurrentState(local_state_);
1125 }
1126
1127 void MetricsService::RecordCurrentState(PrefService* pref) {
1128   pref->SetInt64(prefs::kStabilityLastTimestampSec,
1129                  base::Time::Now().ToTimeT());
1130 }
1131
1132 }  // namespace metrics