Send UMA stability stats in a separate UMA log on startup.

chrome/browser/metrics/metrics_service.cc

 // Copyright (c) 2012 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.
 
 //------------------------------------------------------------------------------
 // Description of the life cycle of a instance of MetricsService.
 //
 //  OVERVIEW
 //
 // A MetricsService instance is typically created at application startup.  It is
 // the central controller for the acquisition of log data, and the automatic
 // transmission of that log data to an external server.  Its major job is to
 // manage logs, grouping them for transmission, and transmitting them.  As part
 // of its grouping, MS finalizes logs by including some just-in-time gathered
 // memory statistics, snapshotting the current stats of numerous histograms,
 // closing the logs, translating to protocol buffer format, and compressing the
 // results for transmission.  Transmission includes submitting a compressed log
 // as data in a URL-post, and retransmitting (or retaining at process
 // termination) if the attempted transmission failed.  Retention across process
 // terminations is done using the the PrefServices facilities. The retained logs
 // (the ones that never got transmitted) are compressed and base64-encoded
 // before being persisted.
 //
 // Logs fall into one of two categories: "initial logs," and "ongoing logs."
-// There is at most one initial log sent for each complete run of the chromium
-// product (from startup, to browser shutdown).  An initial log is generally
-// transmitted some short time (1 minute?) after startup, and includes stats
-// such as recent crash info, the number and types of plugins, etc.  The
-// external server's response to the initial log conceptually tells this MS if
-// it should continue transmitting logs (during this session). The server
-// response can actually be much more detailed, and always includes (at a
-// minimum) how often additional ongoing logs should be sent.
+// There is at most one initial log sent for each complete run of Chrome (from
+// startup, to browser shutdown).  An initial log is generally transmitted some
+// short time (1 minute?) after startup, and includes stats such as recent crash
+// info, the number and types of plugins, etc.  The external server's response
+// to the initial log conceptually tells this MS if it should continue
+// transmitting logs (during this session). The server response can actually be
+// much more detailed, and always includes (at a minimum) how often additional
+// ongoing logs should be sent.
 //
 // After the above initial log, a series of ongoing logs will be transmitted.
 // The first ongoing log actually begins to accumulate information stating when
 // the MS was first constructed.  Note that even though the initial log is
 // commonly sent a full minute after startup, the initial log does not include
 // much in the way of user stats.   The most common interlog period (delay)
 // is 30 minutes. That time period starts when the first user action causes a
 // logging event.  This means that if there is no user action, there may be long
 // periods without any (ongoing) log transmissions.  Ongoing logs typically
 // contain very detailed records of user activities (ex: opened tab, closed
 // tab, fetched URL, maximized window, etc.)  In addition, just before an
 // ongoing log is closed out, a call is made to gather memory statistics.  Those
 // memory statistics are deposited into a histogram, and the log finalization
 // code is then called.  In the finalization, a call to a Histogram server
 // acquires a list of all local histograms that have been flagged for upload
-// to the UMA server.  The finalization also acquires a the most recent number
+// to the UMA server.  The finalization also acquires the most recent number
 // of page loads, along with any counts of renderer or plugin crashes.
 //
 // When the browser shuts down, there will typically be a fragment of an ongoing
-// log that has not yet been transmitted.  At shutdown time, that fragment
-// is closed (including snapshotting histograms), and persisted, for
-// potential transmission during a future run of the product.
+// log that has not yet been transmitted.  At shutdown time, that fragment is
+// closed (including snapshotting histograms), and persisted, for potential
+// transmission during a future run of the product.
 //
 // There are two slightly abnormal shutdown conditions.  There is a
 // "disconnected scenario," and a "really fast startup and shutdown" scenario.
 // In the "never connected" situation, the user has (during the running of the
 // process) never established an internet connection.  As a result, attempts to
 // transmit the initial log have failed, and a lot(?) of data has accumulated in
 // the ongoing log (which didn't yet get closed, because there was never even a
 // contemplation of sending it).  There is also a kindred "lost connection"
 // situation, where a loss of connection prevented an ongoing log from being
 // transmitted, and a (still open) log was stuck accumulating a lot(?) of data,
 // while the earlier log retried its transmission.  In both of these
 // disconnected situations, two logs need to be, and are, persistently stored
 // for future transmission.
 //
 // The other unusual shutdown condition, termed "really fast startup and
 // shutdown," involves the deliberate user termination of the process before
 // the initial log is even formed or transmitted. In that situation, no logging
 // is done, but the historical crash statistics remain (unlogged) for inclusion
 // in a future run's initial log.  (i.e., we don't lose crash stats).
 //
 // With the above overview, we can now describe the state machine's various
