Add/change metrics for cookie store loading:

chrome/browser/net/sqlite_persistent_cookie_store.cc

 // Copyright (c) 2011 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/net/sqlite_persistent_cookie_store.h"
 
 #include <list>
 #include <map>
 #include <set>
 #include <utility>
 
 #include "base/basictypes.h"
 #include "base/bind.h"
 #include "base/file_path.h"
 #include "base/file_util.h"
 #include "base/logging.h"
 #include "base/memory/ref_counted.h"
 #include "base/memory/scoped_ptr.h"
 #include "base/metrics/histogram.h"
 #include "base/string_util.h"
 #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"
 #include "net/base/registry_controlled_domain.h"
 #include "sql/meta_table.h"
 #include "sql/statement.h"
 #include "sql/transaction.h"
 
 using base::Time;
 using content::BrowserThread;
 
 // This class is designed to be shared between any calling threads and the
 // database thread. It batches operations and commits them on a timer.
 //
 // SQLitePersistentCookieStore::Load is called to load all cookies.  It
 // 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
 // AddCookie, UpdateCookieAccessTime, and DeleteCookie. These are flushed to
 // disk on the DB thread every 30 seconds, 512 operations, or call to Flush(),
 // whichever occurs first.
 class SQLitePersistentCookieStore::Backend
     : public base::RefCountedThreadSafe<SQLitePersistentCookieStore::Backend> {
  public:
   explicit Backend(const FilePath& path)
       : path_(path),
         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.
   void Load(const LoadedCallback& loaded_callback);
 
   // Loads cookies for the domain key (eTLD+1).
   void LoadCookiesForKey(const std::string& domain,
       const LoadedCallback& loaded_callback);
 
   // Batch a cookie addition.
@@ skipping 50 matching lines @@
   // Creates or loads the SQLite database on DB thread.
   void LoadAndNotifyOnDBThread(const LoadedCallback& loaded_callback);
 
   // Loads cookies for the domain key (eTLD+1) on DB thread.
   void LoadKeyAndNotifyOnDBThread(const std::string& domains,
       const LoadedCallback& loaded_callback);
 
   // 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();
 
   // Loads cookies for the next domain key from the DB, then either reschedules
   // itself or schedules the provided callback to run on the IO thread (if all
   // domains are loaded).
   void ChainLoadCookies(const LoadedCallback& loaded_callback);
 
   // Load all cookies for a set of domains/hosts
   bool LoadCookiesForDomains(const std::set<std::string>& key);
 
   // Batch a cookie operation (add or delete)
   void BatchOperation(PendingOperation::OperationType op,
                       const net::CookieMonster::CanonicalCookie& cc);
   // Commit our pending operations to the database.
   void Commit();
   // Close() executed on the background thread.
   void InternalBackgroundClose();
 
   FilePath path_;
   scoped_ptr<sql::Connection> db_;
   sql::MetaTable meta_table_;
 
   typedef std::list<PendingOperation*> PendingOperationsList;
   PendingOperationsList pending_;
   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
   // the number of messages sent to the IO thread. Sent back in response to
   // individual load requests for domain keys or when all loading completes.
   std::vector<net::CookieMonster::CanonicalCookie*> cookies_;
 
   // Map of domain keys(eTLD+1) to domains/hosts that are to be loaded from DB.
   std::map<std::string, std::set<std::string> > keys_to_load_;
 
   // 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);
 };
 
 // Version number of the database. In version 4, we migrated the time epoch.
 // If you open the DB with an older version on Mac or Linux, the times will
 // look wonky, but the file will likely be usable. On Windows version 3 and 4
 // are the same.
 //
 // Version 3 updated the database to include the last access time, so we can
 // expire them in decreasing order of use when we've reached the maximum
 // number of cookies.
 static const int kCurrentVersionNumber = 4;
 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")) {
     if (!db->Execute("CREATE TABLE cookies ("
                      "creation_utc INTEGER NOT NULL UNIQUE PRIMARY KEY,"
                      "host_key TEXT NOT NULL,"
                      "name TEXT NOT NULL,"
                      "value TEXT NOT NULL,"
                      "path TEXT NOT NULL,"
                      // We only store persistent, so we know it expires
@@ skipping 21 matching lines @@
   // This function should be called only once per instance.
   DCHECK(!db_.get());
   BrowserThread::PostTask(
       BrowserThread::DB, FROM_HERE,
       base::Bind(&Backend::LoadAndNotifyOnDBThread, this, loaded_callback));
 }
 
 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,
     key,
     loaded_callback));
 }
 
 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);
   }
 }
 
 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()) {
     std::map<std::string, std::set<std::string> >::iterator
       it = keys_to_load_.find(key);
     if (it != keys_to_load_.end()) {
       success = LoadCookiesForDomains(it->second);
       keys_to_load_.erase(it);
     } else {
       success = true;
     }
   }
 
   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::NotifyOnIOThread(
+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::Notify(
     const LoadedCallback& loaded_callback,
     bool load_success) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
 
   std::vector<net::CookieMonster::CanonicalCookie*> cookies;
   {
     base::AutoLock locked(lock_);
     cookies.swap(cookies_);
   }
 
@@ skipping 53 matching lines @@
     it->second.insert(domain);
   }
 
   initialized_ = true;
   return true;
 }
 
 void SQLitePersistentCookieStore::Backend::ChainLoadCookies(
     const LoadedCallback& loaded_callback) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::DB));
+  IncrementTimeDelta increment(&cookie_load_duration_);
 
   bool load_success = true;
 
   if (keys_to_load_.size() > 0) {
     // Load cookies for the first domain key.
     std::map<std::string, std::set<std::string> >::iterator
       it = keys_to_load_.begin();
     load_success = LoadCookiesForDomains(it->second);
     keys_to_load_.erase(it);
   }
 
   // If load is successful and there are more domain keys to be loaded,
   // then post a DB task to continue chain-load;
   // Otherwise notify on IO thread.
   if (load_success && keys_to_load_.size() > 0) {
     BrowserThread::PostTask(
       BrowserThread::DB, FROM_HERE,
       base::Bind(&Backend::ChainLoadCookies, this, loaded_callback));
   } else {
     BrowserThread::PostTask(
       BrowserThread::IO, FROM_HERE,
-      base::Bind(&SQLitePersistentCookieStore::Backend::NotifyOnIOThread,
+      base::Bind(&SQLitePersistentCookieStore::Backend::CompleteLoadOnIOThread,
                  this, loaded_callback, load_success));
   }
 }
 
 bool SQLitePersistentCookieStore::Backend::LoadCookiesForDomains(
   const std::set<std::string>& domains) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::DB));
 
   sql::Statement smt(db_->GetCachedStatement(SQL_FROM_HERE,
     "SELECT creation_utc, host_key, name, value, path, expires_utc, secure, "
@@ skipping 337 matching lines @@
   if (backend_.get())
     backend_->SetClearLocalStateOnExit(clear_local_state);
 }
 
 void SQLitePersistentCookieStore::Flush(Task* completion_task) {
   if (backend_.get())
     backend_->Flush(completion_task);
   else if (completion_task)
     MessageLoop::current()->PostTask(FROM_HERE, completion_task);
 }