Add histograms for network activity, and total/cumulative

chrome/browser/net/cache_stats.cc

Index: chrome/browser/net/cache_stats.cc
===================================================================
--- chrome/browser/net/cache_stats.cc	(revision 150909)
+++ chrome/browser/net/cache_stats.cc	(working copy)
@@ -22,6 +22,7 @@
 using content::BrowserThread;
 using content::RenderViewHost;
 using content::ResourceRequestInfo;
+using std::string;
 
 #if defined(COMPILER_GCC)
 
@@ -72,6 +73,32 @@
 
 static int kTabLoadStatsAutoCleanupTimeoutSeconds = 30;
 
+const char* kRequestStatusNames[] = {
+  "CacheWait",
+  "NetworkWait",
+  "Active",
+  "None",
+  "Max"
+};
+
+COMPILE_ASSERT(arraysize(kRequestStatusNames) ==
+               chrome_browser_net::CacheStats::REQUEST_STATUS_MAX + 1,
+               CacheStats_RequestStatus_names_mismatch);
+
+const char* kHistogramTypeNames[] = {
+  "FinalAggregate",
+  "FinalCumulative",
+  "FinalCumulativePercentage",
+  "IntermediateAggregate",
+  "IntermediateCumulative",
+  "IntermediateCumulativePercentage",
+  "Max"
+};
+
+COMPILE_ASSERT(arraysize(kHistogramTypeNames) ==
+               chrome_browser_net::CacheStats::HISTOGRAM_MAX + 1,
+               CacheStats_HistogramType_names_mismatch);
+
 }  // namespace
 
 namespace chrome_browser_net {
@@ -82,7 +109,6 @@
 struct CacheStats::TabLoadStats {
   TabLoadStats(std::pair<int, int> render_view_id, CacheStats* owner)
       : render_view_id(render_view_id),
-        num_active(0),
         spinner_started(false),
         next_timer_index(0),
         timer(false, false) {
@@ -100,16 +126,37 @@
                            render_view_id));
   }
 
+  struct PerRequestStatusData {
+    PerRequestStatusData()
+        : num_active(0) {
+    }
+    void UpdateTotalTimes() {
+      base::TimeTicks now = base::TimeTicks::Now();
+      if (num_active > 0) {
+        total_time += now - current_start_time;
+        total_cumulative_time +=
+            (now - current_start_time) * static_cast<int64>(num_active);
+      }
+      current_start_time = now;
+    }
+    void ResetTimes() {
+      current_start_time = base::TimeTicks::Now();
+      total_time = base::TimeDelta();
+      total_cumulative_time = base::TimeDelta();
+    }
+    int num_active;
+    base::TimeTicks current_start_time;
+    base::TimeDelta total_time;
+    base::TimeDelta total_cumulative_time;
+  };
   std::pair<int, int> render_view_id;
-  int num_active;
+  PerRequestStatusData per_status_stats[REQUEST_STATUS_MAX];
   bool spinner_started;
   base::TimeTicks load_start_time;
-  base::TimeTicks cache_start_time;
-  base::TimeDelta cache_total_time;
   int next_timer_index;
   base::Timer timer;
-  // URLRequest's for which there are outstanding cache transactions.
-  base::hash_set<const net::URLRequest*> active_requests;
+  // Currently active URLRequests.
+  base::hash_map<const net::URLRequest*, RequestStatus> active_requests;
 };
 
 CacheStatsTabHelper::CacheStatsTabHelper(TabContents* tab)