-// stats, based on the State enum specified in the state_ member.  Those states
+// states, based on the State enum specified in the state_ member.  Those states
 // are:
 //
-//    INITIALIZED,            // Constructor was called.
-//    INIT_TASK_SCHEDULED,    // Waiting for deferred init tasks to complete.
-//    INIT_TASK_DONE,         // Waiting for timer to send initial log.
-//    INITIAL_LOG_READY,      // Initial log generated, and waiting for reply.
-//    SENDING_OLD_LOGS,       // Sending unsent logs from previous session.
-//    SENDING_CURRENT_LOGS,   // Sending standard current logs as they accrue.
+//  INITIALIZED,                   // Constructor was called.
+//  INIT_TASK_SCHEDULED,           // Waiting for deferred init tasks to finish.

[Ilya Sherman, 2013/12/06 06:21:26]

nit: Note that you still have "tasks" here, but you've switched to "task" below.
 IMO you should keep "tasks" throughout.

[Alexei Svitkine (slow), 2013/12/06 17:59:22]

Done.

+//  INIT_TASK_DONE,                // Waiting for timer to send initial log.
+//  SENDING_INITIAL_STABILITY_LOG, // Initial stability log being sent.
+//  SENDING_INITIAL_METRICS_LOG,   // Initial metrics log being sent.
+//  SENDING_OLD_LOGS,              // Sending unsent logs from previous session.
+//  SENDING_CURRENT_LOGS,          // Sending ongoing logs as they acrue.
 //
 // In more detail, we have:
 //
 //    INITIALIZED,            // Constructor was called.
 // The MS has been constructed, but has taken no actions to compose the
 // initial log.
 //
-//    INIT_TASK_SCHEDULED,    // Waiting for deferred init tasks to complete.
+//    INIT_TASK_SCHEDULED,    // Waiting for deferred init task to complete.
 // Typically about 30 seconds after startup, a task is sent to a second thread
 // (the file thread) to perform deferred (lower priority and slower)
 // initialization steps such as getting the list of plugins.  That task will
 // (when complete) make an async callback (via a Task) to indicate the
 // completion.
 //
 //    INIT_TASK_DONE,         // Waiting for timer to send initial log.
 // The callback has arrived, and it is now possible for an initial log to be
 // created.  This callback typically arrives back less than one second after
 // the deferred init task is dispatched.
 //
-//    INITIAL_LOG_READY,      // Initial log generated, and waiting for reply.
-// This state is entered only after an initial log has been composed, and
-// prepared for transmission.  It is also the case that any previously unsent
-// logs have been loaded into instance variables for possible transmission.
+//    SENDING_INITIAL_STABILITY_LOG,  // Initial stability log being sent.
+// During initialization, if a crash occurred during the previous session, an
+// initial stability log will be generated and registered with the log manager.
+// This state will be entered if there's such a stability log waiting to be

[Ilya Sherman, 2013/12/06 06:21:26]

nit: What does it mean for there to be a stability log waiting to be
transmitted?  It might be clearer to reference when (during which step?) such a
log would be created.

[Alexei Svitkine (slow), 2013/12/06 17:59:22]

Done.

+// transmitted when its time to sent up the first log (per the reporting

[Ilya Sherman, 2013/12/06 06:21:26]

nit: "its" -> "it's"

[Ilya Sherman, 2013/12/06 06:21:26]

nit: "sent" -> "send"

[Alexei Svitkine (slow), 2013/12/06 17:59:22]

Done.

[Alexei Svitkine (slow), 2013/12/06 17:59:22]

Done.

+// scheduler).  If there is no initial stability log (e.g. there was no previous
+// crash), then this state will be skipped and the state will advance to
+// SENDING_INITIAL_METRICS_LOG.
+//
+//    SENDING_INITIAL_METRICS_LOG,  // Initial metrics log being sent.
+// This state is entered once the initial metrics log has been composed, and
+// prepared for transmission and after sending the initial stability log, if
+// any.  It is also the case that any previously unsent logs have been loaded

[Ilya Sherman, 2013/12/06 06:21:26]

nit: This first sentence is a bit hard to parse; consider rewording.

[Alexei Svitkine (slow), 2013/12/06 17:59:22]

Done.

