| // 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 |