@@ -155,23 +202,38 @@
 }
 
 CacheStats::CacheStats() {
-  for (int i = 0;
-       i < static_cast<int>(arraysize(kStatsCollectionTimesMs));
-       i++) {
-    final_histograms_.push_back(
-        base::LinearHistogram::FactoryGet(
-            "CacheStats.FractionCacheUseFinalPLT_" +
-            base::IntToString(kStatsCollectionTimesMs[i]),
-            0, 101, 102, base::Histogram::kUmaTargetedHistogramFlag));
-    intermediate_histograms_.push_back(
-        base::LinearHistogram::FactoryGet(
-            "CacheStats.FractionCacheUseIntermediatePLT_" +
-            base::IntToString(kStatsCollectionTimesMs[i]),
-            0, 101, 102, base::Histogram::kUmaTargetedHistogramFlag));
+  for (int status_int = REQUEST_STATUS_CACHE_WAIT;
+       status_int <= REQUEST_STATUS_ACTIVE;
+       status_int++) {
+    RequestStatus status = static_cast<RequestStatus>(status_int);
+    for (int type_int = HISTOGRAM_FINAL_AGGREGATE;
+         type_int < HISTOGRAM_MAX;
+         type_int++) {
+      HistogramType type = static_cast<HistogramType>(type_int);
+      for (int i = 0;
+           i < static_cast<int>(arraysize(kStatsCollectionTimesMs));
+           i++) {
+        string histogram_name = string("CacheStats.Fraction_") +
+            string(kRequestStatusNames[status]) + string("_") +
+            string(kHistogramTypeNames[type]) + string("_") +
+            base::IntToString(kStatsCollectionTimesMs[i]);
+        if (type != HISTOGRAM_FINAL_CUMULATIVE_PERCENTAGE &&
+            type != HISTOGRAM_INTERMEDIATE_CUMULATIVE_PERCENTAGE) {
+          histograms_[status][type].push_back(
+              base::LinearHistogram::FactoryGet(
+                  histogram_name,
+                  0, 101, 102, base::Histogram::kUmaTargetedHistogramFlag));
+        } else {
+          histograms_[status][type].push_back(
+              base::Histogram::FactoryGet(
+                  histogram_name,
+                  0, 10000, 500, base::Histogram::kUmaTargetedHistogramFlag));
+        }
+      }
+      DCHECK_EQ(histograms_[status][type].size(),
+                arraysize(kStatsCollectionTimesMs));
+    }
   }
-  DCHECK_EQ(final_histograms_.size(), arraysize(kStatsCollectionTimesMs));
-  DCHECK_EQ(intermediate_histograms_.size(),
-            arraysize(kStatsCollectionTimesMs));
 }
 
 CacheStats::~CacheStats() {
@@ -196,9 +258,9 @@
   }
 }
 
