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) {
   }
 
   // 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_;
+  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_;
+
   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.
+class IncrementTimeDelta {
+ 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_;
+    }
+  }
+
+}
+
+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() {
+  BrowserThread::PostTask(BrowserThread::DB, FROM_HERE, base::Bind(
+      &SQLitePersistentCookieStore::Backend::ReportMetricsOnDBThread, this));
+
+  {
+    base::AutoLock locked(metrics_lock_);
+    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)
+    ReportMetrics();
+}
+
+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);
 }