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 and waiting for hardware statistics on Chrome OS.
+// 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 36 matching lines @@
 //------------------------------------------------------------------------------
 
 #include "chrome/browser/metrics/metrics_service.h"
 
 #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/string_util.h"
 #include "base/threading/platform_thread.h"
 #include "base/threading/thread.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"
@@ skipping 586 matching lines @@
   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));
+    base::WeakPtr<MetricsService> self) {
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
+#if defined(OS_CHROMEOS)
+  chromeos::system::StatisticsProvider::GetInstance()->WhenReady(
+      base::Bind(&MetricsService::OnStatisticsProviderReady,
+                 self));

[Ilya Sherman, 2012/04/19 19:35:32]

Does the WhenReady() call have any sort of timeout?  I'd be worried about adding
any code to the metrics initialization critical path that can block
indefinitely...

[Joao da Silva, 2012/04/19 19:54:33]

StatisticsProvider is a singleton whose ctor immediately posts to FILE to load
stats from the output of a cmd line tool. WhenReady() fires its callbacks once
this tool returns.

The problem we're seeing is that some hardware is taking very long to initialize
these stats (a couple seconds more than the 30 secs delay for this task). If the
tool didn't ever return it'd completely block the FILE thread, and there'd be
larger problems in that case :-) So this is expected to slightly delay the
MetricsService initialization on only a couple of flaky hardware setups, but
won't affect other cases. It will eventually start in any case.

[Ilya Sherman, 2012/04/19 20:16:54]

What if the StatisticsProvider's task gets scheduled after a task that takes
minutes to run?  (Sadly, these exist sometimes, especially on the FILE thread.) 
I don't think it's appropriate to block the MetricsService initialization path
for that long.

How about instead not making fetching the hardware class be part of the critical
path, e.g. (a) by calling into StatisticsProvider::GetMachineStatistic() when we
would first use hardware_class_ or (b) notifying the MetricsService when the
data is loaded, rather trying to cache it earlier on?

[Joao da Silva, 2012/04/20 11:53:35]

There's another CL that moves its task to the BlockingPool instead; this is just
FYI, it's not relevant for this CL.
At first I went for the lazy, straightforward fix :-) (b) sounds like a good
idea to me, and I've read a bit more of the MetricsService code to figure how to
do that correctly. Please have another look.

+#else
+  if (self)
+    OnInitTaskGotHardwareClass(EmptyString());
+#endif  // OS_CHROMEOS
+}
 
+#if defined(OS_CHROMEOS)
+void MetricsService::OnStatisticsProviderReady() {
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
   std::string hardware_class;
-#if defined(OS_CHROMEOS)
   chromeos::system::StatisticsProvider::GetInstance()->GetMachineStatistic(
       "hardware_class", &hardware_class);
-#endif  // OS_CHROMEOS
-
-  target_loop->PostTask(FROM_HERE,
-      base::Bind(&MetricsService::OnInitTaskGotHardwareClass,
-          self, hardware_class));
+  OnInitTaskGotHardwareClass(hardware_class);
 }
+#endif
 
 void MetricsService::OnInitTaskGotHardwareClass(
     const std::string& hardware_class) {
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
   DCHECK_EQ(state_, INIT_TASK_SCHEDULED);
   hardware_class_ = hardware_class;
 
   // Start the next part of the init task: loading plugin information.
   PluginService::GetInstance()->GetPlugins(
       base::Bind(&MetricsService::OnInitTaskGotPluginInfo,
           self_ptr_factory_.GetWeakPtr()));
 }
 
 void MetricsService::OnInitTaskGotPluginInfo(
@@ skipping 46 matching lines @@
                                    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,
+        BrowserThread::UI,
         FROM_HERE,
         base::Bind(&MetricsService::InitTaskGetHardwareClass,
-            self_ptr_factory_.GetWeakPtr(),
-            MessageLoop::current()->message_loop_proxy()),
+                   self_ptr_factory_.GetWeakPtr()),

[Ilya Sherman, 2012/04/19 19:35:32]

nit: No need to use a weak pointer if this is all happening on the UI thread --
or am I missing something?

[Joao da Silva, 2012/04/19 19:54:33]

The WeakPtr is bound to the callback task passed to WhenReady(), which is posted
with a long delay (30 secs). Shutdown might have started when that task
executes, and |this| might have been deleted by then (unlikely, but possible).

[Ilya Sherman, 2012/04/19 20:16:54]

Fair enough.

         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 813 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;
 }