Add/change metrics for cookie store loading:

chrome/browser/net/sqlite_persistent_cookie_store.cc

Index: chrome/browser/net/sqlite_persistent_cookie_store.cc
diff --git a/chrome/browser/net/sqlite_persistent_cookie_store.cc b/chrome/browser/net/sqlite_persistent_cookie_store.cc
index ef531c363f15f15244c1ba60b89d5cbd18b969ce..cb6ace3c63634b29e9c518e7d1360d0d7dd21987 100644
--- a/chrome/browser/net/sqlite_persistent_cookie_store.cc
+++ b/chrome/browser/net/sqlite_persistent_cookie_store.cc
@@ -21,6 +21,7 @@
 #include "base/synchronization/lock.h"
 #include "base/threading/thread.h"
 #include "base/threading/thread_restrictions.h"
+#include "base/time.h"
 #include "chrome/browser/diagnostics/sqlite_diagnostics.h"
 #include "content/public/browser/browser_thread.h"
 #include "googleurl/src/gurl.h"
@@ -39,15 +40,15 @@ using content::BrowserThread;
 // delegates to Backend::Load, which posts a Backend::LoadAndNotifyOnDBThread
 // task to the DB thread.  This task calls Backend::ChainLoadCookies(), which
 // repeatedly posts itself to the DB thread to load each eTLD+1's cookies in
-// separate tasks.  When this is complete, Backend::NotifyOnIOThread is posted
-// to the IO thread, which notifies the caller of SQLitePersistentCookieStore::
-// Load that the load is complete.
+// separate tasks.  When this is complete, Backend::CompleteLoadOnIOThread is
+// posted to the IO thread, which notifies the caller of
+// SQLitePersistentCookieStore::Load that the load is complete.
 //
 // If a priority load request is invoked via SQLitePersistentCookieStore::
 // LoadCookiesForKey, it is delegated to Backend::LoadCookiesForKey, which posts
 // Backend::LoadKeyAndNotifyOnDBThread to the DB thread. That routine loads just
 // that single domain key (eTLD+1)'s cookies, and posts a Backend::
-// NotifyOnIOThread to the IO thread to notify the caller of
+// CompleteLoadForKeyOnIOThread to the IO thread to notify the caller of
 // SQLitePersistentCookieStore::LoadCookiesForKey that that load is complete.
 //
 // Subsequent to loading, mutations may be queued by any thread using
@@ -62,7 +63,10 @@ class SQLitePersistentCookieStore::Backend
         db_(NULL),
         num_pending_(0),
         clear_local_state_on_exit_(false),
-        initialized_(false) {
+        initialized_(false),
+        num_priority_waiting_(0),
+        total_priority_requests_(0),
+        metrics_reporting_deferred_(false) {
   }
 
   // Creates or loads the SQLite database.
@@ -133,9 +137,26 @@ class SQLitePersistentCookieStore::Backend
   // Notifies the CookieMonster when loading completes for a specific domain key
   // or for all domain keys. Triggers the callback and passes it all cookies
   // that have been loaded from DB since last IO notification.
-  void NotifyOnIOThread(
-      const LoadedCallback& loaded_callback,
-      bool load_success);
+  void Notify(const LoadedCallback& loaded_callback, bool load_success);
+
+  // Sends notification when the entire store is loaded, and reports metrics
+  // for the total time to load and aggregated results from any priority loads
+  // that occurred.
+  void CompleteLoadOnIOThread(const LoadedCallback& loaded_callback,
+                              bool load_success);
+
+  // Sends notification when a single priority load completes. Updates priority
+  // load metric data. The data is sent only after the final load completes.
+  void CompleteLoadForKeyOnIOThread(const LoadedCallback& loaded_callback,
+                                    bool load_success);
+
+  // Sends all metrics, including posting a ReportMetricsOnDBThread task.
+  // Called after all priority and regular loading is complete.
+  void ReportMetrics();
+
+  // Sends DB-thread owned metrics (i.e., the combined duration of all DB-thread
+  // tasks).
+  void ReportMetricsOnDBThread();
 
   // Initialize the data base.
   bool InitializeDatabase();
@@ -165,8 +186,7 @@ class SQLitePersistentCookieStore::Backend
   PendingOperationsList::size_type num_pending_;
   // True if the persistent store should be deleted upon destruction.
   bool clear_local_state_on_exit_;
-  // Guard |cookies_|, |pending_|, |num_pending_| and
-  // |clear_local_state_on_exit_|.
+  // Guard |cookies_|, |pending_|, |num_pending_|, |clear_local_state_on_exit_|
   base::Lock lock_;
 
   // Temporary buffer for cookies loaded from DB. Accumulates cookies to reduce
@@ -180,6 +200,26 @@ class SQLitePersistentCookieStore::Backend
   // Indicates if DB has been initialized.
   bool initialized_;
 
+  // The cumulative time spent loading the cookies on the DB thread. Incremented
+  // and reported from the DB thread.
+  base::TimeDelta cookie_load_duration_;
+
+  // Guards the following metrics-related properties (only accessed when
+  // starting/completing priority loads or completing the total load).
+  base::Lock metrics_lock_;

[Randy Smith (Not in Mondays), 2011/11/13 03:38:23]

Why do we need this lock?  All of the variables protected look like they're only
being accessed on the IO thread (LoadCookiesForKey, CompleteLoad*,
ReportMetrics).

[erikwright (departed), 2011/11/13 22:23:31]

Unfortunately, technically Load and LoadCookiesForKey are accessed on any
thread. The CookieMonster calls them on whichever thread it is accessed on
(though they immediately delegate to the DB thread).

I don't know if anyone calls the methods in question from the UI thread, but it
wouldn't be appropriate to assume they won't even if they don't now.

I thought about having the cookie monster always switch to the IO thread before
calling them, but it isn't aware of the IO thread (it would boil down to locking
to whichever thread the cookie monster were constructed on).

