Added asynchronous notification of readiness to the StatisticsProvider, and

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
@@ skipping 71 matching lines @@
 //    SENDING_OLD_LOGS,       // Sending unsent logs from previous session.
 //    SENDING_CURRENT_LOGS,   // Sending standard current logs as they accrue.
 //
 // 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.
-// 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.
+// Typically about 30 seconds after startup, a task is posted 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.
@@ skipping 39 matching lines @@
 
 #include "base/bind.h"
 #include "base/callback.h"
 #include "base/command_line.h"
 #include "base/md5.h"
 #include "base/metrics/histogram.h"
 #include "base/string_number_conversions.h"
 #include "base/threading/platform_thread.h"
 #include "base/threading/thread.h"
 #include "base/threading/thread_restrictions.h"
+#include "base/time.h"
 #include "base/tracked_objects.h"
 #include "base/utf_string_conversions.h"
 #include "base/values.h"
 #include "chrome/browser/bookmarks/bookmark_model.h"
 #include "chrome/browser/browser_process.h"
 #include "chrome/browser/extensions/extension_service.h"
 #include "chrome/browser/extensions/process_map.h"
 #include "chrome/browser/io_thread.h"
 #include "chrome/browser/memory_details.h"
 #include "chrome/browser/metrics/histogram_synchronizer.h"
@@ skipping 56 matching lines @@
 const char kMetricsTypeProto[] = "application/vnd.chrome.uma";
 
 const char kServerUrlXml[] =
     "https://clients4.google.com/firefox/metrics/collect";
 const char kServerUrlProto[] = "https://clients4.google.com/uma/v2";
 
 // The delay, in seconds, after starting recording before doing expensive
 // initialization work.
 const int kInitializationDelaySeconds = 30;
 
+// The timeout, in seconds, to resume initialization of the MetricsService if
+// the initialization of the StatisticsProvider hasn't completed yet.
+const int kStatisticsProviderTimeoutSeconds = 300;
+
 // This specifies the amount of time to wait for all renderers to send their
 // data.
 const int kMaxHistogramGatheringWaitDuration = 60000;  // 60 seconds.
 
 // The maximum number of events in a log uploaded to the UMA server.
 const int kEventLimit = 2400;
 
 // 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 = 50000;
 
 // Interval, in minutes, between state saves.
 const int kSaveStateIntervalMinutes = 5;
 
 // Used to indicate that the response code is currently not set at all --
 // RESPONSE_CODE_INVALID can sometimes be returned in response to a request if,
 // e.g., the server is down.
 const int kNoResponseCode = content::URLFetcher::RESPONSE_CODE_INVALID - 1;
 
+// Used to indicate that a report was generated before the hardware_class
+// property was available from the StatisticsProvider. This is used to identify
+// faulty reports from Chrome OS clients.
+const char kHardwareClassNotReady[] = "(not ready)";
+
 }
 
 // static
 MetricsService::ShutdownCleanliness MetricsService::clean_shutdown_status_ =
     MetricsService::CLEANLY_SHUTDOWN;
 
 // This is used to quickly log stats from child process related notifications in
 // MetricsService::child_stats_buffer_.  The buffer's contents are transferred
 // out when Local State is periodically saved.  The information is then
 // reported to the UMA server on next launch.
@@ skipping 130 matching lines @@
 }
 
 MetricsService::MetricsService()
     : recording_active_(false),
       reporting_active_(false),
       state_(INITIALIZED),
       idle_since_last_transmission_(false),
       next_window_id_(0),
       ALLOW_THIS_IN_INITIALIZER_LIST(self_ptr_factory_(this)),
       ALLOW_THIS_IN_INITIALIZER_LIST(state_saver_factory_(this)),
+      ALLOW_THIS_IN_INITIALIZER_LIST(timeout_task_factory_(this)),
       waiting_for_asynchronus_reporting_step_(false) {
   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);
 }
@@ skipping 337 matching lines @@
   size_t switch_count = command_line->GetSwitches().size();
   UMA_HISTOGRAM_COUNTS_100("Chrome.CommandLineFlagCount", switch_count);
   UMA_HISTOGRAM_COUNTS_100("Chrome.CommandLineUncommonFlagCount",
                            switch_count - common_commands);
 
   // Kick off the process of saving the state (so the uptime numbers keep
   // getting updated) every n minutes.
   ScheduleNextStateSave();
 }
 
