Add new histograms to track down cookie performance issues.

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 58f44cae81ae7ced0bea3a8dc2cdacccc4805650..c4cb43a62c0fd3cc9bb7e3f1a638b65457355551 100644
--- a/chrome/browser/net/sqlite_persistent_cookie_store.cc
+++ b/chrome/browser/net/sqlite_persistent_cookie_store.cc
@@ -65,6 +65,7 @@ class SQLitePersistentCookieStore::Backend
         clear_local_state_on_exit_(false),
         initialized_(false),
         restore_old_session_cookies_(restore_old_session_cookies),
+        num_cookies_read_(0),
         num_priority_waiting_(0),
         total_priority_requests_(0) {
   }
@@ -128,11 +129,13 @@ class SQLitePersistentCookieStore::Backend
 
  private:
   // Creates or loads the SQLite database on DB thread.
-  void LoadAndNotifyOnDBThread(const LoadedCallback& loaded_callback);
+  void LoadAndNotifyOnDBThread(const LoadedCallback& loaded_callback,
+                               const base::Time& posted_at);
 
   // Loads cookies for the domain key (eTLD+1) on DB thread.
   void LoadKeyAndNotifyOnDBThread(const std::string& domains,
-      const LoadedCallback& loaded_callback);
+                                  const LoadedCallback& loaded_callback,
+                                  const base::Time& posted_at);
 
   // Notifies the CookieMonster when loading completes for a specific domain key
   // or for all domain keys. Triggers the callback and passes it all cookies
@@ -209,6 +212,10 @@ class SQLitePersistentCookieStore::Backend
   // and reported from the DB thread.
   base::TimeDelta cookie_load_duration_;
 
+  // The total number of cookies read. Incremented and reported on the DB
+  // thread.
+  int num_cookies_read_;
+
   // Guards the following metrics-related properties (only accessed when
   // starting/completing priority loads or completing the total load).
   base::Lock metrics_lock_;
@@ -303,7 +310,8 @@ void SQLitePersistentCookieStore::Backend::Load(
   DCHECK(!db_.get());
   BrowserThread::PostTask(
       BrowserThread::DB, FROM_HERE,
-      base::Bind(&Backend::LoadAndNotifyOnDBThread, this, loaded_callback));
+      base::Bind(&Backend::LoadAndNotifyOnDBThread, this, loaded_callback,
+                 base::Time::Now()));
 }
 
 void SQLitePersistentCookieStore::Backend::LoadCookiesForKey(
@@ -320,15 +328,22 @@ void SQLitePersistentCookieStore::Backend::LoadCookiesForKey(
   BrowserThread::PostTask(
     BrowserThread::DB, FROM_HERE,
     base::Bind(&Backend::LoadKeyAndNotifyOnDBThread, this,
-    key,
-    loaded_callback));
+               key,
+               loaded_callback,
+               base::Time::Now()));
 }
 
 void SQLitePersistentCookieStore::Backend::LoadAndNotifyOnDBThread(
-    const LoadedCallback& loaded_callback) {
+    const LoadedCallback& loaded_callback, const base::Time& posted_at) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::DB));
   IncrementTimeDelta increment(&cookie_load_duration_);
 
+  UMA_HISTOGRAM_CUSTOM_TIMES(
+      "Cookie.TimeLoadDBQueueWait",
+      base::Time::Now() - posted_at,
+      base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromMinutes(1),
+      50);

[Randy Smith (Not in Mondays), 2011/12/05 22:18:08]

Do the queue load histograms give us a lot more information than the built-in
profiler?  ("about:profiler")  Yes, we get a distribution rather than
average/max, but what we're really curious about getting the distribution for is
the amount of time we take doing our stuff, not the amount of time we're
waiting, I'd think?

[erikwright (departed), 2011/12/06 00:07:09]

