Adding histograms showing fraction of page load times

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 <vector>
+
+#include "base/hash_tables.h"
+#include "base/metrics/histogram.h"
+#include "base/stl_util.h"
+#include "base/string_number_conversions.h"
+#include "base/timer.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"
+#include <stdio.h>

[mmenke, 2012/07/19 17:55:34]

Fix include order.

[tburkard, 2012/07/19 22:54:33]

Done.

+
+using content::BrowserThread;
+using content::ResourceRequestInfo;
+
+#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);
+  }
+};
+}
+
+#endif
+
+namespace chrome_browser_net {
+
+namespace {
+
+bool GetRenderView(const net::URLRequest& request,
+                   int* process_id, int* route_id) {
+  const ResourceRequestInfo* info = ResourceRequestInfo::ForRequest(&request);
+  if (!info)
+    return false;
+
+  return info->GetAssociatedRenderView(process_id, route_id);
+}
+
+// Times after a load has started at which stats are collected.
+const int kStatsCollectionTimesMs[] = {
+  500,
+  1000,
+  2000,
+  3000,
+  4000,
+  5000,
+  7500,
+  10000,
+  15000,
+  20000
+};
+
+}  // namespace
+
+// static
+CacheStats* CacheStats::GetInstance() {
+  return Singleton<CacheStats>::get();
+}
+
+struct CacheStats::TabLoadStats {
+  int num_active_;
+  base::TimeTicks load_start_time_;
+  base::TimeTicks cache_start_time_;
+  base::TimeDelta cache_total_time_;
+  base::Timer timer_;
+  typedef base::hash_map<const net::URLRequest*, int> PerRequestNumActiveMap;
+  PerRequestNumActiveMap per_request_num_active_;
+  TabLoadStats()
+      : num_active_(0),
+        timer_(false, false) {
+  }
+};
+
+CacheStatsTabHelper::CacheStatsTabHelper(TabContents* tab)
+    : content::WebContentsObserver(tab->web_contents()),
+      cache_stats_(CacheStats::GetInstance()),
+      is_loading_(false),
+      render_view_id_initialized_(false) {
+}
+
+CacheStatsTabHelper::~CacheStatsTabHelper() {
+  DidStopLoading();
+  if (render_view_id_initialized_)
+    NotifyCacheStats(CacheStats::RENDERER_DESTROY);
+}
+
+void CacheStatsTabHelper::DidStartProvisionalLoadForFrame(
+      int64 frame_id,
+      bool is_main_frame,
+      const GURL& validated_url,
+      bool is_error_page,
+      content::RenderViewHost* render_view_host) {

[mmenke, 2012/07/19 17:55:34]

Fix indent

[tburkard, 2012/07/19 22:54:33]

Done.

+  if (!render_view_id_initialized_)
+    return;
+  if (!is_main_frame)
+    return;
+  if (!validated_url.SchemeIs("http"))
+    return;
+  // If is_loading_ is already true, it means the user navigated to a new
+  // URL while the old URL is still in progress.  That is ok, we will
+  // just reset the metrics for the new page load in this case.
+  if (is_loading_)
+    NotifyCacheStats(CacheStats::SPINNER_STOP);
+  is_loading_ = true;
+  NotifyCacheStats(CacheStats::SPINNER_START);
+}
+
+void CacheStatsTabHelper::DidStopLoading() {
+  if (!is_loading_)
+    return;
+  is_loading_ = false;
+  NotifyCacheStats(CacheStats::SPINNER_STOP);

[mmenke, 2012/07/19 17:55:34]

It's actually possible for this not to be for the page with the last
DidStartProvisionalLoadForFrame, I believe.  Not sure there's much we can do
about that case, but with this code, we will always get the render view id wrong
in that case.

[tburkard, 2012/07/19 22:54:33]

will fix separately.

On 2012/07/19 17:55:34, Matt Menke wrote:

+}
+
+void CacheStatsTabHelper::RenderViewCreated(
+    content::RenderViewHost* render_view_host) {
+  DidStopLoading();
+  if (render_view_id_initialized_)
+    NotifyCacheStats(CacheStats::RENDERER_DESTROY);

[mmenke, 2012/07/19 17:55:34]

This is incorrect - if it's a cross process navigation, it could end up being
cancelled, and then we'd be keeping the old render view around, so process_id,
route_id, and render_view_id_ would all be incorrect.

Also, I'm not sure what happens for interstitial pages - a new RenderView is
created, but I'm not sure whether or not we'd ever hear about it here.  I don't
believe they'll access the cache (Or do any over the wire requests), but I'm not
positive.

[tburkard, 2012/07/19 22:54:33]

will fix separately.

On 2012/07/19 17:55:34, Matt Menke wrote:

+  int process_id = render_view_host->GetProcess()->GetID();
+  int route_id = render_view_host->GetRoutingID();
+  render_view_id_ = std::pair<int, int>(process_id, route_id);
+  render_view_id_initialized_ = true;
+}
+
+  void CacheStatsTabHelper::NotifyCacheStats(CacheStats::TabEvent event) {

[mmenke, 2012/07/19 17:55:34]

Fix indent

[tburkard, 2012/07/19 22:54:33]

Done.

+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
+  BrowserThread::PostTask(
+      BrowserThread::IO, FROM_HERE,
+      base::Bind(&CacheStats::OnTabEvent,
+                 base::Unretained(cache_stats_),
+                 render_view_id_, event));
+}
+
+CacheStats::CacheStats() :
+    registered_message_loop_destruction_observer_(false) {
+  for (int i = 0;
+       i < static_cast<int>(arraysize(kStatsCollectionTimesMs));
+       i++) {
+    final_histograms_.push_back(
+        base::LinearHistogram::FactoryGet(
+            "DiskCache.FractionCacheUseFinalPLT_" +
+            base::IntToString(kStatsCollectionTimesMs[i]),
+            0, 101, 102, base::Histogram::kUmaTargetedHistogramFlag));
+    intermediate_histograms_.push_back(
+        base::LinearHistogram::FactoryGet(
+            "DiskCache.FractionCacheUseIntermediatePLT_" +
+            base::IntToString(kStatsCollectionTimesMs[i]),
+            0, 101, 102, base::Histogram::kNoFlags));
+  }
+  DCHECK(final_histograms_.size() == arraysize(kStatsCollectionTimesMs));
+  DCHECK(intermediate_histograms_.size() == arraysize(kStatsCollectionTimesMs));

[mmenke, 2012/07/19 17:55:34]

DCHECK_EQ?

[tburkard, 2012/07/19 22:54:33]

Done.

+}
+
+CacheStats::~CacheStats() {
+}
+
+void CacheStats::WillDestroyCurrentMessageLoop() {
+  MessageLoop::current()->RemoveDestructionObserver(this);
+  STLDeleteValues(&tab_load_stats_);
+  registered_message_loop_destruction_observer_ = false;
+}
+
+CacheStats::TabLoadStats* CacheStats::GetTabLoadStats(
+    std::pair<int, int> render_view_id) {
+  if (!registered_message_loop_destruction_observer_) {
+    MessageLoop::current()->AddDestructionObserver(this);
+    registered_message_loop_destruction_observer_ = true;
+  }
+  if (tab_load_stats_.count(render_view_id) < 1)
+    tab_load_stats_[render_view_id] = new TabLoadStats();
+  return tab_load_stats_[render_view_id];
+}
+
+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(
+    const net::URLRequest& request,
+    net::NetworkDelegate::CacheWaitState state) {
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
+  int render_view, route_id;

[mmenke, 2012/07/19 17:55:34]

render_view should be process_id.

[tburkard, 2012/07/19 22:54:33]

Done.

+  if (!GetRenderView(request, &render_view, &route_id))
+    return;
+  TabLoadStats* stats =
+      GetTabLoadStats(std::pair<int, int>(render_view, route_id));
+  bool newly_started = false;
+  bool newly_finished = false;
+  std::pair<TabLoadStats::PerRequestNumActiveMap::iterator, bool> insert_ret =
+      stats->per_request_num_active_.insert(
+          std::pair<const net::URLRequest*, int>(&request, 0));
+  TabLoadStats::PerRequestNumActiveMap::iterator entry = insert_ret.first;
+  DCHECK(entry->second >= 0);
+  switch (state) {
+    case net::NetworkDelegate::CACHE_WAIT_STATE_START:
+      if (entry->second == 0)
+        newly_started = true;
+      entry->second++;
+      break;
+    case net::NetworkDelegate::CACHE_WAIT_STATE_FINISH:
+      if (entry->second > 0) {
+        entry->second--;
+        if (entry->second == 0)
+          newly_finished = true;
+      }
+      break;
+    case net::NetworkDelegate::CACHE_WAIT_STATE_DONE:
+      if (entry->second > 0) {
+        entry->second = 0;
+        newly_finished = true;
+      }
+      break;
+  }
+  DCHECK(entry->second >= 0);

[mmenke, 2012/07/19 17:55:34]

DCHECK_GE?

[tburkard, 2012/07/19 22:54:33]

Done.

+  DCHECK(!newly_started || !newly_finished);

[mmenke, 2012/07/19 17:55:34]

I find this a little hard to follow.  I'd suggest just doing a
DCHECK(!newly_finished) in the newly_started case.

[tburkard, 2012/07/19 22:54:33]

Done.

+  if (newly_started) {
+    if (stats->num_active_ == 0) {
+      stats->cache_start_time_ = base::TimeTicks::Now();
+    }
+    stats->num_active_++;
+  }
+  if (newly_finished) {
+    if (stats->num_active_ == 1) {
+      stats->cache_total_time_ +=
+          base::TimeTicks::Now() - stats->cache_start_time_;

[mmenke, 2012/07/19 17:55:34]

Should we remove it from the map?  Otherwise, as long as there's no main frame
navigation, we'll continue to accumulate objects.

[tburkard, 2012/07/19 22:54:33]

will fix separately.

On 2012/07/19 17:55:34, Matt Menke wrote:

+    }
+    stats->num_active_--;
+  }
+}
+
+void CacheStats::OnTabEvent(std::pair<int, int> render_view_id,
+                            TabEvent event) {
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
+  if (event == RENDERER_DESTROY) {
+    RemoveTabLoadStats(render_view_id);
+    return;
+  }
+  TabLoadStats* stats = GetTabLoadStats(render_view_id);
+  if (event == SPINNER_START) {
+    stats->cache_total_time_ = base::TimeDelta();
+    stats->cache_start_time_ = base::TimeTicks::Now();
+    stats->load_start_time_ = base::TimeTicks::Now();
+    ScheduleTimer(stats, 0);
+  } else {
+    stats->timer_.Stop();
+    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);
+    RemoveTabLoadStats(render_view_id);

[mmenke, 2012/07/19 17:55:34]

So when navigating though an HTTPS site...We just accumulate objects until the
tab is closed or we navigate to a non-https site?

[tburkard, 2012/07/19 22:54:33]

will fix separately.

On 2012/07/19 17:55:34, Matt Menke wrote:

+  }
+}
+
+void CacheStats::ScheduleTimer(TabLoadStats* stats, int 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_;
+  stats->timer_.Start(FROM_HERE,
+                      delta,
+                      base::Bind(&CacheStats::TimerCb,
+                                 base::Unretained(this),
+                                 base::Unretained(stats),
+                                 timer_index));
+}
+
+void CacheStats::TimerCb(TabLoadStats* stats, int timer_index) {
+  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);
+  timer_index++;
+  if (timer_index < static_cast<int>(arraysize(kStatsCollectionTimesMs)))
+    ScheduleTimer(stats, timer_index);
+}
+
+void CacheStats::RecordCacheFractionHistogram(base::TimeDelta elapsed,
+                                              base::TimeDelta cache_time,
+                                              bool is_load_done) {
+  if (elapsed.InMilliseconds() <= 0)
+    return;
+
+  double cache_fraction =
+      static_cast<double>(cache_time.InMilliseconds()) /
+      static_cast<double>(elapsed.InMilliseconds());
+
+  DCHECK(cache_fraction >= 0.0 && cache_fraction <= 1.0);
+  int cache_fraction_percentage = cache_fraction * 100;
+  DCHECK(cache_fraction_percentage >= 0 && cache_fraction_percentage < 100);
+
+  int index = 0;
+  while (index + 1 < static_cast<int>(arraysize(kStatsCollectionTimesMs)) &&
+         base::TimeDelta::FromMilliseconds(kStatsCollectionTimesMs[index + 1]) <
+         elapsed) {
+    index++;
+  }
+
+  if (is_load_done) {
+    final_histograms_[index]->Add(cache_fraction_percentage);
+  } else {
+    intermediate_histograms_[index]->Add(cache_fraction_percentage);
+  }
+}
+
+}  // namespace chrome_browser_net