Add histograms for network activity, and total/cumulative

chrome/browser/net/cache_stats.cc

 // Copyright (c) 2012 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/cache_stats.h"
 
 #include "base/metrics/histogram.h"
 #include "base/stl_util.h"
 #include "base/string_number_conversions.h"
 #include "base/timer.h"
 #include "chrome/browser/browser_process.h"
 #include "chrome/browser/io_thread.h"
 #include "chrome/browser/profiles/profile.h"
 #include "chrome/browser/ui/tab_contents/tab_contents.h"
 #include "content/public/browser/browser_thread.h"
 #include "content/public/browser/render_process_host.h"
 #include "content/public/browser/render_view_host.h"
 #include "content/public/browser/resource_request_info.h"
 #include "content/public/browser/web_contents.h"
 #include "net/url_request/url_request.h"
 
 using content::BrowserThread;
 using content::RenderViewHost;
 using content::ResourceRequestInfo;
+using std::string;
 
 #if defined(COMPILER_GCC)
 
 namespace BASE_HASH_NAMESPACE {
 template <>
 struct hash<const net::URLRequest*> {
   std::size_t operator()(const net::URLRequest* value) const {
     return reinterpret_cast<std::size_t>(value);
   }
 };
@@ skipping 30 matching lines @@
   4000,
   5000,
   7500,
   10000,
   15000,
   20000
 };
 
 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 {
 
 // 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) {
     // Initialize the timer to do an automatic cleanup.  If a pageload is
     // started for the TabLoadStats within that timeframe, CacheStats
     // will start using the timer, thereby cancelling the cleanup.
     // Once CacheStats 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));
   }
 
+  struct PerRequestStatusData {

[mmenke, 2012/08/15 18:45:41]

Think a comment stating that this records the time taken by all requests while
they have a certain status would make this code clearer.

[tburkard, 2012/08/15 21:05:56]

Done.

+    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();
+    }

[mmenke, 2012/08/15 18:45:41]

suggest a blank line after every function to improve readability.

[tburkard, 2012/08/15 21:05:56]

Done.

+    int num_active;
+    base::TimeTicks current_start_time;

[mmenke, 2012/08/15 18:45:41]

Think last_update_time would be more accurate.

[tburkard, 2012/08/15 21:05:56]

Done.

+    base::TimeDelta total_time;
+    base::TimeDelta total_cumulative_time;
+  };

[mmenke, 2012/08/15 18:45:41]

Inner classes/structs go before constructors.

[tburkard, 2012/08/15 21:05:56]

Done.

   std::pair<int, int> render_view_id;
-  int num_active;
+  PerRequestStatusData per_status_stats[REQUEST_STATUS_MAX];

[mmenke, 2012/08/15 18:45:41]

Your variable name and struct names should be more consistent.  I think that
PerStatusData or PerStatusStats is clearest.  "PerRequestStatusData" sounds a
bit like it's per request, which confused me at first.  May want to remove the
"Per" as well.

[tburkard, 2012/08/15 21:05:56]

Done.

   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)
     : content::WebContentsObserver(tab->web_contents()),
       cache_stats_(NULL) {
   is_otr_profile_ = tab->profile()->IsOffTheRecord();
 }
 
 CacheStatsTabHelper::~CacheStatsTabHelper() {
 }
@@ skipping 25 matching lines @@
   int route_id = render_view_host->GetRoutingID();
   BrowserThread::PostTask(
       BrowserThread::IO, FROM_HERE,
       base::Bind(&CallCacheStatsTabEventOnIOThread,
                  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));
+  for (int status_int = REQUEST_STATUS_CACHE_WAIT;
+       status_int <= REQUEST_STATUS_ACTIVE;
+       status_int++) {
+    RequestStatus status = static_cast<RequestStatus>(status_int);

[mmenke, 2012/08/15 18:45:41]

It looks to me like we don't need this.  Can just rename status_int to status
(Or maybe, request_status), and use it directly.

[tburkard, 2012/08/15 21:05:56]

Done.

+    for (int type_int = HISTOGRAM_FINAL_AGGREGATE;
+         type_int < HISTOGRAM_MAX;
+         type_int++) {
+      HistogramType type = static_cast<HistogramType>(type_int);

[mmenke, 2012/08/15 18:45:41]

Same as above.  I'd also suggest using histogram_type rather than type, as it's
a little too ambiguous.

[tburkard, 2012/08/15 21:05:56]

Done.

+      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() {
   STLDeleteValues(&tab_load_stats_);
 }
 
 CacheStats::TabLoadStats* CacheStats::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())
     return it->second;
   TabLoadStats* new_tab_load_stats = new TabLoadStats(render_view_id, this);
   tab_load_stats_[render_view_id] = new_tab_load_stats;
   return new_tab_load_stats;
 }
 
 void CacheStats::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;
     tab_load_stats_.erase(it);
   }
 }
 
-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;
   int process_id, route_id;
   if (!GetRenderView(request, &process_id, &route_id))
     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);

[mmenke, 2012/08/15 18:45:41]

Can just use status again.

[tburkard, 2012/08/15 21:05:56]

Done.

+      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--;

[mmenke, 2012/08/15 18:45:41]

Why not just mess with the stats for old_status and new_status?

[tburkard, 2012/08/15 21:05:56]

Done.

+      }
+      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;

[mmenke, 2012/08/15 18:45:41]

This could be put in the above if statement, right?

[tburkard, 2012/08/15 21:05:56]

Done.

 }
 
 void CacheStats::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();
+    for (int status_int = REQUEST_STATUS_CACHE_WAIT;
+         status_int <= REQUEST_STATUS_ACTIVE; status_int++) {
+      RequestStatus status = static_cast<RequestStatus>(status_int);

[mmenke, 2012/08/15 18:45:41]

Again, don't need status_int and status.

[tburkard, 2012/08/15 21:05:56]

Done.

+      stats->per_status_stats[status].ResetTimes();
+    }
     stats->next_timer_index = 0;
     ScheduleTimer(stats);
   } else {
     DCHECK_EQ(event, SPINNER_STOP);
     if (stats->spinner_started) {
       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);
   }
 }
 
 void CacheStats::ScheduleTimer(TabLoadStats* stats) {
   int timer_index = stats->next_timer_index;
   DCHECK(timer_index >= 0 &&
          timer_index < static_cast<int>(arraysize(kStatsCollectionTimesMs)));
   base::TimeDelta delta =
@@ skipping 10 matching lines @@
   stats->timer.Start(FROM_HERE,
                      delta,
                      base::Bind(&CacheStats::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);
+  RecordHistograms(load_time, stats, false);
   stats->next_timer_index++;
   if (stats->next_timer_index <
       static_cast<int>(arraysize(kStatsCollectionTimesMs))) {
     ScheduleTimer(stats);
   } else {
     RemoveTabLoadStats(stats->render_view_id);
   }
 }
 
-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);
+      }
+    }
   }
 }
 
 void CacheStats::RegisterURLRequestContext(
     const net::URLRequestContext* context,
     ChromeURLRequestContext::ContextType type) {
   if (type == ChromeURLRequestContext::CONTEXT_TYPE_MAIN)
     main_request_contexts_.insert(context);
 }
 
 void CacheStats::UnregisterURLRequestContext(
     const net::URLRequestContext* context) {
   main_request_contexts_.erase(context);
 }
 
 }  // namespace chrome_browser_net