1 // Copyright (c) 2012 The Chromium Authors. All rights reserved. 2 // Use of this source code is governed by a BSD-style license that can be 3 // found in the LICENSE file. 4 5 #include "chrome/browser/net/load_time_stats.h" 6 7 #include "base/debug/trace_event.h" 8 #include "base/metrics/histogram.h" 9 #include "base/stl_util.h" 10 #include "base/strings/string_number_conversions.h" 11 #include "base/timer/timer.h" 12 #include "chrome/browser/browser_process.h" 13 #include "chrome/browser/io_thread.h" 14 #include "chrome/browser/profiles/profile.h" 15 #include "content/public/browser/browser_thread.h" 16 #include "content/public/browser/render_process_host.h" 17 #include "content/public/browser/render_view_host.h" 18 #include "content/public/browser/resource_request_info.h" 19 #include "content/public/browser/web_contents.h" 20 #include "net/url_request/url_request.h" 21 22 using content::BrowserThread; 23 using content::RenderViewHost; 24 using content::ResourceRequestInfo; 25 using std::string; 26 27 DEFINE_WEB_CONTENTS_USER_DATA_KEY(chrome_browser_net::LoadTimeStatsTabHelper); 28 29 namespace { 30 31 bool GetRenderView(const net::URLRequest& request, 32 int* process_id, int* route_id) { 33 DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO)); 34 const ResourceRequestInfo* info = ResourceRequestInfo::ForRequest(&request); 35 if (!info) 36 return false; 37 return info->GetAssociatedRenderView(process_id, route_id); 38 } 39 40 void CallLoadTimeStatsTabEventOnIOThread( 41 std::pair<int, int> render_view_id, 42 chrome_browser_net::LoadTimeStats::TabEvent event, 43 IOThread* io_thread) { 44 DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO)); 45 if (io_thread) 46 io_thread->globals()->load_time_stats->OnTabEvent(render_view_id, event); 47 } 48 49 // Times after a load has started at which stats are collected. 50 const int kStatsCollectionTimesMs[] = { 51 1000, 52 2000, 53 4000, 54 20000 55 }; 56 57 static int kTabLoadStatsAutoCleanupTimeoutSeconds = 30; 58 59 const char* kRequestStatusNames[] = { 60 "CacheWait", 61 "NetworkWait", 62 "Active", 63 "None", 64 "Max" 65 }; 66 67 COMPILE_ASSERT(arraysize(kRequestStatusNames) == 68 chrome_browser_net::LoadTimeStats::REQUEST_STATUS_MAX + 1, 69 LoadTimeStats_RequestStatus_names_mismatch); 70 71 const char* kHistogramTypeNames[] = { 72 "FinalAggregate", 73 "FinalCumulativePercentage", 74 "IntermediateAggregate", 75 "IntermediateCumulativePercentage", 76 "Max" 77 }; 78 79 COMPILE_ASSERT(arraysize(kHistogramTypeNames) == 80 chrome_browser_net::LoadTimeStats::HISTOGRAM_MAX + 1, 81 LoadTimeStats_HistogramType_names_mismatch); 82 83 } // namespace 84 85 namespace chrome_browser_net { 86 87 // Helper struct keeping stats about the page load progress & cache usage 88 // stats during the pageload so far for a given RenderView, identified 89 // by a pair of process id and route id. 90 class LoadTimeStats::TabLoadStats { 91 public: 92 // Stores the time taken by all requests while they have a certain 93 // RequestStatus. 94 class PerStatusStats { 95 public: 96 PerStatusStats() : num_active_(0) { 97 } 98 99 void UpdateTotalTimes() { 100 DCHECK_GE(num_active_, 0); 101 base::TimeTicks now = base::TimeTicks::Now(); 102 if (num_active_ > 0) { 103 total_time_ += now - last_update_time_; 104 total_cumulative_time_ += 105 (now - last_update_time_) * static_cast<int64>(num_active_); 106 } 107 last_update_time_ = now; 108 } 109 110 void ResetTimes() { 111 last_update_time_ = base::TimeTicks::Now(); 112 total_time_ = base::TimeDelta(); 113 total_cumulative_time_ = base::TimeDelta(); 114 } 115 116 void IncrementNumActive() { 117 num_active_++; 118 } 119 120 void DecrementNumActiveIfPositive() { 121 if (num_active_ > 0) 122 num_active_--; 123 } 124 125 int num_active() { return num_active_; } 126 void set_num_active(int num_active) { num_active_ = num_active; } 127 base::TimeDelta total_time() { return total_time_; } 128 base::TimeDelta total_cumulative_time() { return total_cumulative_time_; } 129 130 private: 131 int num_active_; 132 base::TimeTicks last_update_time_; 133 base::TimeDelta total_time_; 134 base::TimeDelta total_cumulative_time_; 135 }; 136 137 TabLoadStats(std::pair<int, int> render_view_id, LoadTimeStats* owner) 138 : render_view_id_(render_view_id), 139 spinner_started_(false), 140 next_timer_index_(0), 141 timer_(false, false) { 142 // Initialize the timer to do an automatic cleanup. If a pageload is 143 // started for the TabLoadStats within that timeframe, LoadTimeStats 144 // will start using the timer, thereby cancelling the cleanup. 145 // Once LoadTimeStats starts the timer, the object is guaranteed to be 146 // destroyed eventually, so there is no more need for automatic cleanup at 147 // that point. 148 timer_.Start(FROM_HERE, 149 base::TimeDelta::FromSeconds( 150 kTabLoadStatsAutoCleanupTimeoutSeconds), 151 base::Bind(&LoadTimeStats::RemoveTabLoadStats, 152 base::Unretained(owner), 153 render_view_id_)); 154 } 155 156 typedef std::pair<int, int> RenderViewId; 157 typedef PerStatusStats PerStatusStatsArray[REQUEST_STATUS_MAX]; 158 typedef base::hash_map<const net::URLRequest*, RequestStatus> RequestMap; 159 160 RenderViewId& render_view_id() { return render_view_id_; } 161 PerStatusStatsArray& per_status_stats() { return per_status_stats_; } 162 bool spinner_started() { return spinner_started_; } 163 void set_spinner_started(bool value) { spinner_started_ = value; } 164 base::TimeTicks load_start_time() { return load_start_time_; } 165 void set_load_start_time(base::TimeTicks time) { load_start_time_ = time; } 166 int next_timer_index() { return next_timer_index_; } 167 void set_next_timer_index(int index) { next_timer_index_ = index; } 168 base::Timer& timer() { return timer_; } 169 RequestMap& active_requests() { return active_requests_; } 170 171 private: 172 RenderViewId render_view_id_; 173 PerStatusStatsArray per_status_stats_; 174 bool spinner_started_; 175 base::TimeTicks load_start_time_; 176 int next_timer_index_; 177 base::Timer timer_; 178 // Currently active URLRequests. 179 RequestMap active_requests_; 180 }; 181 182 class LoadTimeStats::URLRequestStats { 183 public: 184 URLRequestStats() 185 : done_(false), 186 start_time_(GetCurrentTime()), 187 status_(REQUEST_STATUS_ACTIVE) { 188 } 189 void OnStatusChange(RequestStatus new_status) { 190 if (done_) 191 return; 192 DCHECK_GE(status_, 0); 193 DCHECK_GE(new_status, 0); 194 DCHECK_LE(status_, REQUEST_STATUS_ACTIVE); 195 DCHECK_LE(new_status, REQUEST_STATUS_ACTIVE); 196 base::TimeTicks now = GetCurrentTime(); 197 base::TimeDelta elapsed = now - start_time_; 198 status_times_[status_] += elapsed; 199 start_time_ = now; 200 status_ = new_status; 201 } 202 void RequestDone() { 203 DCHECK(!done_); 204 // Dummy status change to add last elapsed time. 205 OnStatusChange(REQUEST_STATUS_ACTIVE); 206 done_ = true; 207 208 UMA_HISTOGRAM_TIMES("LoadTimeStats.Request_CacheWait_Time", 209 status_times_[REQUEST_STATUS_CACHE_WAIT]); 210 UMA_HISTOGRAM_TIMES("LoadTimeStats.Request_NetworkWait_Time", 211 status_times_[REQUEST_STATUS_NETWORK_WAIT]); 212 UMA_HISTOGRAM_TIMES("LoadTimeStats.Request_Active_Time", 213 status_times_[REQUEST_STATUS_ACTIVE]); 214 215 base::TimeDelta total_time; 216 for (int status = REQUEST_STATUS_CACHE_WAIT; 217 status <= REQUEST_STATUS_ACTIVE; 218 status++) { 219 total_time += status_times_[status]; 220 } 221 if (total_time.InMilliseconds() <= 0) 222 return; 223 224 for (int status = REQUEST_STATUS_CACHE_WAIT; 225 status <= REQUEST_STATUS_ACTIVE; 226 status++) { 227 int64 fraction_percentage = 100 * 228 status_times_[status].InMilliseconds() / 229 total_time.InMilliseconds(); 230 DCHECK(fraction_percentage >= 0 && fraction_percentage <= 100); 231 switch (status) { 232 case REQUEST_STATUS_CACHE_WAIT: 233 UMA_HISTOGRAM_PERCENTAGE( 234 "LoadTimeStats.Request_CacheWait_Percentage", 235 fraction_percentage); 236 break; 237 case REQUEST_STATUS_NETWORK_WAIT: 238 UMA_HISTOGRAM_PERCENTAGE( 239 "LoadTimeStats.Request_NetworkWait_Percentage", 240 fraction_percentage); 241 break; 242 case REQUEST_STATUS_ACTIVE: 243 UMA_HISTOGRAM_PERCENTAGE( 244 "LoadTimeStats.Request_Active_Percentage", fraction_percentage); 245 break; 246 } 247 } 248 } 249 250 private: 251 base::TimeTicks GetCurrentTime() { 252 return base::TimeTicks::Now(); 253 } 254 bool done_; 255 base::TimeTicks start_time_; 256 RequestStatus status_; 257 base::TimeDelta status_times_[REQUEST_STATUS_MAX]; 258 }; 259 260 LoadTimeStatsTabHelper::LoadTimeStatsTabHelper( 261 content::WebContents* web_contents) 262 : content::WebContentsObserver(web_contents) { 263 is_otr_profile_ = web_contents->GetBrowserContext()->IsOffTheRecord(); 264 } 265 266 LoadTimeStatsTabHelper::~LoadTimeStatsTabHelper() { 267 } 268 269 void LoadTimeStatsTabHelper::DidStartProvisionalLoadForFrame( 270 int64 frame_id, 271 int64 parent_frame_id, 272 bool is_main_frame, 273 const GURL& validated_url, 274 bool is_error_page, 275 bool is_iframe_srcdoc, 276 content::RenderViewHost* render_view_host) { 277 if (!is_main_frame) 278 return; 279 if (!validated_url.SchemeIs("http")) 280 return; 281 NotifyLoadTimeStats(LoadTimeStats::SPINNER_START, render_view_host); 282 } 283 284 void LoadTimeStatsTabHelper::DidStopLoading(RenderViewHost* render_view_host) { 285 NotifyLoadTimeStats(LoadTimeStats::SPINNER_STOP, render_view_host); 286 } 287 288 void LoadTimeStatsTabHelper::NotifyLoadTimeStats( 289 LoadTimeStats::TabEvent event, 290 RenderViewHost* render_view_host) { 291 DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI)); 292 if (is_otr_profile_) 293 return; 294 int process_id = render_view_host->GetProcess()->GetID(); 295 int route_id = render_view_host->GetRoutingID(); 296 BrowserThread::PostTask( 297 BrowserThread::IO, FROM_HERE, 298 base::Bind(&CallLoadTimeStatsTabEventOnIOThread, 299 std::pair<int, int>(process_id, route_id), 300 event, 301 base::Unretained(g_browser_process->io_thread()))); 302 } 303 304 LoadTimeStats::LoadTimeStats() { 305 TRACE_EVENT0("browser", "LoadTimeStats::ctor"); 306 for (int status = REQUEST_STATUS_CACHE_WAIT; 307 status <= REQUEST_STATUS_ACTIVE; 308 status++) { 309 for (int histogram_type = HISTOGRAM_FINAL_AGGREGATE; 310 histogram_type < HISTOGRAM_MAX; 311 histogram_type++) { 312 for (int i = 0; 313 i < static_cast<int>(arraysize(kStatsCollectionTimesMs)); 314 i++) { 315 string histogram_name = string("LoadTimeStats.Fraction_") + 316 string(kRequestStatusNames[status]) + string("_") + 317 string(kHistogramTypeNames[histogram_type]) + string("_") + 318 base::IntToString(kStatsCollectionTimesMs[i]); 319 histograms_[status][histogram_type].push_back( 320 base::LinearHistogram::FactoryGet( 321 histogram_name, 322 0, 101, 51, base::HistogramBase::kUmaTargetedHistogramFlag)); 323 } 324 DCHECK_EQ(histograms_[status][histogram_type].size(), 325 arraysize(kStatsCollectionTimesMs)); 326 } 327 } 328 } 329 330 LoadTimeStats::~LoadTimeStats() { 331 STLDeleteValues(&tab_load_stats_); 332 STLDeleteValues(&request_stats_); 333 } 334 335 LoadTimeStats::URLRequestStats* LoadTimeStats::GetRequestStats( 336 const net::URLRequest* request) { 337 RequestStatsMap::const_iterator it = request_stats_.find(request); 338 if (it != request_stats_.end()) 339 return it->second; 340 URLRequestStats* new_request_stats = new URLRequestStats(); 341 request_stats_[request] = new_request_stats; 342 return new_request_stats; 343 } 344 345 LoadTimeStats::TabLoadStats* LoadTimeStats::GetTabLoadStats( 346 std::pair<int, int> render_view_id) { 347 TabLoadStatsMap::const_iterator it = tab_load_stats_.find(render_view_id); 348 if (it != tab_load_stats_.end()) 349 return it->second; 350 TabLoadStats* new_tab_load_stats = new TabLoadStats(render_view_id, this); 351 tab_load_stats_[render_view_id] = new_tab_load_stats; 352 return new_tab_load_stats; 353 } 354 355 void LoadTimeStats::RemoveTabLoadStats(std::pair<int, int> render_view_id) { 356 TabLoadStatsMap::iterator it = tab_load_stats_.find(render_view_id); 357 if (it != tab_load_stats_.end()) { 358 delete it->second; 359 tab_load_stats_.erase(it); 360 } 361 } 362 363 void LoadTimeStats::OnRequestWaitStateChange( 364 const net::URLRequest& request, 365 net::NetworkDelegate::RequestWaitState state) { 366 DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO)); 367 if (main_request_contexts_.count(request.context()) < 1) 368 return; 369 int process_id, route_id; 370 if (!GetRenderView(request, &process_id, &route_id)) 371 return; 372 TabLoadStats* stats = 373 GetTabLoadStats(std::pair<int, int>(process_id, route_id)); 374 RequestStatus old_status = REQUEST_STATUS_NONE; 375 if (stats->active_requests().count(&request) > 0) 376 old_status = stats->active_requests()[&request]; 377 RequestStatus new_status = REQUEST_STATUS_NONE; 378 switch (state) { 379 case net::NetworkDelegate::REQUEST_WAIT_STATE_CACHE_START: 380 DCHECK(old_status == REQUEST_STATUS_NONE || 381 old_status == REQUEST_STATUS_ACTIVE); 382 new_status = REQUEST_STATUS_CACHE_WAIT; 383 break; 384 case net::NetworkDelegate::REQUEST_WAIT_STATE_CACHE_FINISH: 385 DCHECK(old_status == REQUEST_STATUS_NONE || 386 old_status == REQUEST_STATUS_CACHE_WAIT); 387 new_status = REQUEST_STATUS_ACTIVE; 388 break; 389 case net::NetworkDelegate::REQUEST_WAIT_STATE_NETWORK_START: 390 DCHECK(old_status == REQUEST_STATUS_NONE || 391 old_status == REQUEST_STATUS_ACTIVE); 392 new_status = REQUEST_STATUS_NETWORK_WAIT; 393 break; 394 case net::NetworkDelegate::REQUEST_WAIT_STATE_NETWORK_FINISH: 395 DCHECK(old_status == REQUEST_STATUS_NONE || 396 old_status == REQUEST_STATUS_NETWORK_WAIT); 397 new_status = REQUEST_STATUS_ACTIVE; 398 break; 399 case net::NetworkDelegate::REQUEST_WAIT_STATE_RESET: 400 new_status = REQUEST_STATUS_NONE; 401 break; 402 } 403 if (old_status == new_status) 404 return; 405 if (old_status != REQUEST_STATUS_NONE) { 406 TabLoadStats::PerStatusStats* status_stats = 407 &(stats->per_status_stats()[old_status]); 408 DCHECK_GE(status_stats->num_active(), 0); 409 status_stats->UpdateTotalTimes(); 410 status_stats->DecrementNumActiveIfPositive(); 411 DCHECK_GE(status_stats->num_active(), 0); 412 } 413 if (new_status != REQUEST_STATUS_NONE) { 414 TabLoadStats::PerStatusStats* status_stats = 415 &(stats->per_status_stats()[new_status]); 416 DCHECK_GE(status_stats->num_active(), 0); 417 status_stats->UpdateTotalTimes(); 418 status_stats->IncrementNumActive(); 419 DCHECK_GE(status_stats->num_active(), 0); 420 stats->active_requests()[&request] = new_status; 421 URLRequestStats* request_stats = GetRequestStats(&request); 422 request_stats->OnStatusChange(new_status); 423 } else { 424 stats->active_requests().erase(&request); 425 } 426 } 427 428 void LoadTimeStats::OnURLRequestDestroyed(const net::URLRequest& request) { 429 if (request_stats_.count(&request) < 1) 430 return; 431 scoped_ptr<URLRequestStats> request_stats(GetRequestStats(&request)); 432 request_stats_.erase(&request); 433 request_stats->RequestDone(); 434 } 435 436 void LoadTimeStats::OnTabEvent(std::pair<int, int> render_view_id, 437 TabEvent event) { 438 DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO)); 439 TabLoadStats* stats = GetTabLoadStats(render_view_id); 440 if (event == SPINNER_START) { 441 stats->set_spinner_started(true); 442 stats->set_load_start_time(base::TimeTicks::Now()); 443 for (int status = REQUEST_STATUS_CACHE_WAIT; 444 status <= REQUEST_STATUS_ACTIVE; status++) { 445 stats->per_status_stats()[status].ResetTimes(); 446 } 447 stats->set_next_timer_index(0); 448 ScheduleTimer(stats); 449 } else { 450 DCHECK_EQ(event, SPINNER_STOP); 451 if (stats->spinner_started()) { 452 stats->set_spinner_started(false); 453 base::TimeDelta load_time = 454 base::TimeTicks::Now() - stats->load_start_time(); 455 RecordHistograms(load_time, stats, true); 456 } 457 RemoveTabLoadStats(render_view_id); 458 } 459 } 460 461 void LoadTimeStats::ScheduleTimer(TabLoadStats* stats) { 462 int timer_index = stats->next_timer_index(); 463 DCHECK(timer_index >= 0 && 464 timer_index < static_cast<int>(arraysize(kStatsCollectionTimesMs))); 465 base::TimeDelta delta = 466 base::TimeDelta::FromMilliseconds(kStatsCollectionTimesMs[timer_index]); 467 delta -= base::TimeTicks::Now() - stats->load_start_time(); 468 469 // If the ScheduleTimer call was delayed significantly, like when one's using 470 // a debugger, don't try to start the timer with a negative time. 471 if (delta < base::TimeDelta()) { 472 RemoveTabLoadStats(stats->render_view_id()); 473 return; 474 } 475 476 stats->timer().Start(FROM_HERE, 477 delta, 478 base::Bind(&LoadTimeStats::TimerCallback, 479 base::Unretained(this), 480 base::Unretained(stats))); 481 } 482 483 void LoadTimeStats::TimerCallback(TabLoadStats* stats) { 484 DCHECK(stats->spinner_started()); 485 base::TimeDelta load_time = base::TimeTicks::Now() - stats->load_start_time(); 486 RecordHistograms(load_time, stats, false); 487 stats->set_next_timer_index(stats->next_timer_index() + 1); 488 if (stats->next_timer_index() < 489 static_cast<int>(arraysize(kStatsCollectionTimesMs))) { 490 ScheduleTimer(stats); 491 } else { 492 RemoveTabLoadStats(stats->render_view_id()); 493 } 494 } 495 496 void LoadTimeStats::RecordHistograms(base::TimeDelta elapsed, 497 TabLoadStats* stats, 498 bool is_load_done) { 499 int timer_index = stats->next_timer_index(); 500 DCHECK(timer_index >= 0 && 501 timer_index < static_cast<int>(arraysize(kStatsCollectionTimesMs))); 502 503 if (elapsed.InMilliseconds() <= 0) 504 return; 505 506 base::TimeDelta total_cumulative; 507 for (int status = REQUEST_STATUS_CACHE_WAIT; 508 status <= REQUEST_STATUS_ACTIVE; 509 status++) { 510 total_cumulative += 511 stats->per_status_stats()[status].total_cumulative_time(); 512 } 513 514 for (int status = REQUEST_STATUS_CACHE_WAIT; 515 status <= REQUEST_STATUS_ACTIVE; 516 status++) { 517 TabLoadStats::PerStatusStats* status_stats = 518 &(stats->per_status_stats()[status]); 519 520 int64 fraction_percentage = 100 * 521 status_stats->total_time().InMilliseconds() / elapsed.InMilliseconds(); 522 DCHECK(fraction_percentage >= 0 && fraction_percentage <= 100); 523 if (is_load_done) { 524 histograms_[status][HISTOGRAM_FINAL_AGGREGATE][timer_index]->Add( 525 fraction_percentage); 526 } else { 527 histograms_[status][HISTOGRAM_INTERMEDIATE_AGGREGATE][timer_index]->Add( 528 fraction_percentage); 529 } 530 531 if (total_cumulative.InMilliseconds() > 0) { 532 fraction_percentage = 100 * 533 status_stats->total_cumulative_time().InMilliseconds() / 534 total_cumulative.InMilliseconds(); 535 DCHECK(fraction_percentage >= 0 && fraction_percentage <= 100); 536 if (is_load_done) { 537 histograms_[status][HISTOGRAM_FINAL_CUMULATIVE_PERCENTAGE] 538 [timer_index]->Add(fraction_percentage); 539 } else { 540 histograms_[status][HISTOGRAM_INTERMEDIATE_CUMULATIVE_PERCENTAGE] 541 [timer_index]->Add(fraction_percentage); 542 } 543 } 544 } 545 } 546 547 void LoadTimeStats::RegisterURLRequestContext( 548 const net::URLRequestContext* context, 549 ChromeURLRequestContext::ContextType type) { 550 if (type == ChromeURLRequestContext::CONTEXT_TYPE_MAIN) 551 main_request_contexts_.insert(context); 552 } 553 554 void LoadTimeStats::UnregisterURLRequestContext( 555 const net::URLRequestContext* context) { 556 main_request_contexts_.erase(context); 557 } 558 559 } // namespace chrome_browser_net 560