Add new histograms to track down cookie performance issues.

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>
@@ skipping 47 matching lines @@
 class SQLitePersistentCookieStore::Backend
     : public base::RefCountedThreadSafe<SQLitePersistentCookieStore::Backend> {
  public:
   Backend(const FilePath& path, bool restore_old_session_cookies)
       : path_(path),
         db_(NULL),
         num_pending_(0),
         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) {
   }
 
   // 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);
@@ skipping 43 matching lines @@
     OperationType op() const { return op_; }
     const net::CookieMonster::CanonicalCookie& cc() const { return cc_; }
 
    private:
     OperationType op_;
     net::CookieMonster::CanonicalCookie cc_;
   };
 
  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
   // that have been loaded from DB since last IO notification.
   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,
@@ skipping 56 matching lines @@
   // Indicates if DB has been initialized.
   bool initialized_;
 
   // If false, we should filter out session cookies when reading the DB.
   bool restore_old_session_cookies_;
 
   // The cumulative time spent loading the cookies on the DB thread. Incremented
   // 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_;
   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.
@@ skipping 74 matching lines @@
 }
 
 }  // namespace
 
 void SQLitePersistentCookieStore::Backend::Load(
     const LoadedCallback& loaded_callback) {
   // 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));
+      base::Bind(&Backend::LoadAndNotifyOnDBThread, this, loaded_callback,
+                 base::Time::Now()));
 }
 
 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));
+               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,
       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) {
+    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
       it = keys_to_load_.find(key);
     if (it != keys_to_load_.end()) {
       success = LoadCookiesForDomains(it->second);
       keys_to_load_.erase(it);
     } else {
       success = true;
     }
@@ skipping 38 matching lines @@
     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_);
+
+    UMA_HISTOGRAM_COUNTS_10000(
+        "Cookie.NumberOfLoadedCookies",
+        num_cookies_read_);
   }
 }
 
 void SQLitePersistentCookieStore::Backend::CompleteLoadOnIOThread(
     const LoadedCallback& loaded_callback, bool load_success) {
   Notify(loaded_callback, load_success);
 
   if (load_success)
     ReportMetrics();
 }
@@ skipping 12 matching lines @@
   loaded_callback.Run(cookies);
 }
 
 bool SQLitePersistentCookieStore::Backend::InitializeDatabase() {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::DB));
 
   if (initialized_) {
     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.";
     db_.reset();
     return false;
   }
 
   db_->set_error_delegate(GetErrorHandlerForCookieDb());
 
   if (!EnsureDatabaseVersion() || !InitTable(db_.get())) {
     NOTREACHED() << "Unable to open cookie DB.";
     db_.reset();
     return false;
   }
 
   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"));
 
   if (!smt) {
     NOTREACHED() << "select statement prep failed";
     db_.reset();
     return false;
   }
 
   // Build a map of domain keys (always eTLD+1) to domains.
   while (smt.Step()) {
     std::string domain = smt.ColumnString(0);
     std::string key =
       net::RegistryControlledDomainService::GetDomainAndRegistry(domain);
 
     std::map<std::string, std::set<std::string> >::iterator it =
       keys_to_load_.find(key);
     if (it == keys_to_load_.end())
       it = keys_to_load_.insert(std::make_pair
                                 (key, std::set<std::string>())).first;
     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;
 }
 
 void SQLitePersistentCookieStore::Backend::ChainLoadCookies(
     const LoadedCallback& loaded_callback) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::DB));
   IncrementTimeDelta increment(&cookie_load_duration_);
 
   bool load_success = true;
@@ skipping 64 matching lines @@
               Time::FromInternalValue(smt.ColumnInt64(0)),    // creation_utc
               Time::FromInternalValue(smt.ColumnInt64(5)),    // expires_utc
               Time::FromInternalValue(smt.ColumnInt64(8)),    // last_access_utc
               smt.ColumnInt(6) != 0,                          // secure
               smt.ColumnInt(7) != 0,                          // httponly
               smt.ColumnInt(9) != 0,                          // has_expires
               smt.ColumnInt(10) != 0));                       // is_persistent
       DLOG_IF(WARNING,
               cc->CreationDate() > Time::Now()) << L"CreationDate too recent";
       cookies.push_back(cc.release());
+      ++num_cookies_read_;
     }
     smt.Reset();
   }
   {
     base::AutoLock locked(lock_);
     cookies_.insert(cookies_.end(), cookies.begin(), cookies.end());
   }
   return true;
 }
 
@@ skipping 328 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);
 }