+// into instance variables for possible transmission.
 //
 //    SENDING_OLD_LOGS,       // Sending unsent logs from previous session.
 // This state indicates that the initial log for this session has been
 // successfully sent and it is now time to send any logs that were
 // saved from previous sessions.  All such logs will be transmitted before
 // exiting this state, and proceeding with ongoing logs from the current session
 // (see next state).
 //
 //    SENDING_CURRENT_LOGS,   // Sending standard current logs as they accrue.
 // Current logs are being accumulated.  Typically every 20 minutes a log is
@@ skipping 212 matching lines @@
 
 void MarkAppCleanShutdownAndCommit() {
   PrefService* pref = g_browser_process->local_state();
   pref->SetBoolean(prefs::kStabilityExitedCleanly, true);
   pref->SetInteger(prefs::kStabilityExecutionPhase,
                    MetricsService::SHUTDOWN_COMPLETE);
   // Start writing right away (write happens on a different thread).
   pref->CommitPendingWrite();
 }
 
+// Returns whether initial stability metrics should be sent in a separate log.
+bool SendSeparateInitialStabilityLog() {
+  return base::FieldTrialList::FindFullName("UMAStability") == "SeparateLog";
+}
+
 }  // namespace
 
 
 SyntheticTrialGroup::SyntheticTrialGroup(uint32 trial,
                                          uint32 group,
                                          base::TimeTicks start)
     : start_time(start) {
   id.name = trial;
   id.group = group;
 }
@@ skipping 146 matching lines @@
   local_state->ClearPref(prefs::kMetricsOngoingLogs);
 }
 
 MetricsService::MetricsService()
     : recording_active_(false),
       reporting_active_(false),
       test_mode_active_(false),
       state_(INITIALIZED),
       low_entropy_source_(kLowEntropySourceNotSet),
       idle_since_last_transmission_(false),
+      session_id_(-1),
       next_window_id_(0),
       self_ptr_factory_(this),
       state_saver_factory_(this),
       waiting_for_asynchronous_reporting_step_(false),
       num_async_histogram_fetches_in_progress_(0),
       entropy_source_returned_(LAST_ENTROPY_NONE) {
   DCHECK(IsSingleThreaded());
-  InitializeMetricsState();
-
-  base::Closure callback = base::Bind(&MetricsService::StartScheduledUpload,
-                                      self_ptr_factory_.GetWeakPtr());
-  scheduler_.reset(new MetricsReportingScheduler(callback));
-  log_manager_.set_log_serializer(new MetricsLogSerializer());
-  log_manager_.set_max_ongoing_log_store_size(kUploadLogAvoidRetransmitSize);
 
   BrowserChildProcessObserver::Add(this);
 }
 
 MetricsService::~MetricsService() {
   DisableRecording();
 
   BrowserChildProcessObserver::Remove(this);
 }
 