-void CacheStats::OnCacheWaitStateChange(
+void CacheStats::OnRequestWaitStateChange(
     const net::URLRequest& request,
-    net::NetworkDelegate::CacheWaitState state) {
+    net::NetworkDelegate::RequestWaitState state) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
   if (main_request_contexts_.count(request.context()) < 1)
     return;
@@ -207,44 +269,57 @@
     return;
   TabLoadStats* stats =
       GetTabLoadStats(std::pair<int, int>(process_id, route_id));
-  bool newly_started = false;
-  bool newly_finished = false;
+  RequestStatus old_status = REQUEST_STATUS_NONE;
+  if (stats->active_requests.count(&request) > 0)
+    old_status = stats->active_requests[&request];
+  RequestStatus new_status = REQUEST_STATUS_NONE;
   switch (state) {
-    case net::NetworkDelegate::CACHE_WAIT_STATE_START:
-      DCHECK(stats->active_requests.count(&request) == 0);
-      newly_started = true;
-      stats->active_requests.insert(&request);
+    case net::NetworkDelegate::REQUEST_WAIT_STATE_CACHE_START:
+      DCHECK(old_status == REQUEST_STATUS_NONE ||
+             old_status == REQUEST_STATUS_ACTIVE);
+      new_status = REQUEST_STATUS_CACHE_WAIT;
       break;
-    case net::NetworkDelegate::CACHE_WAIT_STATE_FINISH:
-      if (stats->active_requests.count(&request) > 0) {
-        stats->active_requests.erase(&request);
-        newly_finished = true;
-      }
+    case net::NetworkDelegate::REQUEST_WAIT_STATE_CACHE_FINISH:
+      DCHECK(old_status == REQUEST_STATUS_NONE ||
+             old_status == REQUEST_STATUS_CACHE_WAIT);
+      new_status = REQUEST_STATUS_ACTIVE;
       break;
-    case net::NetworkDelegate::CACHE_WAIT_STATE_RESET:
-      if (stats->active_requests.count(&request) > 0) {
-        stats->active_requests.erase(&request);
-        newly_finished = true;
-      }
+    case net::NetworkDelegate::REQUEST_WAIT_STATE_NETWORK_START:
+      DCHECK(old_status == REQUEST_STATUS_NONE ||
+             old_status == REQUEST_STATUS_ACTIVE);
+      new_status = REQUEST_STATUS_NETWORK_WAIT;
       break;
+    case net::NetworkDelegate::REQUEST_WAIT_STATE_NETWORK_FINISH:
+      DCHECK(old_status == REQUEST_STATUS_NONE ||
+             old_status == REQUEST_STATUS_NETWORK_WAIT);
+      new_status = REQUEST_STATUS_ACTIVE;
+      break;
+    case net::NetworkDelegate::REQUEST_WAIT_STATE_RESET:
+      new_status = REQUEST_STATUS_NONE;
+      break;
   }
-  DCHECK_GE(stats->num_active, 0);
-  if (newly_started) {
-    DCHECK(!newly_finished);
-    if (stats->num_active == 0) {
-      stats->cache_start_time = base::TimeTicks::Now();
+  if (old_status != new_status) {
+    for (int status_int = REQUEST_STATUS_CACHE_WAIT;
+         status_int <= REQUEST_STATUS_ACTIVE; status_int++) {
+      RequestStatus status = static_cast<RequestStatus>(status_int);
+      TabLoadStats::PerRequestStatusData* status_stats =
+          &(stats->per_status_stats[status]);
+      DCHECK_GE(status_stats->num_active, 0);
+      if (old_status == status) {
+        status_stats->UpdateTotalTimes();
+        status_stats->num_active--;
+      }
+      if (new_status == status) {
+        status_stats->UpdateTotalTimes();
+        status_stats->num_active++;
+      }
+      DCHECK_GE(status_stats->num_active, 0);
     }
-    stats->num_active++;
   }
-  if (newly_finished) {
-    DCHECK(!newly_started);
-    if (stats->num_active == 1) {
-      stats->cache_total_time +=
-          base::TimeTicks::Now() - stats->cache_start_time;
-    }
-    stats->num_active--;
-  }
-  DCHECK_GE(stats->num_active, 0);
+  if (new_status == REQUEST_STATUS_NONE)
+    stats->active_requests.erase(&request);
+  else
+    stats->active_requests[&request] = new_status;
 }
 
 void CacheStats::OnTabEvent(std::pair<int, int> render_view_id,
@@ -253,9 +328,11 @@
   TabLoadStats* stats = GetTabLoadStats(render_view_id);
   if (event == SPINNER_START) {
     stats->spinner_started = true;
-    stats->cache_total_time = base::TimeDelta();
-    stats->cache_start_time = base::TimeTicks::Now();
-    stats->load_start_time = base::TimeTicks::Now();
+    for (int status_int = REQUEST_STATUS_CACHE_WAIT;
+         status_int <= REQUEST_STATUS_ACTIVE; status_int++) {
+      RequestStatus status = static_cast<RequestStatus>(status_int);
+      stats->per_status_stats[status].ResetTimes();
+    }
     stats->next_timer_index = 0;
     ScheduleTimer(stats);
   } else {
@@ -264,11 +341,7 @@
       stats->spinner_started = false;
       base::TimeDelta load_time =
           base::TimeTicks::Now() - stats->load_start_time;
-      if (stats->num_active > 1)
-        stats->cache_total_time +=
-            base::TimeTicks::Now() - stats->cache_start_time;
-      RecordCacheFractionHistogram(load_time, stats->cache_total_time, true,
-                                   stats->next_timer_index);
+      RecordHistograms(load_time, stats, true);
     }
     RemoveTabLoadStats(render_view_id);
   }
@@ -299,11 +372,7 @@
 void CacheStats::TimerCallback(TabLoadStats* stats) {
   DCHECK(stats->spinner_started);
   base::TimeDelta load_time = base::TimeTicks::Now() - stats->load_start_time;
-  base::TimeDelta cache_time = stats->cache_total_time;
-  if (stats->num_active > 1)
-    cache_time += base::TimeTicks::Now() - stats->cache_start_time;
-  RecordCacheFractionHistogram(load_time, cache_time, false,
-                               stats->next_timer_index);
+  RecordHistograms(load_time, stats, false);
   stats->next_timer_index++;
   if (stats->next_timer_index <
       static_cast<int>(arraysize(kStatsCollectionTimesMs))) {
@@ -313,25 +382,67 @@
   }
 }
 
-void CacheStats::RecordCacheFractionHistogram(base::TimeDelta elapsed,
-                                              base::TimeDelta cache_time,
-                                              bool is_load_done,
-                                              int timer_index) {
+void CacheStats::RecordHistograms(base::TimeDelta elapsed,
+                                  TabLoadStats* stats,
+                                  bool is_load_done) {
+  int timer_index = stats->next_timer_index;
   DCHECK(timer_index >= 0 &&
          timer_index < static_cast<int>(arraysize(kStatsCollectionTimesMs)));
 
   if (elapsed.InMilliseconds() <= 0)
     return;
 
-  int64 cache_fraction_percentage =
-      100 * cache_time.InMilliseconds() / elapsed.InMilliseconds();
+  base::TimeDelta total_cumulative;
+  for (int status_int = REQUEST_STATUS_CACHE_WAIT;
+       status_int <= REQUEST_STATUS_ACTIVE;
+       status_int++) {
+    RequestStatus status = static_cast<RequestStatus>(status_int);
+    total_cumulative += stats->per_status_stats[status].total_cumulative_time;
+  }
 
-  DCHECK(cache_fraction_percentage >= 0 && cache_fraction_percentage <= 100);
+  for (int status_int = REQUEST_STATUS_CACHE_WAIT;
+       status_int <= REQUEST_STATUS_ACTIVE;
+       status_int++) {
+    RequestStatus status = static_cast<RequestStatus>(status_int);
+    TabLoadStats::PerRequestStatusData* status_stats =
+        &(stats->per_status_stats[status]);
 
-  if (is_load_done) {
-    final_histograms_[timer_index]->Add(cache_fraction_percentage);
-  } else {
-    intermediate_histograms_[timer_index]->Add(cache_fraction_percentage);
+    int64 fraction_percentage = 100 *
+        status_stats->total_time.InMilliseconds() / elapsed.InMilliseconds();
+    DCHECK(fraction_percentage >= 0 && fraction_percentage <= 100);
+    if (is_load_done) {
+      histograms_[status][HISTOGRAM_FINAL_AGGREGATE][timer_index]->Add(
+          fraction_percentage);
+    } else {
+      histograms_[status][HISTOGRAM_INTERMEDIATE_AGGREGATE][timer_index]->Add(
+          fraction_percentage);
+    }
+
+    fraction_percentage = 100 *
+        status_stats->total_cumulative_time.InMilliseconds() /
+        elapsed.InMilliseconds();
+    DCHECK(fraction_percentage >= 0);
+    if (is_load_done) {
+      histograms_[status][HISTOGRAM_FINAL_CUMULATIVE][timer_index]->Add(
+          fraction_percentage);
+    } else {
+      histograms_[status][HISTOGRAM_INTERMEDIATE_CUMULATIVE][timer_index]->Add(
+          fraction_percentage);
+    }
+
+    if (total_cumulative.InMilliseconds() > 0) {
+      fraction_percentage = 100 *
+          status_stats->total_cumulative_time.InMilliseconds() /
+          total_cumulative.InMilliseconds();
+      DCHECK(fraction_percentage >= 0 && fraction_percentage <= 100);
+      if (is_load_done) {
+        histograms_[status][HISTOGRAM_FINAL_CUMULATIVE_PERCENTAGE]
+            [timer_index]->Add(fraction_percentage);
+      } else {
+        histograms_[status][HISTOGRAM_INTERMEDIATE_CUMULATIVE_PERCENTAGE]
+            [timer_index]->Add(fraction_percentage);
+      }
+    }
   }
 }