I could also have the SQLitePersistentCookieStore post a task to the IO thread,
in order to access the metrics and then post a task to the DB thread, but that
seems even worse than having the lock.

I chose to have a separate lock so that there would not be any contention with
the actual loading process.

[Randy Smith (Not in Mondays), 2011/11/14 19:55:33]

D'oh!  Good point.  If it's still in your plan to make the CookieMonster
non-thread safe at some point, I'd put a TODO() in to get rid of the lock. 
Beyond that, ok.

+  int num_priority_waiting_;
+  // The total number of priority requests.
+  int total_priority_requests_;
+  // The time when |num_priority_waiting_| incremented to 1.
+  base::Time current_priority_wait_start_;
+  // The cumulative duration of time when |num_priority_waiting_| was greater
+  // than 1.
+  base::TimeDelta priority_wait_duration_;
+  // In the case of a race condition where a priority load is ongoing when
+  // regular loading completes, we defer metric reporting until the priority
+  // load completes with this flag.
+  bool metrics_reporting_deferred_;

[Randy Smith (Not in Mondays), 2011/11/13 03:38:23]

I think if you wanted to you could get rid of this without really compromising
the stats.  As I read the code, this will be set if you hit
CompleteLoadOnIOThread while there's still priority loads that have entered
LoadCookiesForKey but haven't exited CompleteLoadForKeyOnIOThread.  But if
that's the case, those priority loads will hit a null keys_to_load_ map, and
won't do anything.  You'll get the total_priority_requests_ bump (since that
happens at the same time as the num_priority_waiting_ increment), and not
including the contribution of that time on the DB thread won't effect your stats
much since it won't touch the database (if you take my other suggestion of just
instrumenting LoadCookiesForDomains, it won't affect your stats at all).  That
lets you get rid of this variable and the check & double call of
ReportMetrics(), which seems a win.  

I'll admit that the above reasoning is a bit complicated, but it still might be
worthwhile trying to assert on it rather than putting in code to handle
something that shouldn't happen.

[erikwright (departed), 2011/11/13 22:23:31]

The race condition does not represent a bug, so asserting on it is not
appropriate. But it is unlikely, and presumably has a negligible impact on
accuracy of the histograms, so I'm happy to remove the deferral. I'll upload a
CL to that effect Monday AM or tonight if possible.

[Randy Smith (Not in Mondays), 2011/11/14 19:55:33]

Why do you say it's not a bug?  I'm not saying it's a bug that a priority load
finishes after the regular load, I'm saying it's a bug (or a "can't happen") if
a priority load that finishes after the regular load loaded anything (==
contributed to the time spent loading).  A "can't happen" that would mess up our
statistics seems worth a DCHECK if we can figure out a way to do it, even if it
won't have any negative effect on user experience.  But that's IMO; I'm not
wedded to the idea.

