Added asynchronous notification of readiness to the StatisticsProvider, and

chrome/browser/chromeos/system/statistics_provider.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.
 
 #include "chrome/browser/chromeos/system/statistics_provider.h"
 
 #include "base/bind.h"
+#include "base/bind_helpers.h"
 #include "base/chromeos/chromeos_version.h"
 #include "base/file_path.h"
 #include "base/file_util.h"
 #include "base/logging.h"
 #include "base/memory/singleton.h"
+#include "base/message_loop.h"
 #include "base/synchronization/waitable_event.h"
 #include "base/time.h"
 #include "base/chromeos/chromeos_version.h"
 #include "chrome/browser/chromeos/system/name_value_pairs_parser.h"
 #include "chrome/common/child_process_logging.h"
 #include "chrome/common/chrome_version_info.h"
 #include "content/public/browser/browser_thread.h"
 
 using content::BrowserThread;
 
@@ skipping 32 matching lines @@
 const char kMachineOSInfoDelim[] = "\n";
 
 // File to get VPD info from, and key/value delimiters of the file.
 const char kVpdFile[] = "/var/log/vpd_2.0.txt";
 const char kVpdEq[] = "=";
 const char kVpdDelim[] = "\n";
 
 // Timeout that we should wait for statistics to get loaded
 const int kTimeoutSecs = 3;
 
+// Helper to invoke |callbacks| on the UI thread.
+void NotifyOnUI(std::vector<base::Closure>* callbacks) {
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
+  for (std::vector<base::Closure>::iterator it = callbacks->begin();
+       it != callbacks->end(); ++it) {
+    it->Run();
+  }
+}
+
 }  // namespace
 
 // The StatisticsProvider implementation used in production.
 class StatisticsProviderImpl : public StatisticsProvider {
  public:
   // StatisticsProvider implementation:
   virtual bool GetMachineStatistic(const std::string& name,
                                    std::string* result) OVERRIDE;
 
+  virtual void WhenReady(const base::Closure& callback) OVERRIDE;
+
   static StatisticsProviderImpl* GetInstance();
 
  private:
   friend struct DefaultSingletonTraits<StatisticsProviderImpl>;
 
   StatisticsProviderImpl();
 
   // Starts loading the machine statistcs.
   void StartLoadingMachineStatistics();
 
   // Loads the machine statistcs by examining the system.
   void LoadMachineStatistics();
 
   NameValuePairsParser::NameValueMap machine_info_;
   base::WaitableEvent on_statistics_loaded_;
+  std::vector<base::Closure> callbacks_;
 
   DISALLOW_COPY_AND_ASSIGN(StatisticsProviderImpl);
 };
 
 bool StatisticsProviderImpl::GetMachineStatistic(
     const std::string& name, std::string* result) {

[jar (doing other things), 2012/04/24 18:37:40]

nit: arguments should be aligned, one per line.

[Joao da Silva, 2012/04/27 09:47:48]

Done.

   VLOG(1) << "Statistic is requested for " << name;
   // Block if the statistics are not loaded yet. Per LOG(WARNING) below,
   // the statistics are loaded before requested as of now. For regular
   // sessions (i.e. not OOBE), statistics are first requested when the
   // user is logging in so we have plenty of time to load the data
   // beforehand.
   //
   // If you see the warning appeared for regular sessions, it probably
   // means that there is new client code that uses the statistics in the
   // very early stage of the browser startup. The statistic name should be
   // helpful to identify the caller.
   if (!on_statistics_loaded_.IsSignaled()) {
     LOG(WARNING) << "Waiting to load statistics. Requested statistic: "

[jar (doing other things), 2012/04/24 18:37:40]

To reduce the size of the binary, brett made a big sweep getting rid of LOG
messages, and turning them into DLOG.  Messages like the above probably never
get looked at, clog the logs, and tend to provide little to no value.

I suspect other LOG messages below are also worth considering transition to
DLOG.

[Joao da Silva, 2012/04/27 09:47:48]

Agree, done.

                  << name;
     on_statistics_loaded_.TimedWait(base::TimeDelta::FromSeconds(kTimeoutSecs));

[jar (doing other things), 2012/04/24 18:37:40]

IMO, the timeout should definitely be part of the function argument list.  The
caller is in a much better position to decide how long it wishes to wait, and
having this unknown time-out (unknown to the caller) makes this very
questionable to use.

[Joao da Silva, 2012/04/27 09:47:48]

This is definitely questionable and can surprise callers; I think the right
approach for these cases are async interfaces.

 
     if (!on_statistics_loaded_.IsSignaled()) {
       LOG(ERROR) << "Statistics weren't loaded after waiting! "
                  << "Requested statistic: " << name;
       return false;
     }
   }
 
   NameValuePairsParser::NameValueMap::iterator iter = machine_info_.find(name);
   if (iter != machine_info_.end()) {
     *result = iter->second;
     return true;
   }
   return false;

[jar (doing other things), 2012/04/24 18:37:40]

This API makes it impossible to tell whether there was a time-out, or if the
value was not present.  Hence you can't tell if it is "worth asking again."

[Joao da Silva, 2012/04/27 09:47:48]

This problem doesn't exist with the async notification; every user of this
interface should be refactored to use the async interface, and the WaitableEvent
should be removed.

[jar (doing other things), 2012/04/27 18:00:38]

I think what you're saying is that you plan to remove this API... and hence you
don't want to fix it.  Is that correct?

On 2012/04/27 09:47:48, Joao da Silva wrote:

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

This API is used in a couple of places that aren't straightforward to refactor
to wait for the asynchronous notification. For example,
StartupCustomizationDocument (chrome/browser/chromeos/customization_document.cc)
call this from the ctor, and I don't see an easy way to make it wait for an
async notification.

So for now I'd like to fix the problem at hand (empty hardware_class in UMA
reports), and introduce an API that clients who care should use :-)

 }
 
