// 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/load_time_stats.h"
#include "base/debug/trace_event.h"
#include "base/metrics/histogram.h"
#include "base/stl_util.h"
#include "base/strings/string_number_conversions.h"
#include "base/timer/timer.h"
#include "chrome/browser/browser_process.h"
#include "chrome/browser/io_thread.h"
#include "chrome/browser/profiles/profile.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;
DEFINE_WEB_CONTENTS_USER_DATA_KEY(chrome_browser_net::LoadTimeStatsTabHelper);
namespace {
bool GetRenderView(const net::URLRequest& request,
int* process_id, int* route_id) {
DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
const ResourceRequestInfo* info = ResourceRequestInfo::ForRequest(&request);
if (!info)
return false;
return info->GetAssociatedRenderView(process_id, route_id);
}
void CallLoadTimeStatsTabEventOnIOThread(
std::pair<int, int> render_view_id,
chrome_browser_net::LoadTimeStats::TabEvent event,
IOThread* io_thread) {
DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
if (io_thread)
io_thread->globals()->load_time_stats->OnTabEvent(render_view_id, event);
}
// Times after a load has started at which stats are collected.
const int kStatsCollectionTimesMs[] = {
1000,
2000,
4000,
20000
};
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 {
// 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.
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, LoadTimeStats
// will start using the timer, thereby cancelling the cleanup.
// 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(&LoadTimeStats::RemoveTabLoadStats,
base::Unretained(owner),
render_view_id_));
}
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_; }
void set_load_start_time(base::TimeTicks time) { load_start_time_ = 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_;
};
class LoadTimeStats::URLRequestStats {
public:
URLRequestStats()
: done_(false),
start_time_(GetCurrentTime()),
status_(REQUEST_STATUS_ACTIVE) {
}
void OnStatusChange(RequestStatus new_status) {
if (done_)
return;
DCHECK_GE(status_, 0);
DCHECK_GE(new_status, 0);
DCHECK_LE(status_, REQUEST_STATUS_ACTIVE);
DCHECK_LE(new_status, REQUEST_STATUS_ACTIVE);
base::TimeTicks now = GetCurrentTime();
base::TimeDelta elapsed = now - start_time_;
status_times_[status_] += elapsed;
start_time_ = now;
status_ = new_status;
}
void RequestDone() {
DCHECK(!done_);
// Dummy status change to add last elapsed time.
OnStatusChange(REQUEST_STATUS_ACTIVE);
done_ = true;
UMA_HISTOGRAM_TIMES("LoadTimeStats.Request_CacheWait_Time",
status_times_[REQUEST_STATUS_CACHE_WAIT]);
UMA_HISTOGRAM_TIMES("LoadTimeStats.Request_NetworkWait_Time",
status_times_[REQUEST_STATUS_NETWORK_WAIT]);
UMA_HISTOGRAM_TIMES("LoadTimeStats.Request_Active_Time",
status_times_[REQUEST_STATUS_ACTIVE]);
base::TimeDelta total_time;
for (int status = REQUEST_STATUS_CACHE_WAIT;
status <= REQUEST_STATUS_ACTIVE;
status++) {
total_time += status_times_[status];
}
if (total_time.InMilliseconds() <= 0)
return;
for (int status = REQUEST_STATUS_CACHE_WAIT;
status <= REQUEST_STATUS_ACTIVE;
status++) {
int64 fraction_percentage = 100 *
status_times_[status].InMilliseconds() /
total_time.InMilliseconds();
DCHECK(fraction_percentage >= 0 && fraction_percentage <= 100);
switch (status) {
case REQUEST_STATUS_CACHE_WAIT:
UMA_HISTOGRAM_PERCENTAGE(
"LoadTimeStats.Request_CacheWait_Percentage",
fraction_percentage);
break;
case REQUEST_STATUS_NETWORK_WAIT:
UMA_HISTOGRAM_PERCENTAGE(
"LoadTimeStats.Request_NetworkWait_Percentage",
fraction_percentage);
break;
case REQUEST_STATUS_ACTIVE:
UMA_HISTOGRAM_PERCENTAGE(
"LoadTimeStats.Request_Active_Percentage", fraction_percentage);
break;
}
}
}
private:
base::TimeTicks GetCurrentTime() {
return base::TimeTicks::Now();
}
bool done_;
base::TimeTicks start_time_;
RequestStatus status_;
base::TimeDelta status_times_[REQUEST_STATUS_MAX];
};
LoadTimeStatsTabHelper::LoadTimeStatsTabHelper(
content::WebContents* web_contents)
: content::WebContentsObserver(web_contents) {
is_otr_profile_ = web_contents->GetBrowserContext()->IsOffTheRecord();
}
LoadTimeStatsTabHelper::~LoadTimeStatsTabHelper() {
}
void LoadTimeStatsTabHelper::DidStartProvisionalLoadForFrame(
int64 frame_id,
int64 parent_frame_id,
bool is_main_frame,
const GURL& validated_url,
bool is_error_page,
bool is_iframe_srcdoc,
content::RenderViewHost* render_view_host) {
if (!is_main_frame)
return;
if (!validated_url.SchemeIs("http"))
return;
NotifyLoadTimeStats(LoadTimeStats::SPINNER_START, render_view_host);
}
void LoadTimeStatsTabHelper::DidStopLoading(RenderViewHost* render_view_host) {
NotifyLoadTimeStats(LoadTimeStats::SPINNER_STOP, render_view_host);
}
void LoadTimeStatsTabHelper::NotifyLoadTimeStats(
LoadTimeStats::TabEvent event,
RenderViewHost* render_view_host) {
DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
if (is_otr_profile_)
return;
int process_id = render_view_host->GetProcess()->GetID();
int route_id = render_view_host->GetRoutingID();
BrowserThread::PostTask(
BrowserThread::IO, FROM_HERE,
base::Bind(&CallLoadTimeStatsTabEventOnIOThread,
std::pair<int, int>(process_id, route_id),
event,
base::Unretained(g_browser_process->io_thread())));
}
LoadTimeStats::LoadTimeStats() {
TRACE_EVENT0("browser", "LoadTimeStats::ctor");
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, 51, base::HistogramBase::kUmaTargetedHistogramFlag));
}
DCHECK_EQ(histograms_[status][histogram_type].size(),
arraysize(kStatsCollectionTimesMs));
}
}
}
LoadTimeStats::~LoadTimeStats() {
STLDeleteValues(&tab_load_stats_);
STLDeleteValues(&request_stats_);
}
LoadTimeStats::URLRequestStats* LoadTimeStats::GetRequestStats(
const net::URLRequest* request) {
RequestStatsMap::const_iterator it = request_stats_.find(request);
if (it != request_stats_.end())
return it->second;
URLRequestStats* new_request_stats = new URLRequestStats();
request_stats_[request] = new_request_stats;
return new_request_stats;
}
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())
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 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;
tab_load_stats_.erase(it);
}
}
void LoadTimeStats::OnRequestWaitStateChange(
const net::URLRequest& request,
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));
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::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::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::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;
}
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 (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;
URLRequestStats* request_stats = GetRequestStats(&request);
request_stats->OnStatusChange(new_status);
} else {
stats->active_requests().erase(&request);
}
}
void LoadTimeStats::OnURLRequestDestroyed(const net::URLRequest& request) {
if (request_stats_.count(&request) < 1)
return;
scoped_ptr<URLRequestStats> request_stats(GetRequestStats(&request));
request_stats_.erase(&request);
request_stats->RequestDone();
}
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->set_spinner_started(true);
stats->set_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->set_next_timer_index(0);
ScheduleTimer(stats);
} else {
DCHECK_EQ(event, SPINNER_STOP);
if (stats->spinner_started()) {
stats->set_spinner_started(false);
base::TimeDelta load_time =
base::TimeTicks::Now() - stats->load_start_time();
RecordHistograms(load_time, stats, true);
}
RemoveTabLoadStats(render_view_id);
}
}
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();
// 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());
return;
}
stats->timer().Start(FROM_HERE,
delta,
base::Bind(&LoadTimeStats::TimerCallback,
base::Unretained(this),
base::Unretained(stats)));
}
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());
}
}
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;
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();
}
for (int status = REQUEST_STATUS_CACHE_WAIT;
status <= REQUEST_STATUS_ACTIVE;
status++) {
TabLoadStats::PerStatusStats* status_stats =
&(stats->per_status_stats()[status]);
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 LoadTimeStats::RegisterURLRequestContext(
const net::URLRequestContext* context,
ChromeURLRequestContext::ContextType type) {
if (type == ChromeURLRequestContext::CONTEXT_TYPE_MAIN)
main_request_contexts_.insert(context);
}
void LoadTimeStats::UnregisterURLRequestContext(
const net::URLRequestContext* context) {
main_request_contexts_.erase(context);
}
} // namespace chrome_browser_net