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 85 matching lines @@
 #include "webkit/plugins/webplugininfo.h"
 
 // TODO(port): port browser_distribution.h.
 #if !defined(OS_POSIX)
 #include "chrome/installer/util/browser_distribution.h"
 #endif
 
 #if defined(OS_CHROMEOS)
 #include "chrome/browser/chromeos/cros/cros_library.h"
 #include "chrome/browser/chromeos/external_metrics.h"
-#include "chrome/browser/chromeos/system/statistics_provider.h"
 #endif
 
 using base::Time;
 using content::BrowserThread;
 using content::ChildProcessData;
 using content::LoadNotificationDetails;
 using content::PluginService;
 
 namespace {
 
 // Check to see that we're being called on only one thread.
 bool IsSingleThreaded() {
   static base::PlatformThreadId thread_id = 0;
   if (!thread_id)
     thread_id = base::PlatformThread::CurrentId();
   return base::PlatformThread::CurrentId() == thread_id;
 }
 
 // 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 143 matching lines @@
 
   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);
 }
 
 MetricsService::~MetricsService() {
   SetRecording(false);
+#if defined(OS_CHROMEOS)
+  chromeos::system::StatisticsProvider::GetInstance()->RemoveObserver(this);

[jar (doing other things), 2012/05/21 18:10:02]

Are we sure it was added before we call this remove?

[Joao da Silva, 2012/05/22 14:55:25]

Removing an observer that isn't registered is OK. Otherwise we'd have to track
whether we are currently observing...

+#endif
 }
 
 void MetricsService::Start() {
   HandleIdleSinceLastTransmission(false);
   SetRecording(true);
   SetReporting(true);
 }
 
 void MetricsService::StartRecordingOnly() {
   SetRecording(true);
@@ skipping 324 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)
+  // Exactly one of these two callbacks will be invoked. |on_timeout_callback_|
+  // is posted to UI with a certain delay; |on_ready_callback_| is invoked
+  // once the StatisticsProvider() becomes ready. Execution of one of these
+  // callbacks cancels the execution of the other.
+  on_timeout_callback_.Reset(
+      base::Bind(&MetricsService::OnStatisticsProviderTimeout,
+                 base::Unretained(this)));
+  on_ready_callback_.Reset(
+      base::Bind(&MetricsService::InitTaskGetPluginInfo,
+                 base::Unretained(this)));
+
+  BrowserThread::PostDelayedTask(
+      BrowserThread::UI, FROM_HERE,
+      on_timeout_callback_.callback(),
+      base::TimeDelta::FromSeconds(kStatisticsProviderTimeoutSeconds));
+
+  // 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()->AddObserver(this);

[jar (doing other things), 2012/05/21 18:10:02]

I *think* the semantics of AddObserver() are such that they sometimes
synchronously call the completion, and other times they actually add to the
list.  This leaves us unsure if we need to do a remove later.

+#else
+  InitTaskGetPluginInfo();
+#endif  // OS_CHROMEOS
+}
+
+#if defined(OS_CHROMEOS)
+
+void MetricsService::OnMachineStatisticsReady() {
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
   chromeos::system::StatisticsProvider::GetInstance()->GetMachineStatistic(
-      "hardware_class", &hardware_class);
+      "hardware_class", &hardware_class_);
+  on_timeout_callback_.Cancel();
+  if (!on_ready_callback_.IsCancelled())

[jar (doing other things), 2012/05/21 18:10:02]

This cancellable callback looks more complex than need be.

This code is only called on the UI thread, and the Run() method on the next
line, if it runs at all, will call InitTaskGetPluginInfo() (just like we do in
the OnStatisticsProviderTimeout().

Why don't we just have boolean like:
get_plugin_info_was_called_

What is the complexity I'm missing?

[Joao da Silva, 2012/05/22 14:55:25]

That's another way to do it, I just wanted to avoid adding that state. I'll
refactor this like that.

[jar (doing other things), 2012/05/22 17:07:58]

Note: You could implement the "was_called" bool inside of the method, so that
extraneous calls would be ignored. That might simplify your concerns about state
(held in the instance), but it might make it harder to test etc.

On 2012/05/22 14:55:25, Joao da Silva wrote:

+    on_ready_callback_.callback().Run();
+}
+
+void MetricsService::OnStatisticsProviderTimeout() {
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
+  // Use an invalid hardware_class temporarily until the StatisticsProvider is
+  // ready.
+  hardware_class_ = kHardwareClassNotReady;
+  on_ready_callback_.Cancel();
+  InitTaskGetPluginInfo();
+}
+
 #endif  // OS_CHROMEOS
 
-  target_loop->PostTask(FROM_HERE,
-      base::Bind(&MetricsService::OnInitTaskGotHardwareClass,
-          self, hardware_class));
-}
-
-void MetricsService::OnInitTaskGotHardwareClass(
-    const std::string& hardware_class) {
+void MetricsService::InitTaskGetPluginInfo() {
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
   DCHECK_EQ(INIT_TASK_SCHEDULED, state_);
-  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()));
+                 self_ptr_factory_.GetWeakPtr()));
 }
 
 void MetricsService::OnInitTaskGotPluginInfo(
     const std::vector<webkit::WebPluginInfo>& plugins) {
   DCHECK_EQ(INIT_TASK_SCHEDULED, state_);
   plugins_ = plugins;
 
   // Schedules a task on a blocking pool thread to gather Google Update
   // statistics (requires Registry reads).
   BrowserThread::PostBlockingPoolTask(
@@ skipping 96 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(

[jar (doing other things), 2012/05/21 18:10:02]

Why are we now willing to do this on the current (UI??) thread?

[Joao da Silva, 2012/05/22 14:55:25]

Because this isn't a blocking operation anymore, it just sets up the timeout
task and registers an observer.

[jar (doing other things), 2012/05/22 17:07:58]

Since it is non-blocking, there should be even less concern about running on the
UI thread.

I think registering an observer is supposed to be done on the "observer's
thread."  All notifications are done synchronously on that thread as well.

If you want cross-thread notification, or registration, you probably need to use
ObserverListThreadSafe... but that might mess things up and get the callback to
the registration thread :-/.

My guess is that you want all registration and notification to happen on the UI
thread... so I think you should go ahead and post to the UI thread still (and
not bother with ObserverListThreadSafe).


On 2012/05/22 14:55:25, Joao da Silva wrote:

[Joao da Silva, 2012/05/22 19:10:09]

I may be misunderstanding, but that is the case. The observer is added in the UI
thread, and the notification also comes in the UI thread.
Alright, I'll leave it as is then.

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