Add histograms for network activity, and total/cumulative

chrome/browser/net/load_time_stats.cc

Index: chrome/browser/net/load_time_stats.cc
===================================================================
--- chrome/browser/net/load_time_stats.cc	(revision 150909)
+++ chrome/browser/net/load_time_stats.cc	(working copy)
@@ -2,7 +2,7 @@
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
-#include "chrome/browser/net/cache_stats.h"
+#include "chrome/browser/net/load_time_stats.h"
 
 #include "base/metrics/histogram.h"
 #include "base/stl_util.h"
@@ -22,6 +22,7 @@
 using content::BrowserThread;
 using content::RenderViewHost;
 using content::ResourceRequestInfo;
+using std::string;
 
 #if defined(COMPILER_GCC)
 
@@ -47,13 +48,13 @@
   return info->GetAssociatedRenderView(process_id, route_id);
 }
 
-void CallCacheStatsTabEventOnIOThread(
+void CallLoadTimeStatsTabEventOnIOThread(
     std::pair<int, int> render_view_id,
-    chrome_browser_net::CacheStats::TabEvent event,
+    chrome_browser_net::LoadTimeStats::TabEvent event,
     IOThread* io_thread) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
   if (io_thread)
-    io_thread->globals()->cache_stats->OnTabEvent(render_view_id, event);
+    io_thread->globals()->load_time_stats->OnTabEvent(render_view_id, event);
 }
 
 // Times after a load has started at which stats are collected.
@@ -72,6 +73,30 @@
 
 static int kTabLoadStatsAutoCleanupTimeoutSeconds = 30;
 