Mind you, I can't come up with a good way to do the DCHECK(), so the point is
probably moot :-}.

+
   DISALLOW_COPY_AND_ASSIGN(Backend);
 };
 
@@ -196,6 +236,29 @@ static const int kCompatibleVersionNumber = 3;
 
 namespace {
 
+// Increments a specified TimeDelta by the duration between this object's
+// constructor and destructor. Not thread safe. Multiple instances may be
+// created with the same delta instance as long as their lifetimes are nested.
+// The shortest lived instances have no impact.

[Randy Smith (Not in Mondays), 2011/11/13 03:38:23]

Nice idea!  I have to admit, the thing I'd really like is a class where the
delta got automatically incremented by the time that any IncrementTimeDelta's
pointing to it were alive (i.e. overlapping IncrementTimeDeltas working
properly, not just nested ones), but I don't think there's a way to provide that
functionality easily.

[erikwright (departed), 2011/11/13 22:23:31]

If there were other places looking for the same thing, it wouldn't be that hard,
but it isn't needed here.

If you point me at an opportunity for re-use I will do something with it, though
possibly in a separate commit. I took a quick look with the following query but
didn't find anything:

http://codesearch.google.com/codesearch#search/&exact_package=chromium&q=%5E%...

+class IncrementTimeDelta {

[Randy Smith (Not in Mondays), 2011/11/13 03:38:23]

Looking over this code, I think it would be simpler and (I believe--WDYT?) just
about accurate, if we just had a start/end timer in LoadCookiesForDomain--I
don't really believe that anything else could really take a lot of time (maybe
InitializeDatabase?).  I won't block you doing it this way, but I do wonder if
it's worth the extra code complexity.

[erikwright (departed), 2011/11/13 22:23:31]

Initialize DB is a significant cost, based on Hui's experiments. We saw it take
150ms out of 500ms total load times.

[Randy Smith (Not in Mondays), 2011/11/14 19:55:33]

Completely fair; I'd just solve that by incrementing the appropriate counter
both there and in LoadCookiesForDomain, rather than the extra fanciness of the
possibly nested class.  Your call; just wanted to call out a possibly simpler
alternative.

+ public:
+  explicit IncrementTimeDelta(base::TimeDelta* delta) :
+      delta_(delta),
+      original_value_(*delta),
+      start_(base::Time::Now()) {}
+
+  ~IncrementTimeDelta() {
+    *delta_ = original_value_ + base::Time::Now() - start_;
+  }
+
+ private:
+  base::TimeDelta* delta_;
+  base::TimeDelta original_value_;
+  base::Time start_;
+
+  DISALLOW_COPY_AND_ASSIGN(IncrementTimeDelta);
+};
+
 // Initializes the cookies table, returning true on success.
 bool InitTable(sql::Connection* db) {
   if (!db->DoesTableExist("cookies")) {
@@ -237,6 +300,14 @@ void SQLitePersistentCookieStore::Backend::Load(
 void SQLitePersistentCookieStore::Backend::LoadCookiesForKey(
     const std::string& key,
     const LoadedCallback& loaded_callback) {
+  {
+    base::AutoLock locked(metrics_lock_);
+    if (num_priority_waiting_ == 0)
+      current_priority_wait_start_ = base::Time::Now();
+    num_priority_waiting_++;
+    total_priority_requests_++;
+  }
+
   BrowserThread::PostTask(
     BrowserThread::DB, FROM_HERE,
     base::Bind(&Backend::LoadKeyAndNotifyOnDBThread, this,
@@ -247,11 +318,12 @@ void SQLitePersistentCookieStore::Backend::LoadCookiesForKey(
 void SQLitePersistentCookieStore::Backend::LoadAndNotifyOnDBThread(
     const LoadedCallback& loaded_callback) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::DB));
+  IncrementTimeDelta increment(&cookie_load_duration_);
 
   if (!InitializeDatabase()) {
     BrowserThread::PostTask(
       BrowserThread::IO, FROM_HERE,
-      base::Bind(&SQLitePersistentCookieStore::Backend::NotifyOnIOThread,
+      base::Bind(&SQLitePersistentCookieStore::Backend::CompleteLoadOnIOThread,
                  this, loaded_callback, false));
   } else {
     ChainLoadCookies(loaded_callback);
@@ -262,6 +334,7 @@ void SQLitePersistentCookieStore::Backend::LoadKeyAndNotifyOnDBThread(
     const std::string& key,
     const LoadedCallback& loaded_callback) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::DB));
+  IncrementTimeDelta increment(&cookie_load_duration_);
 
   bool success = false;
   if (InitializeDatabase()) {
@@ -277,11 +350,74 @@ void SQLitePersistentCookieStore::Backend::LoadKeyAndNotifyOnDBThread(
 
   BrowserThread::PostTask(
     BrowserThread::IO, FROM_HERE,
-    base::Bind(&SQLitePersistentCookieStore::Backend::NotifyOnIOThread,
-    this, loaded_callback, success));
+    base::Bind(
+        &SQLitePersistentCookieStore::Backend::CompleteLoadForKeyOnIOThread,
+        this, loaded_callback, success));
+}
+
+void SQLitePersistentCookieStore::Backend::CompleteLoadForKeyOnIOThread(
+    const LoadedCallback& loaded_callback,
+    bool load_success) {
+  Notify(loaded_callback, load_success);
+
+  {
+    base::AutoLock locked(metrics_lock_);
+    num_priority_waiting_--;
+    if (num_priority_waiting_ == 0) {
+      priority_wait_duration_ +=
+          base::Time::Now() - current_priority_wait_start_;
+      if (metrics_reporting_deferred_) {
+        metrics_reporting_deferred_ = false;
+        ReportMetrics();
+      }
+    }
+  }
+
+}
+
+void SQLitePersistentCookieStore::Backend::ReportMetricsOnDBThread() {
+  UMA_HISTOGRAM_CUSTOM_TIMES(
+      "Cookie.TimeLoad",
+      cookie_load_duration_,
+      base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromMinutes(1),
+      50);
+}
+
+void SQLitePersistentCookieStore::Backend::ReportMetrics() {
+  metrics_lock_.AssertAcquired();
+
+  BrowserThread::PostTask(BrowserThread::DB, FROM_HERE, base::Bind(
+      &SQLitePersistentCookieStore::Backend::ReportMetricsOnDBThread, this));
+
+  UMA_HISTOGRAM_CUSTOM_TIMES(
+      "Cookie.PriorityBlockingTime",
+      priority_wait_duration_,
+      base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromMinutes(1),
+      50);
+
+  UMA_HISTOGRAM_COUNTS_100(
+      "Cookie.PriorityLoadCount",
+      total_priority_requests_);
+}
+
+void SQLitePersistentCookieStore::Backend::CompleteLoadOnIOThread(
+    const LoadedCallback& loaded_callback, bool load_success) {
+  Notify(loaded_callback, load_success);
+
+  if (load_success) {
+    base::AutoLock locked(metrics_lock_);
+
+    // There is a race condition where a priority load could complete after
+    // regular loading completes. In that case, defer metric reporting. See
+    // CompleteLoadForKeyOnIOThread for the continuation.
+    if (num_priority_waiting_ == 0)
+      ReportMetrics();
+    else
+      metrics_reporting_deferred_ = true;
+  }
 }
 
-void SQLitePersistentCookieStore::Backend::NotifyOnIOThread(
+void SQLitePersistentCookieStore::Backend::Notify(
     const LoadedCallback& loaded_callback,
     bool load_success) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
@@ -355,6 +491,7 @@ bool SQLitePersistentCookieStore::Backend::InitializeDatabase() {
 void SQLitePersistentCookieStore::Backend::ChainLoadCookies(
     const LoadedCallback& loaded_callback) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::DB));
+  IncrementTimeDelta increment(&cookie_load_duration_);
 
   bool load_success = true;
 
@@ -376,7 +513,7 @@ void SQLitePersistentCookieStore::Backend::ChainLoadCookies(
   } else {
     BrowserThread::PostTask(
       BrowserThread::IO, FROM_HERE,
-      base::Bind(&SQLitePersistentCookieStore::Backend::NotifyOnIOThread,
+      base::Bind(&SQLitePersistentCookieStore::Backend::CompleteLoadOnIOThread,
                  this, loaded_callback, load_success));
   }
 }