-// static
-void MetricsService::InitTaskGetHardwareClass(
-    base::WeakPtr<MetricsService> self,
-    base::MessageLoopProxy* target_loop) {
-  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::FILE));
+void MetricsService::InitTaskGetHardwareClass() {
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
+  DCHECK_EQ(INIT_TASK_SCHEDULED, state_);
 
-  std::string hardware_class;
 #if defined(OS_CHROMEOS)
-  chromeos::system::StatisticsProvider::GetInstance()->GetMachineStatistic(
-      "hardware_class", &hardware_class);
-#endif  // OS_CHROMEOS
+  // The hardware class can only be retrieved once the StatisticsProvider is
+  // ready. This usually happens early enough, but can take longer on some
+  // faulty hardware.
+  chromeos::system::StatisticsProvider::GetInstance()->WhenReady(
+      base::Bind(&MetricsService::OnStatisticsProviderReady,
+                 self_ptr_factory_.GetWeakPtr(),
+                 base::Time::Now()));
 
-  target_loop->PostTask(FROM_HERE,
-      base::Bind(&MetricsService::OnInitTaskGotHardwareClass,
-          self, hardware_class));
+  // Set up a timeout task in case the StatisticsProvider takes too long to
+  // initialize. Only one of these tasks will execute; invoking either
+  // invalidates the WeakPtr of the other. In both cases, hardware_class_ is
+  // updated once OnStatisticsProviderReady is invoked.
+
+  // Invoke the next init task if the StatisticsProvider becomes ready.
+  // This will be invoked immediately after OnStatisticsProviderReady.
+  chromeos::system::StatisticsProvider::GetInstance()->WhenReady(
+      base::Bind(&MetricsService::InitTaskGetPluginInfo,
+                 timeout_task_factory_.GetWeakPtr()));
+
+  // Invoke OnStatisticsProviderTimeout if it times out instead.
+  MessageLoop::current()->PostDelayedTask(
+      FROM_HERE,
+      base::Bind(&MetricsService::OnStatisticsProviderTimeout,
+                 timeout_task_factory_.GetWeakPtr()),
+      base::TimeDelta::FromSeconds(kStatisticsProviderTimeoutSeconds));
+#else
+  InitTaskGetPluginInfo();
+#endif
 }
 
-void MetricsService::OnInitTaskGotHardwareClass(
-    const std::string& hardware_class) {
+void MetricsService::OnStatisticsProviderReady(const base::Time& start_time) {
+#if defined(OS_CHROMEOS)
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
+  base::TimeDelta elapsed = base::Time::Now() - start_time;
+  UMA_HISTOGRAM_LONG_TIMES("UMA.StatisticsProviderReadyDelay", elapsed);
+  chromeos::system::StatisticsProvider::GetInstance()->GetMachineStatistic(
+      "hardware_class", &hardware_class_);
+#endif
+}
+
+void MetricsService::OnStatisticsProviderTimeout() {

[Ilya Sherman, 2012/04/30 07:36:41]

nit: Perhaps log a histogram/event for the timeout case as well?

[Joao da Silva, 2012/05/15 13:52:47]

Good idea. I've moved these histograms to the StatisticsProvider code and added
this one there as well.

+#if defined(OS_CHROMEOS)
+  // Use an invalid hardware_class temporarily until the StatisticsProvider is
+  // ready.

[Ilya Sherman, 2012/04/30 07:36:41]

It looks like, with this setup, we'll never record the hardware class if we
reach the timeout, even for ongoing uploads.  Am I misreading the code?  If not,
it would be nice to still listen for the "ready" event from the
StatisticsProvider, just not have it block the init path, in the case of a
timeout.

[Joao da Silva, 2012/05/15 13:52:47]

The WhenReady() callback is still pending in this case, and will update
hardware_class_ once it executes. This code has changed meanwhile.

+  hardware_class_ = kHardwareClassNotReady;
+  InitTaskGetPluginInfo();
+#endif
+}
+
+void MetricsService::InitTaskGetPluginInfo() {
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
   DCHECK_EQ(INIT_TASK_SCHEDULED, state_);
-  hardware_class_ = hardware_class;
+
+  // Invalidate tasks related to waiting for the StatisticsProvider to
+  // initialize, if any are still scheduled.
+  timeout_task_factory_.InvalidateWeakPtrs();
 
   // Start the next part of the init task: loading plugin information.
   PluginService::GetInstance()->GetPlugins(
       base::Bind(&MetricsService::OnInitTaskGotPluginInfo,
-          self_ptr_factory_.GetWeakPtr()));
+                 self_ptr_factory_.GetWeakPtr()));
 }
 
 void MetricsService::OnInitTaskGotPluginInfo(
     const std::vector<webkit::WebPluginInfo>& plugins) {
   DCHECK_EQ(INIT_TASK_SCHEDULED, state_);
   plugins_ = plugins;
 
   // Start the next part of the init task: fetching performance data.  This will
   // call into |FinishedReceivingProfilerData()| when the task completes.
   chrome_browser_metrics::TrackingSynchronizer::FetchProfilerDataAsynchronously(
@@ skipping 54 matching lines @@
 void MetricsService::StartRecording() {
   if (log_manager_.current_log())
     return;
 
   log_manager_.BeginLoggingWithLog(new MetricsLog(client_id_, session_id_),
                                    MetricsLogManager::ONGOING_LOG);
   if (state_ == INITIALIZED) {
     // We only need to schedule that run once.
     state_ = INIT_TASK_SCHEDULED;
 
-    // Schedules a task on the file thread for execution of slower
-    // initialization steps (such as plugin list generation) necessary
-    // for sending the initial log.  This avoids blocking the main UI
-    // thread.
-    BrowserThread::PostDelayedTask(
-        BrowserThread::FILE,
+    // Schedules a delayed task for execution of slower initialization steps
+    // (such as plugin list generation) necessary for sending the initial log.
+    MessageLoop::current()->PostDelayedTask(
         FROM_HERE,
         base::Bind(&MetricsService::InitTaskGetHardwareClass,
-            self_ptr_factory_.GetWeakPtr(),
-            MessageLoop::current()->message_loop_proxy()),
+                   self_ptr_factory_.GetWeakPtr()),
         base::TimeDelta::FromSeconds(kInitializationDelaySeconds));
   }
 }
 
 void MetricsService::StopRecording() {
   if (!log_manager_.current_log())
     return;
 
   // TODO(jar): Integrate bounds on log recording more consistently, so that we
   // can stop recording logs that are too big much sooner.
@@ skipping 816 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;
 }