+const char* kRequestStatusNames[] = {
+  "CacheWait",
+  "NetworkWait",
+  "Active",
+  "None",
+  "Max"
+};
+
+COMPILE_ASSERT(arraysize(kRequestStatusNames) ==
+               chrome_browser_net::LoadTimeStats::REQUEST_STATUS_MAX + 1,
+               LoadTimeStats_RequestStatus_names_mismatch);
+
+const char* kHistogramTypeNames[] = {
+  "FinalAggregate",
+  "FinalCumulativePercentage",
+  "IntermediateAggregate",
+  "IntermediateCumulativePercentage",
+  "Max"
+};
+
+COMPILE_ASSERT(arraysize(kHistogramTypeNames) ==
+               chrome_browser_net::LoadTimeStats::HISTOGRAM_MAX + 1,
+               LoadTimeStats_HistogramType_names_mismatch);
+
 }  // namespace
 
 namespace chrome_browser_net {
@@ -79,49 +104,106 @@
 // Helper struct keeping stats about the page load progress & cache usage
 // stats during the pageload so far for a given RenderView, identified
 // by a pair of process id and route id.
-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) {
+class LoadTimeStats::TabLoadStats {
+ public:
+  // Stores the time taken by all requests while they have a certain
+  // RequestStatus.
+  class PerStatusStats {
+   public:
+    PerStatusStats() : num_active_(0) {
+    }
+
+    void UpdateTotalTimes() {
+      DCHECK_GE(num_active_, 0);
+      base::TimeTicks now = base::TimeTicks::Now();
+      if (num_active_ > 0) {
+        total_time_ += now - last_update_time_;
+        total_cumulative_time_ +=
+            (now - last_update_time_) * static_cast<int64>(num_active_);
+      }
+      last_update_time_ = now;
+    }
+
+    void ResetTimes() {
+      last_update_time_ = base::TimeTicks::Now();
+      total_time_ = base::TimeDelta();
+      total_cumulative_time_ = base::TimeDelta();
+    }
+
+    void IncrementNumActive() {
+      num_active_++;
+    }
+
+    void DecrementNumActiveIfPositive() {
+      if (num_active_ > 0)
+        num_active_--;
+    }
+
+    int num_active() { return num_active_; }
+    void set_num_active(int num_active) { num_active_ = num_active; }
+    base::TimeDelta total_time() { return total_time_; }
+    base::TimeDelta total_cumulative_time() { return total_cumulative_time_; }
+
+   private:
+    int num_active_;
+    base::TimeTicks last_update_time_;
+    base::TimeDelta total_time_;
+    base::TimeDelta total_cumulative_time_;
+  };
+
+  TabLoadStats(std::pair<int, int> render_view_id, LoadTimeStats* owner)
+      : render_view_id_(render_view_id),
+        spinner_started_(false),
+        next_timer_index_(0),
+        timer_(false, false) {
     // Initialize the timer to do an automatic cleanup.  If a pageload is
-    // started for the TabLoadStats within that timeframe, CacheStats
+    // started for the TabLoadStats within that timeframe, LoadTimeStats
     // will start using the timer, thereby cancelling the cleanup.
-    // Once CacheStats starts the timer, the object is guaranteed to be
+    // Once LoadTimeStats starts the timer, the object is guaranteed to be
     // destroyed eventually, so there is no more need for automatic cleanup at
     // that point.
-    timer.Start(FROM_HERE,
-                base::TimeDelta::FromSeconds(
-                    kTabLoadStatsAutoCleanupTimeoutSeconds),
-                base::Bind(&CacheStats::RemoveTabLoadStats,
-                           base::Unretained(owner),
-                           render_view_id));
+    timer_.Start(FROM_HERE,
+                 base::TimeDelta::FromSeconds(
+                     kTabLoadStatsAutoCleanupTimeoutSeconds),
+                 base::Bind(&LoadTimeStats::RemoveTabLoadStats,
+                            base::Unretained(owner),
+                            render_view_id_));
   }
 
-  std::pair<int, int> render_view_id;
-  int num_active;
-  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;
+  typedef std::pair<int, int> RenderViewId;
+  typedef PerStatusStats PerStatusStatsArray[REQUEST_STATUS_MAX];
+  typedef base::hash_map<const net::URLRequest*, RequestStatus> RequestMap;
+
+  RenderViewId& render_view_id() { return render_view_id_; }
+  PerStatusStatsArray& per_status_stats() { return per_status_stats_; }
+  bool spinner_started() { return spinner_started_; }
+  void set_spinner_started(bool value) { spinner_started_ = value; }
+  base::TimeTicks load_start_time() { return load_start_time_; }
+  int next_timer_index() { return next_timer_index_; }
+  void set_next_timer_index(int index) { next_timer_index_ = index; }
+  base::Timer& timer() { return timer_; }
+  RequestMap& active_requests() { return active_requests_; }
+
+ private:
+  RenderViewId render_view_id_;
+  PerStatusStatsArray per_status_stats_;
+  bool spinner_started_;
+  base::TimeTicks load_start_time_;
+  int next_timer_index_;
+  base::Timer timer_;
+  // Currently active URLRequests.
+  RequestMap active_requests_;
 };
 
-CacheStatsTabHelper::CacheStatsTabHelper(TabContents* tab)
-    : content::WebContentsObserver(tab->web_contents()),
-      cache_stats_(NULL) {
+LoadTimeStatsTabHelper::LoadTimeStatsTabHelper(TabContents* tab)
+    : content::WebContentsObserver(tab->web_contents()) {
   is_otr_profile_ = tab->profile()->IsOffTheRecord();
 }
 
-CacheStatsTabHelper::~CacheStatsTabHelper() {
+LoadTimeStatsTabHelper::~LoadTimeStatsTabHelper() {
 }
 
-void CacheStatsTabHelper::DidStartProvisionalLoadForFrame(
+void LoadTimeStatsTabHelper::DidStartProvisionalLoadForFrame(
     int64 frame_id,
     bool is_main_frame,
     const GURL& validated_url,
@@ -131,15 +213,15 @@
     return;
   if (!validated_url.SchemeIs("http"))
     return;
-  NotifyCacheStats(CacheStats::SPINNER_START, render_view_host);
+  NotifyLoadTimeStats(LoadTimeStats::SPINNER_START, render_view_host);
 }
 
-void CacheStatsTabHelper::DidStopLoading(RenderViewHost* render_view_host) {
-  NotifyCacheStats(CacheStats::SPINNER_STOP, render_view_host);
+void LoadTimeStatsTabHelper::DidStopLoading(RenderViewHost* render_view_host) {
+  NotifyLoadTimeStats(LoadTimeStats::SPINNER_STOP, render_view_host);
 }
 
-void CacheStatsTabHelper::NotifyCacheStats(
-    CacheStats::TabEvent event,
+void LoadTimeStatsTabHelper::NotifyLoadTimeStats(
+    LoadTimeStats::TabEvent event,
     RenderViewHost* render_view_host) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
   if (is_otr_profile_)
@@ -148,37 +230,42 @@
   int route_id = render_view_host->GetRoutingID();
   BrowserThread::PostTask(
       BrowserThread::IO, FROM_HERE,
-      base::Bind(&CallCacheStatsTabEventOnIOThread,
+      base::Bind(&CallLoadTimeStatsTabEventOnIOThread,
                  std::pair<int, int>(process_id, route_id),
                  event,
                  base::Unretained(g_browser_process->io_thread())));
 }
 
-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));
+LoadTimeStats::LoadTimeStats() {
+  for (int status = REQUEST_STATUS_CACHE_WAIT;
+       status <= REQUEST_STATUS_ACTIVE;
+       status++) {
+    for (int histogram_type = HISTOGRAM_FINAL_AGGREGATE;
+         histogram_type < HISTOGRAM_MAX;
+         histogram_type++) {
+      for (int i = 0;
+           i < static_cast<int>(arraysize(kStatsCollectionTimesMs));
+           i++) {
+        string histogram_name = string("LoadTimeStats.Fraction_") +
+            string(kRequestStatusNames[status]) + string("_") +
+            string(kHistogramTypeNames[histogram_type]) + string("_") +
+            base::IntToString(kStatsCollectionTimesMs[i]);
+        histograms_[status][histogram_type].push_back(
+            base::LinearHistogram::FactoryGet(
+                histogram_name,
+                0, 101, 102, base::Histogram::kUmaTargetedHistogramFlag));
+      }
+      DCHECK_EQ(histograms_[status][histogram_type].size(),
+                arraysize(kStatsCollectionTimesMs));
+    }
   }
-  DCHECK_EQ(final_histograms_.size(), arraysize(kStatsCollectionTimesMs));
-  DCHECK_EQ(intermediate_histograms_.size(),
-            arraysize(kStatsCollectionTimesMs));
 }
 
-CacheStats::~CacheStats() {
+LoadTimeStats::~LoadTimeStats() {
   STLDeleteValues(&tab_load_stats_);
 }
 
-CacheStats::TabLoadStats* CacheStats::GetTabLoadStats(
+LoadTimeStats::TabLoadStats* LoadTimeStats::GetTabLoadStats(
     std::pair<int, int> render_view_id) {
   TabLoadStatsMap::const_iterator it = tab_load_stats_.find(render_view_id);
   if (it != tab_load_stats_.end())
@@ -188,7 +275,7 @@
   return new_tab_load_stats;
 }
 
-void CacheStats::RemoveTabLoadStats(std::pair<int, int> render_view_id) {
+void LoadTimeStats::RemoveTabLoadStats(std::pair<int, int> render_view_id) {
   TabLoadStatsMap::iterator it = tab_load_stats_.find(render_view_id);
   if (it != tab_load_stats_.end()) {
     delete it->second;
@@ -196,9 +283,9 @@
   }
 }
 
-void CacheStats::OnCacheWaitStateChange(
+void LoadTimeStats::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,142 +294,176 @@
     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();
-    }
-    stats->num_active++;
+  if (old_status == new_status)
+    return;
+  if (old_status != REQUEST_STATUS_NONE) {
+    TabLoadStats::PerStatusStats* status_stats =
+        &(stats->per_status_stats()[old_status]);
+    DCHECK_GE(status_stats->num_active(), 0);
+    status_stats->UpdateTotalTimes();
+    status_stats->DecrementNumActiveIfPositive();
+    DCHECK_GE(status_stats->num_active(), 0);
   }
-  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--;
+  if (new_status != REQUEST_STATUS_NONE) {
+    TabLoadStats::PerStatusStats* status_stats =
+        &(stats->per_status_stats()[new_status]);
+    DCHECK_GE(status_stats->num_active(), 0);
+    status_stats->UpdateTotalTimes();
+    status_stats->IncrementNumActive();
+    DCHECK_GE(status_stats->num_active(), 0);
+    stats->active_requests()[&request] = new_status;
+  } else {
+    stats->active_requests().erase(&request);
   }
-  DCHECK_GE(stats->num_active, 0);
 }
 
-void CacheStats::OnTabEvent(std::pair<int, int> render_view_id,
+void LoadTimeStats::OnTabEvent(std::pair<int, int> render_view_id,
                             TabEvent event) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
   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();
-    stats->next_timer_index = 0;
+    stats->set_spinner_started(true);
+    for (int status = REQUEST_STATUS_CACHE_WAIT;
+         status <= REQUEST_STATUS_ACTIVE; status++) {
+      stats->per_status_stats()[status].ResetTimes();
+    }
+    stats->set_next_timer_index(0);
     ScheduleTimer(stats);
   } else {
     DCHECK_EQ(event, SPINNER_STOP);
-    if (stats->spinner_started) {
-      stats->spinner_started = false;
+    if (stats->spinner_started()) {
+      stats->set_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);
+          base::TimeTicks::Now() - stats->load_start_time();
+      RecordHistograms(load_time, stats, true);
     }
     RemoveTabLoadStats(render_view_id);
   }
 }
 
-void CacheStats::ScheduleTimer(TabLoadStats* stats) {
-  int timer_index = stats->next_timer_index;
+void LoadTimeStats::ScheduleTimer(TabLoadStats* stats) {
+  int timer_index = stats->next_timer_index();
   DCHECK(timer_index >= 0 &&
          timer_index < static_cast<int>(arraysize(kStatsCollectionTimesMs)));
   base::TimeDelta delta =
       base::TimeDelta::FromMilliseconds(kStatsCollectionTimesMs[timer_index]);
-  delta -= base::TimeTicks::Now() - stats->load_start_time;
+  delta -= base::TimeTicks::Now() - stats->load_start_time();
 
   // If the ScheduleTimer call was delayed significantly, like when one's using
   // a debugger, don't try to start the timer with a negative time.
   if (delta < base::TimeDelta()) {
-    RemoveTabLoadStats(stats->render_view_id);
+    RemoveTabLoadStats(stats->render_view_id());
     return;
   }
 
-  stats->timer.Start(FROM_HERE,
-                     delta,
-                     base::Bind(&CacheStats::TimerCallback,
-                                base::Unretained(this),
-                                base::Unretained(stats)));
+  stats->timer().Start(FROM_HERE,
+                       delta,
+                       base::Bind(&LoadTimeStats::TimerCallback,
+                                  base::Unretained(this),
+                                  base::Unretained(stats)));
 }
 
-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);
-  stats->next_timer_index++;
-  if (stats->next_timer_index <
+void LoadTimeStats::TimerCallback(TabLoadStats* stats) {
+  DCHECK(stats->spinner_started());
+  base::TimeDelta load_time = base::TimeTicks::Now() - stats->load_start_time();
+  RecordHistograms(load_time, stats, false);
+  stats->set_next_timer_index(stats->next_timer_index() + 1);
+  if (stats->next_timer_index() <
       static_cast<int>(arraysize(kStatsCollectionTimesMs))) {
     ScheduleTimer(stats);
   } else {
-    RemoveTabLoadStats(stats->render_view_id);
+    RemoveTabLoadStats(stats->render_view_id());
   }
 }
 
-void CacheStats::RecordCacheFractionHistogram(base::TimeDelta elapsed,
-                                              base::TimeDelta cache_time,
-                                              bool is_load_done,
-                                              int timer_index) {
+void LoadTimeStats::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 = REQUEST_STATUS_CACHE_WAIT;
+       status <= REQUEST_STATUS_ACTIVE;
+       status++) {
+    total_cumulative +=
+        stats->per_status_stats()[status].total_cumulative_time();
+  }
 
-  DCHECK(cache_fraction_percentage >= 0 && cache_fraction_percentage <= 100);
+  for (int status = REQUEST_STATUS_CACHE_WAIT;
+       status <= REQUEST_STATUS_ACTIVE;
+       status++) {
+    TabLoadStats::PerStatusStats* 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);
+    }
+
+    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);
+      }
+    }
   }
 }
 
-void CacheStats::RegisterURLRequestContext(
+void LoadTimeStats::RegisterURLRequestContext(
     const net::URLRequestContext* context,
     ChromeURLRequestContext::ContextType type) {
   if (type == ChromeURLRequestContext::CONTEXT_TYPE_MAIN)
     main_request_contexts_.insert(context);
 }
 
-void CacheStats::UnregisterURLRequestContext(
+void LoadTimeStats::UnregisterURLRequestContext(
     const net::URLRequestContext* context) {
   main_request_contexts_.erase(context);
 }