Histogram appcache task queue and run times.

webkit/appcache/appcache_storage_impl.cc

Index: webkit/appcache/appcache_storage_impl.cc
===================================================================
--- webkit/appcache/appcache_storage_impl.cc	(revision 110360)
+++ webkit/appcache/appcache_storage_impl.cc	(working copy)
@@ -172,8 +172,8 @@
   DelegateReferenceVector delegates_;
 
  private:
-  void CallRun();
-  void CallRunCompleted();
+  void CallRun(base::Time schedule_time);

[rvargas (doing something else), 2011/11/17 03:42:05]

This should be TimeTicks instead.

[michaeln, 2011/11/17 03:59:47]

Done.

+  void CallRunCompleted(base::Time schedule_time);
   void CallDisableStorage();
 
   scoped_refptr<base::MessageLoopProxy> io_thread_;
@@ -184,7 +184,7 @@
   DCHECK(io_thread_->BelongsToCurrentThread());
   if (storage_->db_thread_->PostTask(
       FROM_HERE,
-      base::Bind(&DatabaseTask::CallRun, this))) {
+      base::Bind(&DatabaseTask::CallRun, this, base::Time::Now()))) {
     storage_->scheduled_database_tasks_.push_back(this);
   } else {
     NOTREACHED() << "The database thread is not running.";
@@ -197,9 +197,13 @@
   storage_ = NULL;
 }
 
-void AppCacheStorageImpl::DatabaseTask::CallRun() {
+void AppCacheStorageImpl::DatabaseTask::CallRun(base::Time schedule_time) {
+  AppCacheHistograms::AddTaskQueueTimeSample(
+      base::Time::Now() - schedule_time);
   if (!database_->is_disabled()) {
+    base::Time run_time = base::Time::Now();
     Run();
+    AppCacheHistograms::AddTaskRunTimeSample(base::Time::Now() - run_time);
     if (database_->is_disabled()) {
       io_thread_->PostTask(
           FROM_HERE,
@@ -208,10 +212,13 @@
   }
   io_thread_->PostTask(
       FROM_HERE,
-      base::Bind(&DatabaseTask::CallRunCompleted, this));
+      base::Bind(&DatabaseTask::CallRunCompleted, this, base::Time::Now()));
 }
 
-void AppCacheStorageImpl::DatabaseTask::CallRunCompleted() {
+void AppCacheStorageImpl::DatabaseTask::CallRunCompleted(
+    base::Time schedule_time) {
+  AppCacheHistograms::AddTaskCompletionTimeSample(
+      base::Time::Now() - schedule_time);
   if (storage_) {
     DCHECK(io_thread_->BelongsToCurrentThread());
     DCHECK(storage_->scheduled_database_tasks_.front() == this);
@@ -849,6 +856,8 @@
     }
   }
 
+  // TODO(michaeln): Also lookup matches in intercept namespaces.
+  // http://code.google.com/p/chromium/issues/detail?id=101565
   if (FindExactMatch(preferred_cache_id) ||
       FindFallback(preferred_cache_id)) {
     // We found something.