+void StatisticsProviderImpl::WhenReady(const base::Closure& callback) {
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
+  if (on_statistics_loaded_.IsSignaled()) {
+    // Don't assume the caller is re-entrant.
+    BrowserThread::PostTask(BrowserThread::UI, FROM_HERE, callback);
+  } else {
+    callbacks_.push_back(callback);
+  }
+}
+
 // manual_reset needs to be true, as we want to keep the signaled state.
 StatisticsProviderImpl::StatisticsProviderImpl()
     : on_statistics_loaded_(true  /* manual_reset */,
                             false /* initially_signaled */) {
   StartLoadingMachineStatistics();
 }
 
 void StatisticsProviderImpl::StartLoadingMachineStatistics() {
   VLOG(1) << "Started loading statistics";
   BrowserThread::PostBlockingPoolTask(
       FROM_HERE,
       base::Bind(&StatisticsProviderImpl::LoadMachineStatistics,
                  base::Unretained(this)));
 }
 
 void StatisticsProviderImpl::LoadMachineStatistics() {
   NameValuePairsParser parser(&machine_info_);
 
   // Parse all of the key/value pairs from the crossystem tool.
   if (!parser.ParseNameValuePairsFromTool(
           arraysize(kCrosSystemTool), kCrosSystemTool, kCrosSystemEq,
           kCrosSystemDelim, kCrosSystemCommentDelim)) {
     LOG(WARNING) << "There were errors parsing the output of "

[jar (doing other things), 2012/04/24 18:37:40]

Shouldn't there be action taken to rectify this situation?  Is this LOG message
valuable? If there was value to be had here, I'd expect that a error report,
sent via UMA, such as in a histogram would be much more useful (informative).

[Joao da Silva, 2012/04/27 09:47:48]

Yes indeed! Added a UMA_HISTOGRAM_BOOLEAN to sample this case.

                  << kCrosSystemTool << ".";
   }
 
   // Ensure that the hardware class key is present with the expected
   // key name, and if it couldn't be retrieved, that the value is "unknown".
   std::string hardware_class = machine_info_[kHardwareClassCrosSystemKey];
   if (hardware_class.empty() || hardware_class == kCrosSystemUnknownValue)
     machine_info_[kHardwareClassKey] = kUnknownHardwareClass;
   else
     machine_info_[kHardwareClassKey] = hardware_class;
 
   parser.GetNameValuePairsFromFile(FilePath(kMachineHardwareInfoFile),
                                    kMachineHardwareInfoEq,
                                    kMachineHardwareInfoDelim);
   parser.GetNameValuePairsFromFile(FilePath(kEchoCouponFile),
                                    kEchoCouponEq,
                                    kEchoCouponDelim);
   parser.GetNameValuePairsFromFile(FilePath(kMachineOSInfoFile),
                                    kMachineOSInfoEq,
                                    kMachineOSInfoDelim);
   parser.GetNameValuePairsFromFile(FilePath(kVpdFile), kVpdEq, kVpdDelim);
 
   // Finished loading the statistics.
   on_statistics_loaded_.Signal();
   VLOG(1) << "Finished loading statistics";
 
+  // Any callbacks registed before Signal() are in |callbacks_|. Any registed
+  // after Signal() will be immediately posted. NotifyOnUI() posts the callbacks
+  // in |callbacks_| from the UI loop.
+  std::vector<base::Closure>* callbacks = new std::vector<base::Closure>();
+  callbacks->swap(callbacks_);

[jar (doing other things), 2012/04/24 18:37:40]

What thread are you running on?  Are you ensured to be on the UI thread, where
callbacks is accessed?

[Joao da Silva, 2012/04/27 09:47:48]

This happens in the blocking pool, but the callbacks are passed to UI before
being invoked. The |callbacks_| vector isn't modified from UI anymore after
signaling the WaitableEvent.

[jar (doing other things), 2012/04/27 18:00:38]

It appears as though the line:

callbacks_.push_back(callback);

can be executed asynchronously on the UI thread.  Keep in mind that the test
that preceeds it (by several lines) may be executed befroe you Signal() on line
196 (since we are on different threads).

It is not clear to me what will happen if the swap() is being executed at the
same time as the push is being attempted.  It is plausible that you'd be safe,
but it is also quite likely that we'd corrupt memory.

What am I missing?

On 2012/04/27 09:47:48, Joao da Silva wrote:

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

You're totally right. I tried to make this a static method to execute on the
blocking pool and pass it a WeakPtr created from UI so that it could signal
completion to UI, and pass the parsed data along the callback. However that'd
mean that whoever is blocking in GetMachineStatistic() won't see the data before
this task runs in UI too, so I gave up that approach.

The current solution is to post back to UI a task just to invoke the callbacks,
but keep the WaitableEvent to unblock whoever might be waiting at
GetMachineStatistic() on UI. WDYT?

(I'd really really like to get the whole thing right, but it's not easy at all
to modify callers of GetMachineStatistic() that expect it to be a synchronous
call...)

+  BrowserThread::PostTask(BrowserThread::UI, FROM_HERE,
+                          base::Bind(NotifyOnUI, base::Owned(callbacks)));
+
 #if defined(GOOGLE_CHROME_BUILD)
   // TODO(kochi): This is for providing a channel information to
   // chrome::VersionInfo::GetChannel()/GetVersionStringModifier(),
   // but this is still late for some early customers such as
   // prerender::ConfigurePrefetchAndPrerender() and
   // ThreadWatcherList::ParseCommandLine().
   // See http://crbug.com/107333 .
   const char kChromeOSReleaseTrack[] = "CHROMEOS_RELEASE_TRACK";
   std::string channel;
   if (GetMachineStatistic(kChromeOSReleaseTrack, &channel)) {
@@ skipping 18 matching lines @@
 
 // The stub StatisticsProvider implementation used on Linux desktop.
 class StatisticsProviderStubImpl : public StatisticsProvider {
  public:
   // StatisticsProvider implementation:
   virtual bool GetMachineStatistic(const std::string& name,
                                    std::string* result) OVERRIDE {
     return false;
   }
 
+  virtual void WhenReady(const base::Closure& callback) OVERRIDE {
+    DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
+    BrowserThread::PostTask(BrowserThread::UI, FROM_HERE, callback);
+  }
+
   static StatisticsProviderStubImpl* GetInstance() {
     return Singleton<StatisticsProviderStubImpl,
         DefaultSingletonTraits<StatisticsProviderStubImpl> >::get();
   }
 
  private:
   friend struct DefaultSingletonTraits<StatisticsProviderStubImpl>;
 
   StatisticsProviderStubImpl() {
   }
 
   DISALLOW_COPY_AND_ASSIGN(StatisticsProviderStubImpl);
 };
 
 StatisticsProvider* StatisticsProvider::GetInstance() {
   if (base::chromeos::IsRunningOnChromeOS()) {
     return StatisticsProviderImpl::GetInstance();
   } else {
     return StatisticsProviderStubImpl::GetInstance();
   }
 }
 
 }  // namespace system
 }  // namespace chromeos