AFAIK, task profiler data is not yet available from the field. You can only
visualize it on a running instance of Chromium, for a current run. The
information I found about shipping it back (slides from jar's talk) said the
work was only beginning.

So until then we have nothing.

On 2011/12/05 22:18:08, rdsmith wrote:

+
   if (!InitializeDatabase()) {
     BrowserThread::PostTask(
       BrowserThread::IO, FROM_HERE,
@@ -341,10 +356,17 @@ void SQLitePersistentCookieStore::Backend::LoadAndNotifyOnDBThread(
 
 void SQLitePersistentCookieStore::Backend::LoadKeyAndNotifyOnDBThread(
     const std::string& key,
-    const LoadedCallback& loaded_callback) {
+    const LoadedCallback& loaded_callback,
+    const base::Time& posted_at) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::DB));
   IncrementTimeDelta increment(&cookie_load_duration_);
 
+  UMA_HISTOGRAM_CUSTOM_TIMES(
+      "Cookie.TimeKeyLoadDBQueueWait",
+      base::Time::Now() - posted_at,
+      base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromMinutes(1),
+      50);
+
   bool success = false;
   if (InitializeDatabase()) {
     std::map<std::string, std::set<std::string> >::iterator
@@ -403,6 +425,10 @@ void SQLitePersistentCookieStore::Backend::ReportMetrics() {
     UMA_HISTOGRAM_COUNTS_100(
         "Cookie.PriorityLoadCount",
         total_priority_requests_);
+
+    UMA_HISTOGRAM_COUNTS_10000(
+        "Cookie.NumberOfLoadedCookies",
+        num_cookies_read_);
   }
 }
 
@@ -435,11 +461,19 @@ bool SQLitePersistentCookieStore::Backend::InitializeDatabase() {
     return true;
   }
 
+  base::Time start = base::Time::Now();
+
   const FilePath dir = path_.DirName();
   if (!file_util::PathExists(dir) && !file_util::CreateDirectory(dir)) {
     return false;
   }
 
+  int64 db_size = 0;
+  if (file_util::GetFileSize(path_, &db_size)) {
+    base::ThreadRestrictions::ScopedAllowIO allow_io;
+    UMA_HISTOGRAM_COUNTS("Cookie.DBSizeInKB", db_size / 1024 );
+  }
+
   db_.reset(new sql::Connection);
   if (!db_->Open(path_)) {
     NOTREACHED() << "Unable to open cookie DB.";
@@ -457,6 +491,14 @@ bool SQLitePersistentCookieStore::Backend::InitializeDatabase() {
 
   db_->Preload();

[Randy Smith (Not in Mondays), 2011/12/05 22:18:08]

Didn't we nuke this?  Is there context I'm missing?

[erikwright (departed), 2011/12/06 00:07:09]

After uploading that CL I decided I would prefer to put the metrics in first and
then compare the before and after. My further research indicated to me that the
likely loss of time was substantially in queue waiting time.

So my intention is to commit the metrics, wait for data, then remove the preload
and compare.

 
+  UMA_HISTOGRAM_CUSTOM_TIMES(
+    "Cookie.TimeInitializeDB",
+    base::Time::Now() - start,
+    base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromMinutes(1),
+    50);
+
+  start = base::Time::Now();
+
   // Retrieve all the domains
   sql::Statement smt(db_->GetUniqueStatement(
     "SELECT DISTINCT host_key FROM cookies"));
@@ -481,6 +523,12 @@ bool SQLitePersistentCookieStore::Backend::InitializeDatabase() {
     it->second.insert(domain);
   }
 
+  UMA_HISTOGRAM_CUSTOM_TIMES(
+    "Cookie.TimeInitializeDomainMap",
+    base::Time::Now() - start,
+    base::TimeDelta::FromMilliseconds(1), base::TimeDelta::FromMinutes(1),
+    50);
+
   initialized_ = true;
   return true;
 }
@@ -565,6 +613,7 @@ bool SQLitePersistentCookieStore::Backend::LoadCookiesForDomains(
       DLOG_IF(WARNING,
               cc->CreationDate() > Time::Now()) << L"CreationDate too recent";
       cookies.push_back(cc.release());
+      ++num_cookies_read_;
     }
     smt.Reset();
   }