+void MetricsService::InitializeMetricsRecordingState(
+    bool reporting_will_be_enabled) {
+  InitializeMetricsState(reporting_will_be_enabled);
+
+  base::Closure callback = base::Bind(&MetricsService::StartScheduledUpload,
+                                      self_ptr_factory_.GetWeakPtr());
+  scheduler_.reset(new MetricsReportingScheduler(callback));
+  log_manager_.set_log_serializer(new MetricsLogSerializer());
+  log_manager_.set_max_ongoing_log_store_size(kUploadLogAvoidRetransmitSize);
+}
+
 void MetricsService::Start() {
   HandleIdleSinceLastTransmission(false);
   EnableRecording();
   EnableReporting();
 }
 
 void MetricsService::StartRecordingForTests() {
   test_mode_active_ = true;
   EnableRecording();
   DisableReporting();
@@ skipping 241 matching lines @@
 #if defined(OS_ANDROID) || defined(OS_IOS)
 void MetricsService::OnAppEnterBackground() {
   scheduler_->Stop();
 
   MarkAppCleanShutdownAndCommit();
 
   // At this point, there's no way of knowing when the process will be
   // killed, so this has to be treated similar to a shutdown, closing and
   // persisting all logs. Unlinke a shutdown, the state is primed to be ready
   // to continue logging and uploading if the process does return.
-  if (recording_active() && state_ >= INITIAL_LOG_READY) {
+  if (recording_active() && state_ >= SENDING_INITIAL_STABILITY_LOG) {
     PushPendingLogsToPersistentStorage();
     // Persisting logs closes the current log, so start recording a new log
     // immediately to capture any background work that might be done before the
     // process is killed.
     OpenNewLog();
   }
 }
 
 void MetricsService::OnAppEnterForeground() {
   PrefService* pref = g_browser_process->local_state();
@@ skipping 84 matching lines @@
 #endif  // defined(OS_WIN)
 
 //------------------------------------------------------------------------------
 // private methods
 //------------------------------------------------------------------------------
 
 
 //------------------------------------------------------------------------------
 // Initialization methods
 
-void MetricsService::InitializeMetricsState() {
+void MetricsService::InitializeMetricsState(bool reporting_will_be_enabled) {
 #if defined(OS_POSIX)
   network_stats_server_ = chrome_common_net::kEchoTestServerLocation;
   http_pipelining_test_server_ = chrome_common_net::kPipelineTestServerBaseUrl;
 #else
   BrowserDistribution* dist = BrowserDistribution::GetDistribution();
   network_stats_server_ = dist->GetNetworkStatsServer();
   http_pipelining_test_server_ = dist->GetHttpPipeliningTestServer();
 #endif
 
   PrefService* pref = g_browser_process->local_state();
   DCHECK(pref);
 
+  // TODO(asvitkine): Kill this logic when SendSeparateInitialStabilityLog() is
+  // is made the default behavior.
   if ((pref->GetInt64(prefs::kStabilityStatsBuildTime)
        != MetricsLog::GetBuildTime()) ||
       (pref->GetString(prefs::kStabilityStatsVersion)
        != MetricsLog::GetVersionString())) {
     // This is a new version, so we don't want to confuse the stats about the
     // old version with info that we upload.
     DiscardOldStabilityStats(pref);
     pref->SetString(prefs::kStabilityStatsVersion,
                     MetricsLog::GetVersionString());
     pref->SetInt64(prefs::kStabilityStatsBuildTime,
                    MetricsLog::GetBuildTime());
   }
 
-  // Update session ID
+  // Initialize uptime counters.
+  const base::TimeDelta startup_uptime = GetIncrementalUptime(pref);
+  DCHECK_EQ(0, startup_uptime.InMicroseconds());

[Ilya Sherman, 2013/12/06 06:21:26]

Hmm, why does this need to happen earlier now?

[Alexei Svitkine (slow), 2013/12/06 17:59:22]

In a previous version of this I used startup_uptime for the initial stability
log, so it was needed earlier. But now I just pass 0 unconditionally, so this
doesn't need to be here anymore - you're right. Moved back down.

   session_id_ = pref->GetInteger(prefs::kMetricsSessionID);
-  ++session_id_;
-  pref->SetInteger(prefs::kMetricsSessionID, session_id_);
-
-  // Stability bookkeeping
-  IncrementPrefValue(prefs::kStabilityLaunchCount);
 
   if (!pref->GetBoolean(prefs::kStabilityExitedCleanly)) {
     IncrementPrefValue(prefs::kStabilityCrashCount);
     // Reset flag, and wait until we call LogNeedForCleanShutdown() before
     // monitoring.
     pref->SetBoolean(prefs::kStabilityExitedCleanly, true);
 
     // TODO(rtenneti): On windows, consider saving/getting execution_phase from
     // the registry.
     int execution_phase = pref->GetInteger(prefs::kStabilityExecutionPhase);
     UMA_HISTOGRAM_SPARSE_SLOWLY("Chrome.Browser.CrashedExecutionPhase",
                                 execution_phase);
+
+    // If the previous session didn't exit cleanly, then prepare an initial
+    // stability log if UMA is enabled.
+    if (reporting_will_be_enabled && SendSeparateInitialStabilityLog())
+      PrepareInitialStabilityLog();
   }
+
+  // Update session ID.
+  ++session_id_;
+  pref->SetInteger(prefs::kMetricsSessionID, session_id_);
+
+  // Stability bookkeeping
+  IncrementPrefValue(prefs::kStabilityLaunchCount);
+
   DCHECK_EQ(UNINITIALIZED_PHASE, execution_phase_);
   SetExecutionPhase(START_METRICS_RECORDING);
 
 #if defined(OS_WIN)
   CountBrowserCrashDumpAttempts();
 #endif  // defined(OS_WIN)
 
   if (!pref->GetBoolean(prefs::kStabilitySessionEndCompleted)) {
     IncrementPrefValue(prefs::kStabilityIncompleteSessionEndCount);
     // This is marked false when we get a WM_ENDSESSION.
     pref->SetBoolean(prefs::kStabilitySessionEndCompleted, true);
   }
 
-  // Initialize uptime counters.
-  const base::TimeDelta startup_uptime = GetIncrementalUptime(pref);
-  DCHECK_EQ(0, startup_uptime.InMicroseconds());
   // For backwards compatibility, leave this intact in case Omaha is checking
   // them.  prefs::kStabilityLastTimestampSec may also be useless now.
   // TODO(jar): Delete these if they have no uses.
   pref->SetInt64(prefs::kStabilityLaunchTimeSec, Time::Now().ToTimeT());
 
   // Bookkeeping for the uninstall metrics.
   IncrementLongPrefsValue(prefs::kUninstallLaunchCount);
 
   // Get stats on use of command line.
   const CommandLine* command_line(CommandLine::ForCurrentProcess());
@@ skipping 112 matching lines @@
   HandleIdleSinceLastTransmission(false);
 }
 
 void MetricsService::ReceivedProfilerData(
     const tracked_objects::ProcessDataSnapshot& process_data,
     int process_type) {
   DCHECK_EQ(INIT_TASK_SCHEDULED, state_);
 
   // Upon the first callback, create the initial log so that we can immediately
   // save the profiler data.
-  if (!initial_log_.get())
-    initial_log_.reset(new MetricsLog(client_id_, session_id_));
+  if (!initial_metrics_log_.get())
+    initial_metrics_log_.reset(new MetricsLog(client_id_, session_id_));
 
-  initial_log_->RecordProfilerData(process_data, process_type);
+  initial_metrics_log_->RecordProfilerData(process_data, process_type);
 }
 
 void MetricsService::FinishedReceivingProfilerData() {
   DCHECK_EQ(INIT_TASK_SCHEDULED, state_);
   state_ = INIT_TASK_DONE;
   scheduler_->InitTaskComplete();
 }
 
 base::TimeDelta MetricsService::GetIncrementalUptime(PrefService* pref) {
   base::TimeTicks now = base::TimeTicks::Now();
@@ skipping 136 matching lines @@
   PrefService* pref = g_browser_process->local_state();
   current_log->RecordStabilityMetrics(GetIncrementalUptime(pref),
                                       MetricsLog::ONGOING_LOG);
 
   RecordCurrentHistograms();
 
   log_manager_.FinishCurrentLog();
 }
 
 void MetricsService::PushPendingLogsToPersistentStorage() {
-  if (state_ < INITIAL_LOG_READY)
+  if (state_ < SENDING_INITIAL_STABILITY_LOG)
     return;  // We didn't and still don't have time to get plugin list etc.
 
   if (log_manager_.has_staged_log()) {
     // We may race here, and send second copy of the log later.
     MetricsLogManager::StoreType store_type;
     if (current_fetch_.get())
       store_type = MetricsLogManager::PROVISIONAL_STORE;
     else
       store_type = MetricsLogManager::NORMAL_STORE;
     log_manager_.StoreStagedLogAsUnsent(store_type);
@@ skipping 12 matching lines @@
 // Transmission of logs methods
 
 void MetricsService::StartSchedulerIfNecessary() {
   // Never schedule cutting or uploading of logs in test mode.
   if (test_mode_active_)
     return;
 
   // Even if reporting is disabled, the scheduler is needed to trigger the
   // creation of the initial log, which must be done in order for any logs to be
   // persisted on shutdown or backgrounding.
-  if (recording_active() && (reporting_active() || state_ < INITIAL_LOG_READY))
+  if (recording_active() &&
+      (reporting_active() || state_ < SENDING_INITIAL_STABILITY_LOG)) {
     scheduler_->Start();
+  }
 }
 
 void MetricsService::StartScheduledUpload() {
   // If we're getting no notifications, then the log won't have much in it, and
   // it's possible the computer is about to go to sleep, so don't upload and
   // stop the scheduler.
   // If recording has been turned off, the scheduler doesn't need to run.
   // If reporting is off, proceed if the initial log hasn't been created, since
   // that has to happen in order for logs to be cut and stored when persisting.
   // TODO(stuartmorgan): Call Stop() on the schedule when reporting and/or
   // recording are turned off instead of letting it fire and then aborting.
   if (idle_since_last_transmission_ ||
       !recording_active() ||
-      (!reporting_active() && state_ >= INITIAL_LOG_READY)) {
+      (!reporting_active() && state_ >= SENDING_INITIAL_STABILITY_LOG)) {
     scheduler_->Stop();
     scheduler_->UploadCancelled();
     return;
   }
 
   // If the callback was to upload an old log, but there no longer is one,
   // just report success back to the scheduler to begin the ongoing log
   // callbacks.
   // TODO(stuartmorgan): Consider removing the distinction between
   // SENDING_OLD_LOGS and SENDING_CURRENT_LOGS to simplify the state machine
@@ skipping 118 matching lines @@
   if (!reporting_active()) {
     scheduler_->Stop();
     scheduler_->UploadCancelled();
     return;
   }
 
   SendStagedLog();
 }
 
 void MetricsService::StageNewLog() {
-  if (log_manager_.has_staged_log())
+  if (state_ != INIT_TASK_DONE && log_manager_.has_staged_log())
     return;
 
   switch (state_) {
     case INITIALIZED:
     case INIT_TASK_SCHEDULED:  // We should be further along by now.
       NOTREACHED();
       return;
 
     case INIT_TASK_DONE:
-      PrepareInitialLog();
-      DCHECK_EQ(INIT_TASK_DONE, state_);
-      log_manager_.LoadPersistedUnsentLogs();
-      state_ = INITIAL_LOG_READY;
+      if (log_manager_.has_staged_log()) {
+        // There's an initial stability log, ready to send.
+        state_ = SENDING_INITIAL_STABILITY_LOG;
+      } else {
+        // TODO(asvitkine): When the field trial is removed, the |log_type|
+        // arg should be removed and PrepareInitialMetricsLog() should always
+        // use ONGOING_LOG. Use INITIAL_LOG only to match to the old behavior
+        // when the field trial is off.
+        MetricsLog::LogType log_type = SendSeparateInitialStabilityLog() ?
+            MetricsLog::ONGOING_LOG : MetricsLog::INITIAL_LOG;
+        PrepareInitialMetricsLog(log_type);
+        state_ = SENDING_INITIAL_METRICS_LOG;
+      }
       break;
 
     case SENDING_OLD_LOGS:
       NOTREACHED();  // Shouldn't be staging a new log during old log sending.
       return;
 
     case SENDING_CURRENT_LOGS:
       CloseCurrentLog();
       OpenNewLog();
       log_manager_.StageNextLogForUpload();
       break;
 
     default:
       NOTREACHED();
       return;
   }
 
   DCHECK(log_manager_.has_staged_log());
 }
 
-void MetricsService::PrepareInitialLog() {
-  DCHECK_EQ(INIT_TASK_DONE, state_);

[Ilya Sherman, 2013/12/06 06:21:26]

nit: Please preserve some flavor of this DCHECK.

[Alexei Svitkine (slow), 2013/12/06 17:59:22]

Done (in PrepareInitialMetricsLog()). 

+void MetricsService::PrepareInitialStabilityLog() {
+  DCHECK_EQ(INITIALIZED, state_);
 
-  DCHECK(initial_log_.get());
-  initial_log_->set_hardware_class(hardware_class_);
+  scoped_ptr<MetricsLog> initial_stability_log(
+      new MetricsLog(client_id_, session_id_));
+  if (!initial_stability_log->LoadSavedEnvironmentFromPrefs())
+    return;
+  initial_stability_log->RecordStabilityMetrics(base::TimeDelta(),
+                                                MetricsLog::INITIAL_LOG);
+
+  log_manager_.PauseCurrentLog();
+  log_manager_.BeginLoggingWithLog(initial_stability_log.release(),
+                                   MetricsLog::INITIAL_LOG);
+  log_manager_.FinishCurrentLog();
+  log_manager_.ResumePausedLog();
+  // TODO(asvitkine): It would be nice to defer StageNextLogForUpload() until
+  // the log is ready to be actually sent. This way, the initial stability log
+  // can be kept around in unsent logs (and saved to prefs) in case there's a
+  // crash. However, this would require loading existing unsent logs earlier -
+  // which is currently done in PrepareInitialMetricsLog().

[Ilya Sherman, 2013/12/06 06:21:26]

I think it's important to get this right, i.e. to save the stability log to
prefs in case of a crash and to load the existing unsent logs earlier (so we
don't accidentally overwrite them with the wrong data).

[Alexei Svitkine (slow), 2013/12/06 17:59:22]

Okay - that's why I put the comment here to raise this point so we can discuss.
:)

In order to handle this, we will need to read the existing unsent logs from
prefs earlier (i.e. in this function by moving the
log_manager_.LoadPersistedUnsentLogs() call here).

The consequence of this is it will now be on the startup path. The current code
calls LoadPersistedUnsentLogs() once the initial metrics log is ready to be sent
up - quite a bit later. Whereas this function is executed shortly after metrics
service creation while we're in single-threaded startup. I'm not sure if we're
willing to do this.

One thing to note is the unsent logs are already in memory (i.e. local state has
been read and that call wouldn't result in any I/O) - so its just the cpu load
of decoding the logs and verifying their hashes, etc. So it may be okay to do.
WDYT?

The reason we need to read them is so that when we serialize this out, it
doesn't clobber existing logs. One possibility would be to add to the existing
list without reading the existing contents out. This requires extra support for
this through the log manager (right now it only knows how to clobber the full
list). The extra support required would be to be able to append a log to a list
(which would be done here.) and another function to remove it (done when the log
has been sent successfully). Perhaps this is the best approach (despite
requiring more extensive changes). WDYT?

[Ilya Sherman, 2013/12/07 06:51:53]

Hmm.  Could you possibly measure the actual performance impact of this change? 
It's hard to say whether this is reasonable without any data.  If the logs are
already in memory, though, my intuition is that reading them ought to be fairly
cheap.
Depends on how much extra complexity that is, I guess.

Yet another option is to delay the stability metrics log until we're out of the
startup path.  What are the tradeoffs you're thinking of there?

[Alexei Svitkine (slow), 2013/12/09 21:17:02]

Agreed. I've added histograms to measure how long it takes to load and store
unsent logs and made the new code path (that's behind a field trial) do this
more eagerly now, allowing the initial stability log to be persisted. I figure
given that this is all behind a trial, we can look at the metrics and decide if
its acceptable to ramp things up given what we see. WDYT?
The problem is if we delay the stability metrics, then stuff from the current
session (i.e. new renderer crashes) will be recorded in that log, which is
incorrect.

[Ilya Sherman, 2013/12/10 06:02:10]

Yeah, that sounds reasonable.  Thanks! :)
Makes sense.

+  log_manager_.StageNextLogForUpload();
+}
+
+void MetricsService::PrepareInitialMetricsLog(MetricsLog::LogType log_type) {
+  DCHECK(initial_metrics_log_.get());

[Ilya Sherman, 2013/12/06 06:21:26]

nit: No need for .get()

[Alexei Svitkine (slow), 2013/12/06 17:59:22]

I actually just deleted this line now. If it's null, then the line below will
crash anyway, so no need an extra DCHECK here. (DCHECKs are useful for catching
things early - e.g. if this didn't use the log until much later - but doing it
right above a deref doesn't serve any value - either way the error will point at
this part of the code).

+  initial_metrics_log_->set_hardware_class(hardware_class_);
 
   std::vector<chrome_variations::ActiveGroupId> synthetic_trials;
   GetCurrentSyntheticFieldTrials(&synthetic_trials);
-  initial_log_->RecordEnvironment(plugins_, google_update_metrics_,
-                                  synthetic_trials);
+  initial_metrics_log_->RecordEnvironment(plugins_, google_update_metrics_,
+                                          synthetic_trials);
   PrefService* pref = g_browser_process->local_state();
-  initial_log_->RecordStabilityMetrics(GetIncrementalUptime(pref),
-                                       MetricsLog::INITIAL_LOG);
+  initial_metrics_log_->RecordStabilityMetrics(GetIncrementalUptime(pref),
+                                               log_type);
 
   // Histograms only get written to the current log, so make the new log current
   // before writing them.
   log_manager_.PauseCurrentLog();
-  log_manager_.BeginLoggingWithLog(initial_log_.release(),
-                                   MetricsLog::INITIAL_LOG);
+  log_manager_.BeginLoggingWithLog(initial_metrics_log_.release(), log_type);
   RecordCurrentHistograms();
   log_manager_.FinishCurrentLog();
   log_manager_.ResumePausedLog();
 
   DCHECK(!log_manager_.has_staged_log());
   log_manager_.StageNextLogForUpload();
+  log_manager_.LoadPersistedUnsentLogs();

[Ilya Sherman, 2013/12/06 06:21:26]

nit: It seems more appropriate to leave this where it was.  This is not really
related to preparing the initial metrics log.

[Alexei Svitkine (slow), 2013/12/06 17:59:22]

See my comment above about moving this call earlier.

 }
 
 void MetricsService::StoreUnsentLogs() {
-  if (state_ < INITIAL_LOG_READY)
+  if (state_ < SENDING_INITIAL_STABILITY_LOG)
     return;  // We never Recalled the prior unsent logs.
 
   log_manager_.PersistUnsentLogs();
 }
 
 void MetricsService::SendStagedLog() {
   DCHECK(log_manager_.has_staged_log());
 
   PrepareFetchWithStagedLog();
 
@@ skipping 90 matching lines @@
     discard_log = true;
   }
 
   if (upload_succeeded || discard_log)
     log_manager_.DiscardStagedLog();
 
   waiting_for_asynchronous_reporting_step_ = false;
 
   if (!log_manager_.has_staged_log()) {
     switch (state_) {
-      case INITIAL_LOG_READY:
+      case SENDING_INITIAL_STABILITY_LOG:
+        PrepareInitialMetricsLog(MetricsLog::ONGOING_LOG);
+        SendStagedLog();
+        state_ = SENDING_INITIAL_METRICS_LOG;
+        break;
+
+      case SENDING_INITIAL_METRICS_LOG:
         state_ = log_manager_.has_unsent_logs() ? SENDING_OLD_LOGS
                                                 : SENDING_CURRENT_LOGS;
         break;
 
       case SENDING_OLD_LOGS:
         // Store the updated list to disk now that the removed log is uploaded.
         StoreUnsentLogs();
         if (!log_manager_.has_unsent_logs())
           state_ = SENDING_CURRENT_LOGS;
         break;
 
       case SENDING_CURRENT_LOGS:
         break;
 
       default:
         NOTREACHED();
         break;
     }
 
     if (log_manager_.has_unsent_logs())
       DCHECK_LT(state_, SENDING_CURRENT_LOGS);
   }
 
-  // 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, log_manager_.has_unsent_logs());
+  // Don't notify the scheduler that the upload is finished if we've only sent
+  // the initial stability log, but not yet the initial metrics log (treat the
+  // two as a single unit of work as far as the scheduler is concerned).
+  if (state_ != SENDING_INITIAL_METRICS_LOG) {
+    // 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.

[Ilya Sherman, 2013/12/06 06:21:26]

nit: This comment still belongs above line 1702 IMO.

[Alexei Svitkine (slow), 2013/12/06 17:59:22]

Done.

+    scheduler_->UploadFinished(server_is_healthy,
+                               log_manager_.has_unsent_logs());
+  }
 
   // Collect network stats if UMA upload succeeded.
   IOThread* io_thread = g_browser_process->io_thread();
   if (server_is_healthy && io_thread) {
     chrome_browser_net::CollectNetworkStats(network_stats_server_, io_thread);
     chrome_browser_net::CollectPipeliningCapabilityStatsOnUIThread(
         http_pipelining_test_server_, io_thread);
 #if defined(OS_WIN)
     chrome::CollectTimeTicksStats();
 #endif
@@ skipping 45 matching lines @@
     }
 
     UMA_HISTOGRAM_PERCENTAGE("BrowserRenderProcessHost.ChildCrashes",
                              was_extension_process ? 2 : 1);
   } else if (status == base::TERMINATION_STATUS_PROCESS_WAS_KILLED) {
     UMA_HISTOGRAM_PERCENTAGE("BrowserRenderProcessHost.ChildKills",
                              was_extension_process ? 2 : 1);
   } else if (status == base::TERMINATION_STATUS_STILL_RUNNING) {
     UMA_HISTOGRAM_PERCENTAGE("BrowserRenderProcessHost.DisconnectedAlive",
                                was_extension_process ? 2 : 1);
-    }
   }
+}
 
 void MetricsService::LogRendererHang() {
   IncrementPrefValue(prefs::kStabilityRendererHangCount);
 }
 
 bool MetricsService::UmaMetricsProperlyShutdown() {
   CHECK(clean_shutdown_status_ == CLEANLY_SHUTDOWN ||
         clean_shutdown_status_ == NEED_TO_SHUTDOWN);
   return clean_shutdown_status_ == CLEANLY_SHUTDOWN;
 }
@@ skipping 217 matching lines @@
   if (local_state) {
     const PrefService::Preference* uma_pref =
         local_state->FindPreference(prefs::kMetricsReportingEnabled);
     if (uma_pref) {
       bool success = uma_pref->GetValue()->GetAsBoolean(&result);
       DCHECK(success);
     }
   }
   return result;
 }