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 {
+
+  // Stores the time taken by all requests while they have a certain
+  // RequestStatus.
+  struct PerStatusStats {
+    PerStatusStats()
+        : num_active(0) {
+    }
+
+    void UpdateTotalTimes() {
+      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();
+    }
+
+    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, 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));
   }
 
   std::pair<int, int> render_view_id;
-  int num_active;
+  PerStatusStats 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)
     : 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 = 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("CacheStats.Fraction_") +
+            string(kRequestStatusNames[status]) + string("_") +
+            string(kHistogramTypeNames[histogram_type]) + string("_") +
+            base::IntToString(kStatsCollectionTimesMs[i]);
+        if (histogram_type != HISTOGRAM_FINAL_CUMULATIVE_PERCENTAGE &&
+            histogram_type != HISTOGRAM_INTERMEDIATE_CUMULATIVE_PERCENTAGE) {
+          histograms_[status][histogram_type].push_back(
+              base::LinearHistogram::FactoryGet(
+                  histogram_name,
+                  0, 101, 102, base::Histogram::kUmaTargetedHistogramFlag));
+        } else {
+          histograms_[status][histogram_type].push_back(
+              base::Histogram::FactoryGet(
+                  histogram_name,
+                  0, 10000, 500, base::Histogram::kUmaTargetedHistogramFlag));

[rvargas (doing something else), 2012/08/16 01:18:40]

What I really want is still a linear, 100 bucket histogram where the denominator
is not the wall time but the total cumulative time.

[tburkard, 2012/08/16 22:37:43]

I'm not sure I understand -- you want absolute times?  But that'll be hard to
compare then, because the data points will all belong to varying page load
times, making them hardly comparable?  That's why I find percentages more
meaningful in this case.

[rvargas (doing something else), 2012/08/17 02:36:36]

No, I don't want absolute times.

What I want is still the percentage of the cumulative time that is used in each
part. So for example, if the elapsed time is 2 seconds, and we tracked 10
requests, the total cumulative time would be something close to 20 seconds
(maybe 17). If the cumulative cache time is 5 seconds I want a histogram to say
29% (5/17) not 250% (5/2). I have no idea how to compare 1500% numbers, and the
histogram itself is more complex.

[tburkard, 2012/08/17 20:21:00]

I think what you are talking about is just what the third histogram,
CUMULATIVE_PERCENTAGE, expresses:
For all requests, it takes the total time (including duplication) used for
cache, network, other stuff while requests were active, adds them, and takes the
ratio of each cache, network, and other stuff to that total time.  Isn't that
what you are asking for?

[rvargas (doing something else), 2012/08/17 22:05:00]

So we have 6 types of histograms, and four(*) of those types are actually 500
bucket, log scaled histograms from 0 to 10k?. That doesn't sound right to me.
They don't look really useful to me. (and I had to go back to this line when
reading how values to be placed on the histograms were computed, I guess I
actually didn't reach the last two).

I actually have an issue with writing 500 bucket histograms.

(*) yes two, not four. Please invert the logic and use x == a || x == b if we
end up leaving this type of histogram. The logic is actually wrong because in
the xx_percentage case is going to the else.

(**) The second reason I got confused here is that when I reviewed the code last
time (previous CL), you were using base::Histogram::kNoFlags for all the
intermediate ones, and I missed when that changed to report everything... so at
first this appeared to be the same split of reported vs not reported.

[tburkard, 2012/08/17 22:39:56]

First, there was an error in the code, I had intended to make 500 bucket
histograms for the non-percentage histograms (CUMULATIVE, not
CUMULATIVE_PERCENTAGE, as the code incorrectly stated).  However, thinking about
this some more, I agree with you that these are not all that useful, so I
removed them altogether, so there are no more 500 bucket histograms now.

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

[rvargas (doing something else), 2012/08/16 01:18:40]

I don't think we need both of these states.

The way I see it, a request is in the NONE state before we see it (so nothing to
do about it), and after the transaction finishes or it is restarted.

The restart case is interesting because the request itself is still alive and we
are doing work for it (creating a new job etc), so it should really be marked as
active at that time.

I guess it's basically the same thing, except that in one case there's a very
small under-counting of the ACTIVE number (don't really care about it), and we
need to track another state. So it's not that big of a deal.

[tburkard, 2012/08/16 22:37:43]

I think it works fine the way it is.  In the case of a restart that you mention
-- I verified the code, the restart happens instantly, so there is no pending
callback or anything like that lost (just a few instructions).  I'll leave it
the way it is.

+      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();
+    if (status_stats->num_active > 0)
+      status_stats->num_active--;
+    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->num_active++;
+    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,
                             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 = REQUEST_STATUS_CACHE_WAIT;
+         status <= REQUEST_STATUS_ACTIVE; status++) {
+      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::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);
+    }
+
+    fraction_percentage = 100 *

[rvargas (doing something else), 2012/08/17 22:05:00]

Can we just eliminate these 60 histograms?

[tburkard, 2012/08/17 22:39:56]

Done.

+        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