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/renderer/page_load_histograms.h" 6 7 #include <string> 8 9 #include "base/command_line.h" 10 #include "base/logging.h" 11 #include "base/metrics/field_trial.h" 12 #include "base/metrics/histogram.h" 13 #include "base/strings/utf_string_conversions.h" 14 #include "base/time/time.h" 15 #include "chrome/common/chrome_switches.h" 16 #include "chrome/renderer/chrome_content_renderer_client.h" 17 #include "content/public/common/content_constants.h" 18 #include "content/public/renderer/document_state.h" 19 #include "content/public/renderer/render_thread.h" 20 #include "content/public/renderer/render_view.h" 21 #include "extensions/common/url_pattern.h" 22 #include "third_party/WebKit/public/platform/WebURLRequest.h" 23 #include "third_party/WebKit/public/platform/WebURLResponse.h" 24 #include "third_party/WebKit/public/web/WebDocument.h" 25 #include "third_party/WebKit/public/web/WebFrame.h" 26 #include "third_party/WebKit/public/web/WebPerformance.h" 27 #include "third_party/WebKit/public/web/WebView.h" 28 #include "url/gurl.h" 29 30 using WebKit::WebDataSource; 31 using WebKit::WebFrame; 32 using WebKit::WebPerformance; 33 using WebKit::WebString; 34 using base::Time; 35 using base::TimeDelta; 36 using content::DocumentState; 37 38 const size_t kPLTCount = 100; 39 40 namespace { 41 42 TimeDelta kPLTMin() { 43 return TimeDelta::FromMilliseconds(10); 44 } 45 TimeDelta kPLTMax() { 46 return TimeDelta::FromMinutes(10); 47 } 48 49 #define PLT_HISTOGRAM(name, sample) \ 50 UMA_HISTOGRAM_CUSTOM_TIMES(name, sample, kPLTMin(), kPLTMax(), kPLTCount); 51 52 // In addition to PLT_HISTOGRAM, add the *_DataReductionProxy variant 53 // conditionally. This macro runs only in one thread. 54 #define PLT_HISTOGRAM_DRP(name, sample, data_reduction_proxy_was_used) \ 55 do { \ 56 static base::HistogramBase* counter(NULL); \ 57 static base::HistogramBase* drp_counter(NULL); \ 58 if (!counter) { \ 59 DCHECK(drp_counter == NULL); \ 60 counter = base::Histogram::FactoryTimeGet( \ 61 name, kPLTMin(), kPLTMax(), kPLTCount, \ 62 base::Histogram::kUmaTargetedHistogramFlag); \ 63 } \ 64 counter->AddTime(sample); \ 65 if (!data_reduction_proxy_was_used) break; \ 66 if (!drp_counter) { \ 67 drp_counter = base::Histogram::FactoryTimeGet( \ 68 std::string(name) + "_DataReductionProxy", \ 69 kPLTMin(), kPLTMax(), kPLTCount, \ 70 base::Histogram::kUmaTargetedHistogramFlag); \ 71 } \ 72 drp_counter->AddTime(sample); \ 73 } while (0) 74 75 // Returns the scheme type of the given URL if its type is one for which we 76 // dump page load histograms. Otherwise returns NULL. 77 URLPattern::SchemeMasks GetSupportedSchemeType(const GURL& url) { 78 if (url.SchemeIs("http")) 79 return URLPattern::SCHEME_HTTP; 80 else if (url.SchemeIs("https")) 81 return URLPattern::SCHEME_HTTPS; 82 return static_cast<URLPattern::SchemeMasks>(0); 83 } 84 85 // Returns true if the data reduction proxy was used. Note, this function will 86 // produce a false positive if a page is fetched using SPDY and using a proxy, 87 // and |kDatReductionProxyViaValue| is added to the Via header. 88 // TODO(bengr): Plumb the hostname of the proxy from |HttpNetworkTransaction| 89 // and check if it matches |SPDY_PROXY_AUTH_ORIGIN|. 90 bool DataReductionProxyWasUsed(WebFrame* frame) { 91 #if defined(SPDY_PROXY_AUTH_ORIGIN) 92 const char kViaHeaderName[] = "Via"; 93 const char kDatReductionProxyViaValue[] = "1.1 Chrome Compression Proxy"; 94 95 DocumentState* document_state = 96 DocumentState::FromDataSource(frame->dataSource()); 97 if (!document_state->was_fetched_via_proxy()) 98 return false; 99 100 std::string via_header(UTF16ToUTF8( 101 frame->dataSource()->response().httpHeaderField(kViaHeaderName))); 102 return via_header.find(kDatReductionProxyViaValue) != std::string::npos; 103 #endif 104 return false; 105 } 106 107 void DumpPerformanceTiming(const WebPerformance& performance, 108 DocumentState* document_state, 109 bool data_reduction_proxy_was_used) { 110 Time request = document_state->request_time(); 111 112 Time navigation_start = Time::FromDoubleT(performance.navigationStart()); 113 Time redirect_start = Time::FromDoubleT(performance.redirectStart()); 114 Time redirect_end = Time::FromDoubleT(performance.redirectEnd()); 115 Time fetch_start = Time::FromDoubleT(performance.fetchStart()); 116 Time domain_lookup_start = Time::FromDoubleT(performance.domainLookupStart()); 117 Time domain_lookup_end = Time::FromDoubleT(performance.domainLookupEnd()); 118 Time connect_start = Time::FromDoubleT(performance.connectStart()); 119 Time connect_end = Time::FromDoubleT(performance.connectEnd()); 120 Time request_start = Time::FromDoubleT(performance.requestStart()); 121 Time response_start = Time::FromDoubleT(performance.responseStart()); 122 Time response_end = Time::FromDoubleT(performance.responseEnd()); 123 Time dom_loading = Time::FromDoubleT(performance.domLoading()); 124 Time dom_interactive = Time::FromDoubleT(performance.domInteractive()); 125 Time dom_content_loaded_start = 126 Time::FromDoubleT(performance.domContentLoadedEventStart()); 127 Time dom_content_loaded_end = 128 Time::FromDoubleT(performance.domContentLoadedEventEnd()); 129 Time load_event_start = Time::FromDoubleT(performance.loadEventStart()); 130 Time load_event_end = Time::FromDoubleT(performance.loadEventEnd()); 131 Time begin = (request.is_null() ? navigation_start : request_start); 132 133 DCHECK(!navigation_start.is_null()); 134 135 // It is possible for a document to have navigation_start time, but no 136 // request_start. An example is doing a window.open, which synchronously 137 // loads "about:blank", then using document.write add a meta http-equiv 138 // refresh tag, which causes a navigation. In such case, we will arrive at 139 // this function with no request/response timing data and identical load 140 // start/end values. Avoid logging this case, as it doesn't add any 141 // meaningful information to the histogram. 142 if (request_start.is_null()) 143 return; 144 145 // TODO(dominich): Investigate conditions under which |load_event_start| and 146 // |load_event_end| may be NULL as in the non-PT_ case below. Examples in 147 // http://crbug.com/112006. 148 // DCHECK(!load_event_start.is_null()); 149 // DCHECK(!load_event_end.is_null()); 150 151 if (document_state->web_timing_histograms_recorded()) 152 return; 153 document_state->set_web_timing_histograms_recorded(true); 154 155 if (!redirect_start.is_null() && !redirect_end.is_null()) { 156 PLT_HISTOGRAM_DRP("PLT.NT_Redirect", redirect_end - redirect_start, 157 data_reduction_proxy_was_used); 158 PLT_HISTOGRAM_DRP( 159 "PLT.NT_DelayBeforeFetchRedirect", 160 (fetch_start - navigation_start) - (redirect_end - redirect_start), 161 data_reduction_proxy_was_used); 162 } else { 163 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeFetch", 164 fetch_start - navigation_start, 165 data_reduction_proxy_was_used); 166 } 167 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeDomainLookup", 168 domain_lookup_start - fetch_start, 169 data_reduction_proxy_was_used); 170 PLT_HISTOGRAM_DRP("PLT.NT_DomainLookup", 171 domain_lookup_end - domain_lookup_start, 172 data_reduction_proxy_was_used); 173 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeConnect", 174 connect_start - domain_lookup_end, 175 data_reduction_proxy_was_used); 176 PLT_HISTOGRAM_DRP("PLT.NT_Connect", connect_end - connect_start, 177 data_reduction_proxy_was_used); 178 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeRequest", 179 request_start - connect_end, 180 data_reduction_proxy_was_used); 181 PLT_HISTOGRAM_DRP("PLT.NT_Request", response_start - request_start, 182 data_reduction_proxy_was_used); 183 PLT_HISTOGRAM_DRP("PLT.NT_Response", response_end - response_start, 184 data_reduction_proxy_was_used); 185 186 if (!dom_loading.is_null()) { 187 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeDomLoading", 188 dom_loading - response_start, 189 data_reduction_proxy_was_used); 190 } 191 if (!dom_interactive.is_null() && !dom_loading.is_null()) { 192 PLT_HISTOGRAM_DRP("PLT.NT_DomLoading", 193 dom_interactive - dom_loading, 194 data_reduction_proxy_was_used); 195 } 196 if (!dom_content_loaded_start.is_null() && !dom_interactive.is_null()) { 197 PLT_HISTOGRAM_DRP("PLT.NT_DomInteractive", 198 dom_content_loaded_start - dom_interactive, 199 data_reduction_proxy_was_used); 200 } 201 if (!dom_content_loaded_start.is_null() && 202 !dom_content_loaded_end.is_null() ) { 203 PLT_HISTOGRAM_DRP("PLT.NT_DomContentLoaded", 204 dom_content_loaded_end - dom_content_loaded_start, 205 data_reduction_proxy_was_used); 206 } 207 if (!dom_content_loaded_end.is_null() && !load_event_start.is_null()) { 208 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeLoadEvent", 209 load_event_start - dom_content_loaded_end, 210 data_reduction_proxy_was_used); 211 } 212 213 // TODO(simonjam): There is no way to distinguish between abandonment and 214 // intentional Javascript navigation before the load event fires. 215 // TODO(dominich): Load type breakdown 216 if (!load_event_start.is_null()) { 217 PLT_HISTOGRAM("PLT.PT_BeginToFinishDoc", load_event_start - begin); 218 PLT_HISTOGRAM("PLT.PT_CommitToFinishDoc", 219 load_event_start - response_start); 220 if (data_reduction_proxy_was_used) { 221 PLT_HISTOGRAM("PLT.PT_BeginToFinishDoc_DataReductionProxy", 222 load_event_start - begin); 223 PLT_HISTOGRAM("PLT.PT_CommitToFinishDoc_DataReductionProxy", 224 load_event_start - response_start); 225 } 226 } 227 if (!load_event_end.is_null()) { 228 PLT_HISTOGRAM("PLT.PT_BeginToFinish", load_event_end - begin); 229 PLT_HISTOGRAM("PLT.PT_CommitToFinish", load_event_end - response_start); 230 PLT_HISTOGRAM("PLT.PT_RequestToFinish", load_event_end - navigation_start); 231 PLT_HISTOGRAM("PLT.PT_StartToFinish", load_event_end - request_start); 232 if (data_reduction_proxy_was_used) { 233 PLT_HISTOGRAM("PLT.PT_BeginToFinish_DataReductionProxy", 234 load_event_end - begin); 235 PLT_HISTOGRAM("PLT.PT_CommitToFinish_DataReductionProxy", 236 load_event_end - response_start); 237 PLT_HISTOGRAM("PLT.PT_RequestToFinish_DataReductionProxy", 238 load_event_end - navigation_start); 239 PLT_HISTOGRAM("PLT.PT_StartToFinish_DataReductionProxy", 240 load_event_end - request_start); 241 } 242 } 243 if (!load_event_start.is_null() && !load_event_end.is_null()) { 244 PLT_HISTOGRAM("PLT.PT_FinishDocToFinish", 245 load_event_end - load_event_start); 246 PLT_HISTOGRAM_DRP("PLT.NT_LoadEvent", 247 load_event_end - load_event_start, 248 data_reduction_proxy_was_used); 249 250 if (data_reduction_proxy_was_used) { 251 PLT_HISTOGRAM("PLT.PT_FinishDocToFinish_DataReductionProxy", 252 load_event_end - load_event_start); 253 } 254 } 255 PLT_HISTOGRAM("PLT.PT_BeginToCommit", response_start - begin); 256 PLT_HISTOGRAM("PLT.PT_RequestToStart", request_start - navigation_start); 257 PLT_HISTOGRAM("PLT.PT_StartToCommit", response_start - request_start); 258 if (data_reduction_proxy_was_used) { 259 PLT_HISTOGRAM("PLT.PT_BeginToCommit_DataReductionProxy", 260 response_start - begin); 261 PLT_HISTOGRAM("PLT.PT_RequestToStart_DataReductionProxy", 262 request_start - navigation_start); 263 PLT_HISTOGRAM("PLT.PT_StartToCommit_DataReductionProxy", 264 response_start - request_start); 265 } 266 } 267 268 enum MissingStartType { 269 START_MISSING = 0x1, 270 COMMIT_MISSING = 0x2, 271 NAV_START_MISSING = 0x4, 272 MISSING_START_TYPE_MAX = 0x8 273 }; 274 275 enum AbandonType { 276 FINISH_DOC_MISSING = 0x1, 277 FINISH_ALL_LOADS_MISSING = 0x2, 278 LOAD_EVENT_START_MISSING = 0x4, 279 LOAD_EVENT_END_MISSING = 0x8, 280 ABANDON_TYPE_MAX = 0x10 281 }; 282 283 } // namespace 284 285 PageLoadHistograms::PageLoadHistograms(content::RenderView* render_view) 286 : content::RenderViewObserver(render_view), 287 cross_origin_access_count_(0), 288 same_origin_access_count_(0) { 289 } 290 291 void PageLoadHistograms::Dump(WebFrame* frame) { 292 // We only dump histograms for main frames. 293 // In the future, it may be interesting to tag subframes and dump them too. 294 if (!frame || frame->parent()) 295 return; 296 297 // Only dump for supported schemes. 298 URLPattern::SchemeMasks scheme_type = 299 GetSupportedSchemeType(frame->document().url()); 300 if (scheme_type == 0) 301 return; 302 303 // Ignore multipart requests. 304 if (frame->dataSource()->response().isMultipartPayload()) 305 return; 306 307 DocumentState* document_state = 308 DocumentState::FromDataSource(frame->dataSource()); 309 310 bool data_reduction_proxy_was_used = DataReductionProxyWasUsed(frame); 311 312 // Times based on the Web Timing metrics. 313 // http://www.w3.org/TR/navigation-timing/ 314 // TODO(tonyg, jar): We are in the process of vetting these metrics against 315 // the existing ones. Once we understand any differences, we will standardize 316 // on a single set of metrics. 317 DumpPerformanceTiming(frame->performance(), document_state, 318 data_reduction_proxy_was_used); 319 320 // If we've already dumped, do nothing. 321 // This simple bool works because we only dump for the main frame. 322 if (document_state->load_histograms_recorded()) 323 return; 324 325 // Collect measurement times. 326 Time start = document_state->start_load_time(); 327 Time commit = document_state->commit_load_time(); 328 329 // TODO(tonyg, jar): Start can be missing after an in-document navigation and 330 // possibly other cases like a very premature abandonment of the page. 331 // The PLT.MissingStart histogram should help us troubleshoot and then we can 332 // remove this. 333 Time navigation_start = 334 Time::FromDoubleT(frame->performance().navigationStart()); 335 int missing_start_type = 0; 336 missing_start_type |= start.is_null() ? START_MISSING : 0; 337 missing_start_type |= commit.is_null() ? COMMIT_MISSING : 0; 338 missing_start_type |= navigation_start.is_null() ? NAV_START_MISSING : 0; 339 UMA_HISTOGRAM_ENUMERATION("PLT.MissingStart", missing_start_type, 340 MISSING_START_TYPE_MAX); 341 if (missing_start_type) 342 return; 343 344 // We properly handle null values for the next 3 variables. 345 Time request = document_state->request_time(); 346 Time first_paint = document_state->first_paint_time(); 347 Time first_paint_after_load = document_state->first_paint_after_load_time(); 348 Time finish_doc = document_state->finish_document_load_time(); 349 Time finish_all_loads = document_state->finish_load_time(); 350 351 // TODO(tonyg, jar): We suspect a bug in abandonment counting, this temporary 352 // histogram should help us to troubleshoot. 353 Time load_event_start = 354 Time::FromDoubleT(frame->performance().loadEventStart()); 355 Time load_event_end = Time::FromDoubleT(frame->performance().loadEventEnd()); 356 int abandon_type = 0; 357 abandon_type |= finish_doc.is_null() ? FINISH_DOC_MISSING : 0; 358 abandon_type |= finish_all_loads.is_null() ? FINISH_ALL_LOADS_MISSING : 0; 359 abandon_type |= load_event_start.is_null() ? LOAD_EVENT_START_MISSING : 0; 360 abandon_type |= load_event_end.is_null() ? LOAD_EVENT_END_MISSING : 0; 361 UMA_HISTOGRAM_ENUMERATION("PLT.AbandonType", abandon_type, ABANDON_TYPE_MAX); 362 363 // Handle case where user hits "stop" or "back" before loading completely. 364 bool abandoned_page = finish_doc.is_null(); 365 if (abandoned_page) { 366 finish_doc = Time::Now(); 367 document_state->set_finish_document_load_time(finish_doc); 368 } 369 370 // TODO(jar): We should really discriminate the definition of "abandon" more 371 // finely. We should have: 372 // abandon_before_document_loaded 373 // abandon_before_onload_fired 374 375 if (finish_all_loads.is_null()) { 376 finish_all_loads = Time::Now(); 377 document_state->set_finish_load_time(finish_all_loads); 378 } else { 379 DCHECK(!abandoned_page); // How can the doc have finished but not the page? 380 if (abandoned_page) 381 return; // Don't try to record a stat which is broken. 382 } 383 384 document_state->set_load_histograms_recorded(true); 385 386 // Note: Client side redirects will have no request time. 387 Time begin = request.is_null() ? start : request; 388 TimeDelta begin_to_finish_doc = finish_doc - begin; 389 TimeDelta begin_to_finish_all_loads = finish_all_loads - begin; 390 TimeDelta start_to_finish_all_loads = finish_all_loads - start; 391 TimeDelta start_to_commit = commit - start; 392 393 DocumentState::LoadType load_type = document_state->load_type(); 394 395 // The above code sanitized all values of times, in preparation for creating 396 // actual histograms. The remainder of this code could be run at destructor 397 // time for the document_state, since all data is intact. 398 399 // Aggregate PLT data across all link types. 400 UMA_HISTOGRAM_ENUMERATION("PLT.Abandoned", abandoned_page ? 1 : 0, 2); 401 UMA_HISTOGRAM_ENUMERATION("PLT.LoadType", load_type, 402 DocumentState::kLoadTypeMax); 403 PLT_HISTOGRAM("PLT.StartToCommit", start_to_commit); 404 PLT_HISTOGRAM("PLT.CommitToFinishDoc", finish_doc - commit); 405 PLT_HISTOGRAM("PLT.FinishDocToFinish", finish_all_loads - finish_doc); 406 PLT_HISTOGRAM("PLT.BeginToCommit", commit - begin); 407 PLT_HISTOGRAM("PLT.StartToFinish", start_to_finish_all_loads); 408 if (!request.is_null()) { 409 PLT_HISTOGRAM("PLT.RequestToStart", start - request); 410 PLT_HISTOGRAM("PLT.RequestToFinish", finish_all_loads - request); 411 } 412 PLT_HISTOGRAM("PLT.CommitToFinish", finish_all_loads - commit); 413 414 scoped_ptr<TimeDelta> begin_to_first_paint; 415 scoped_ptr<TimeDelta> commit_to_first_paint; 416 if (!first_paint.is_null()) { 417 // 'first_paint' can be before 'begin' for an unknown reason. 418 // See bug http://crbug.com/125273 for details. 419 if (begin <= first_paint) { 420 begin_to_first_paint.reset(new TimeDelta(first_paint - begin)); 421 PLT_HISTOGRAM("PLT.BeginToFirstPaint", *begin_to_first_paint); 422 } 423 DCHECK(commit <= first_paint); 424 commit_to_first_paint.reset(new TimeDelta(first_paint - commit)); 425 PLT_HISTOGRAM("PLT.CommitToFirstPaint", *commit_to_first_paint); 426 } 427 if (!first_paint_after_load.is_null()) { 428 // 'first_paint_after_load' can be before 'begin' for an unknown reason. 429 // See bug http://crbug.com/125273 for details. 430 if (begin <= first_paint_after_load) { 431 PLT_HISTOGRAM("PLT.BeginToFirstPaintAfterLoad", 432 first_paint_after_load - begin); 433 } 434 DCHECK(commit <= first_paint_after_load); 435 PLT_HISTOGRAM("PLT.CommitToFirstPaintAfterLoad", 436 first_paint_after_load - commit); 437 DCHECK(finish_all_loads <= first_paint_after_load); 438 PLT_HISTOGRAM("PLT.FinishToFirstPaintAfterLoad", 439 first_paint_after_load - finish_all_loads); 440 } 441 PLT_HISTOGRAM("PLT.BeginToFinishDoc", begin_to_finish_doc); 442 PLT_HISTOGRAM("PLT.BeginToFinish", begin_to_finish_all_loads); 443 444 // Load type related histograms. 445 switch (load_type) { 446 case DocumentState::UNDEFINED_LOAD: 447 PLT_HISTOGRAM("PLT.BeginToFinishDoc_UndefLoad", begin_to_finish_doc); 448 PLT_HISTOGRAM("PLT.BeginToFinish_UndefLoad", begin_to_finish_all_loads); 449 break; 450 case DocumentState::RELOAD: 451 PLT_HISTOGRAM("PLT.BeginToFinishDoc_Reload", begin_to_finish_doc); 452 PLT_HISTOGRAM("PLT.BeginToFinish_Reload", begin_to_finish_all_loads); 453 break; 454 case DocumentState::HISTORY_LOAD: 455 PLT_HISTOGRAM("PLT.BeginToFinishDoc_HistoryLoad", begin_to_finish_doc); 456 PLT_HISTOGRAM("PLT.BeginToFinish_HistoryLoad", begin_to_finish_all_loads); 457 break; 458 case DocumentState::NORMAL_LOAD: 459 PLT_HISTOGRAM("PLT.BeginToFinishDoc_NormalLoad", begin_to_finish_doc); 460 PLT_HISTOGRAM("PLT.BeginToFinish_NormalLoad", begin_to_finish_all_loads); 461 break; 462 case DocumentState::LINK_LOAD_NORMAL: 463 PLT_HISTOGRAM("PLT.BeginToFinishDoc_LinkLoadNormal", 464 begin_to_finish_doc); 465 PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadNormal", 466 begin_to_finish_all_loads); 467 break; 468 case DocumentState::LINK_LOAD_RELOAD: 469 PLT_HISTOGRAM("PLT.BeginToFinishDoc_LinkLoadReload", 470 begin_to_finish_doc); 471 PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadReload", 472 begin_to_finish_all_loads); 473 break; 474 case DocumentState::LINK_LOAD_CACHE_STALE_OK: 475 PLT_HISTOGRAM("PLT.BeginToFinishDoc_LinkLoadStaleOk", 476 begin_to_finish_doc); 477 PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadStaleOk", 478 begin_to_finish_all_loads); 479 break; 480 case DocumentState::LINK_LOAD_CACHE_ONLY: 481 PLT_HISTOGRAM("PLT.BeginToFinishDoc_LinkLoadCacheOnly", 482 begin_to_finish_doc); 483 PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadCacheOnly", 484 begin_to_finish_all_loads); 485 break; 486 default: 487 break; 488 } 489 490 if (data_reduction_proxy_was_used) { 491 UMA_HISTOGRAM_ENUMERATION( 492 "PLT.Abandoned_SpdyProxy", abandoned_page ? 1 : 0, 2); 493 PLT_HISTOGRAM("PLT.BeginToFinishDoc_SpdyProxy", begin_to_finish_doc); 494 PLT_HISTOGRAM("PLT.BeginToFinish_SpdyProxy", begin_to_finish_all_loads); 495 } 496 497 if (document_state->was_prefetcher()) { 498 PLT_HISTOGRAM("PLT.BeginToFinishDoc_ContentPrefetcher", 499 begin_to_finish_doc); 500 PLT_HISTOGRAM("PLT.BeginToFinish_ContentPrefetcher", 501 begin_to_finish_all_loads); 502 } 503 if (document_state->was_referred_by_prefetcher()) { 504 PLT_HISTOGRAM("PLT.BeginToFinishDoc_ContentPrefetcherReferrer", 505 begin_to_finish_doc); 506 PLT_HISTOGRAM("PLT.BeginToFinish_ContentPrefetcherReferrer", 507 begin_to_finish_all_loads); 508 } 509 if (document_state->was_after_preconnect_request()) { 510 PLT_HISTOGRAM("PLT.BeginToFinishDoc_AfterPreconnectRequest", 511 begin_to_finish_doc); 512 PLT_HISTOGRAM("PLT.BeginToFinish_AfterPreconnectRequest", 513 begin_to_finish_all_loads); 514 } 515 516 // TODO(mpcomplete): remove the extension-related histograms after we collect 517 // enough data. http://crbug.com/100411 518 const bool use_adblock_histogram = 519 chrome::ChromeContentRendererClient::IsAdblockInstalled(); 520 if (use_adblock_histogram) { 521 UMA_HISTOGRAM_ENUMERATION( 522 "PLT.Abandoned_ExtensionAdblock", 523 abandoned_page ? 1 : 0, 2); 524 switch (load_type) { 525 case DocumentState::NORMAL_LOAD: 526 PLT_HISTOGRAM( 527 "PLT.BeginToFinish_NormalLoad_ExtensionAdblock", 528 begin_to_finish_all_loads); 529 break; 530 case DocumentState::LINK_LOAD_NORMAL: 531 PLT_HISTOGRAM( 532 "PLT.BeginToFinish_LinkLoadNormal_ExtensionAdblock", 533 begin_to_finish_all_loads); 534 break; 535 case DocumentState::LINK_LOAD_RELOAD: 536 PLT_HISTOGRAM( 537 "PLT.BeginToFinish_LinkLoadReload_ExtensionAdblock", 538 begin_to_finish_all_loads); 539 break; 540 case DocumentState::LINK_LOAD_CACHE_STALE_OK: 541 PLT_HISTOGRAM( 542 "PLT.BeginToFinish_LinkLoadStaleOk_ExtensionAdblock", 543 begin_to_finish_all_loads); 544 break; 545 default: 546 break; 547 } 548 } 549 550 const bool use_adblockplus_histogram = 551 chrome::ChromeContentRendererClient::IsAdblockPlusInstalled(); 552 if (use_adblockplus_histogram) { 553 UMA_HISTOGRAM_ENUMERATION( 554 "PLT.Abandoned_ExtensionAdblockPlus", 555 abandoned_page ? 1 : 0, 2); 556 switch (load_type) { 557 case DocumentState::NORMAL_LOAD: 558 PLT_HISTOGRAM( 559 "PLT.BeginToFinish_NormalLoad_ExtensionAdblockPlus", 560 begin_to_finish_all_loads); 561 break; 562 case DocumentState::LINK_LOAD_NORMAL: 563 PLT_HISTOGRAM( 564 "PLT.BeginToFinish_LinkLoadNormal_ExtensionAdblockPlus", 565 begin_to_finish_all_loads); 566 break; 567 case DocumentState::LINK_LOAD_RELOAD: 568 PLT_HISTOGRAM( 569 "PLT.BeginToFinish_LinkLoadReload_ExtensionAdblockPlus", 570 begin_to_finish_all_loads); 571 break; 572 case DocumentState::LINK_LOAD_CACHE_STALE_OK: 573 PLT_HISTOGRAM( 574 "PLT.BeginToFinish_LinkLoadStaleOk_ExtensionAdblockPlus", 575 begin_to_finish_all_loads); 576 break; 577 default: 578 break; 579 } 580 } 581 582 const bool use_webrequest_adblock_histogram = 583 chrome::ChromeContentRendererClient::IsAdblockWithWebRequestInstalled(); 584 if (use_webrequest_adblock_histogram) { 585 UMA_HISTOGRAM_ENUMERATION( 586 "PLT.Abandoned_ExtensionWebRequestAdblock", 587 abandoned_page ? 1 : 0, 2); 588 switch (load_type) { 589 case DocumentState::NORMAL_LOAD: 590 PLT_HISTOGRAM( 591 "PLT.BeginToFinish_NormalLoad_ExtensionWebRequestAdblock", 592 begin_to_finish_all_loads); 593 break; 594 case DocumentState::LINK_LOAD_NORMAL: 595 PLT_HISTOGRAM( 596 "PLT.BeginToFinish_LinkLoadNormal_ExtensionWebRequestAdblock", 597 begin_to_finish_all_loads); 598 break; 599 case DocumentState::LINK_LOAD_RELOAD: 600 PLT_HISTOGRAM( 601 "PLT.BeginToFinish_LinkLoadReload_ExtensionWebRequestAdblock", 602 begin_to_finish_all_loads); 603 break; 604 case DocumentState::LINK_LOAD_CACHE_STALE_OK: 605 PLT_HISTOGRAM( 606 "PLT.BeginToFinish_LinkLoadStaleOk_ExtensionWebRequestAdblock", 607 begin_to_finish_all_loads); 608 break; 609 default: 610 break; 611 } 612 } 613 614 const bool use_webrequest_adblockplus_histogram = 615 chrome::ChromeContentRendererClient:: 616 IsAdblockPlusWithWebRequestInstalled(); 617 if (use_webrequest_adblockplus_histogram) { 618 UMA_HISTOGRAM_ENUMERATION( 619 "PLT.Abandoned_ExtensionWebRequestAdblockPlus", 620 abandoned_page ? 1 : 0, 2); 621 switch (load_type) { 622 case DocumentState::NORMAL_LOAD: 623 PLT_HISTOGRAM( 624 "PLT.BeginToFinish_NormalLoad_ExtensionWebRequestAdblockPlus", 625 begin_to_finish_all_loads); 626 break; 627 case DocumentState::LINK_LOAD_NORMAL: 628 PLT_HISTOGRAM( 629 "PLT.BeginToFinish_LinkLoadNormal_ExtensionWebRequestAdblockPlus", 630 begin_to_finish_all_loads); 631 break; 632 case DocumentState::LINK_LOAD_RELOAD: 633 PLT_HISTOGRAM( 634 "PLT.BeginToFinish_LinkLoadReload_ExtensionWebRequestAdblockPlus", 635 begin_to_finish_all_loads); 636 break; 637 case DocumentState::LINK_LOAD_CACHE_STALE_OK: 638 PLT_HISTOGRAM( 639 "PLT.BeginToFinish_LinkLoadStaleOk_ExtensionWebRequestAdblockPlus", 640 begin_to_finish_all_loads); 641 break; 642 default: 643 break; 644 } 645 } 646 647 const bool use_webrequest_other_histogram = 648 chrome::ChromeContentRendererClient:: 649 IsOtherExtensionWithWebRequestInstalled(); 650 if (use_webrequest_other_histogram) { 651 UMA_HISTOGRAM_ENUMERATION( 652 "PLT.Abandoned_ExtensionWebRequestOther", 653 abandoned_page ? 1 : 0, 2); 654 switch (load_type) { 655 case DocumentState::NORMAL_LOAD: 656 PLT_HISTOGRAM( 657 "PLT.BeginToFinish_NormalLoad_ExtensionWebRequestOther", 658 begin_to_finish_all_loads); 659 break; 660 case DocumentState::LINK_LOAD_NORMAL: 661 PLT_HISTOGRAM( 662 "PLT.BeginToFinish_LinkLoadNormal_ExtensionWebRequestOther", 663 begin_to_finish_all_loads); 664 break; 665 case DocumentState::LINK_LOAD_RELOAD: 666 PLT_HISTOGRAM( 667 "PLT.BeginToFinish_LinkLoadReload_ExtensionWebRequestOther", 668 begin_to_finish_all_loads); 669 break; 670 case DocumentState::LINK_LOAD_CACHE_STALE_OK: 671 PLT_HISTOGRAM( 672 "PLT.BeginToFinish_LinkLoadStaleOk_ExtensionWebRequestOther", 673 begin_to_finish_all_loads); 674 break; 675 default: 676 break; 677 } 678 } 679 680 // Record SpdyCwnd results. 681 if (document_state->was_fetched_via_spdy()) { 682 switch (load_type) { 683 case DocumentState::LINK_LOAD_NORMAL: 684 PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadNormal_cwndDynamic", 685 begin_to_finish_all_loads); 686 PLT_HISTOGRAM("PLT.StartToFinish_LinkLoadNormal_cwndDynamic", 687 start_to_finish_all_loads); 688 PLT_HISTOGRAM("PLT.StartToCommit_LinkLoadNormal_cwndDynamic", 689 start_to_commit); 690 break; 691 case DocumentState::NORMAL_LOAD: 692 PLT_HISTOGRAM("PLT.BeginToFinish_NormalLoad_cwndDynamic", 693 begin_to_finish_all_loads); 694 PLT_HISTOGRAM("PLT.StartToFinish_NormalLoad_cwndDynamic", 695 start_to_finish_all_loads); 696 PLT_HISTOGRAM("PLT.StartToCommit_NormalLoad_cwndDynamic", 697 start_to_commit); 698 break; 699 default: 700 break; 701 } 702 } 703 704 // Record page load time and abandonment rates for proxy cases. 705 if (document_state->was_fetched_via_proxy()) { 706 if (scheme_type == URLPattern::SCHEME_HTTPS) { 707 PLT_HISTOGRAM("PLT.StartToFinish.Proxy.https", start_to_finish_all_loads); 708 UMA_HISTOGRAM_ENUMERATION("PLT.Abandoned.Proxy.https", 709 abandoned_page ? 1 : 0, 2); 710 } else { 711 DCHECK(scheme_type == URLPattern::SCHEME_HTTP); 712 PLT_HISTOGRAM("PLT.StartToFinish.Proxy.http", start_to_finish_all_loads); 713 UMA_HISTOGRAM_ENUMERATION("PLT.Abandoned.Proxy.http", 714 abandoned_page ? 1 : 0, 2); 715 } 716 } else { 717 if (scheme_type == URLPattern::SCHEME_HTTPS) { 718 PLT_HISTOGRAM("PLT.StartToFinish.NoProxy.https", 719 start_to_finish_all_loads); 720 UMA_HISTOGRAM_ENUMERATION("PLT.Abandoned.NoProxy.https", 721 abandoned_page ? 1 : 0, 2); 722 } else { 723 DCHECK(scheme_type == URLPattern::SCHEME_HTTP); 724 PLT_HISTOGRAM("PLT.StartToFinish.NoProxy.http", 725 start_to_finish_all_loads); 726 UMA_HISTOGRAM_ENUMERATION("PLT.Abandoned.NoProxy.http", 727 abandoned_page ? 1 : 0, 2); 728 } 729 } 730 731 // Histograms to determine if disabling overlapped TCP reads 732 // has an impact on PLT. 733 static const bool use_overlapped_read_histogram = 734 base::FieldTrialList::TrialExists("OverlappedReadImpact"); 735 if (use_overlapped_read_histogram) { 736 UMA_HISTOGRAM_ENUMERATION( 737 base::FieldTrial::MakeName("PLT.Abandoned", "OverlappedReadImpact"), 738 abandoned_page ? 1 : 0, 2); 739 UMA_HISTOGRAM_ENUMERATION( 740 base::FieldTrial::MakeName("PLT.LoadType", "OverlappedReadImpact"), 741 load_type, DocumentState::kLoadTypeMax); 742 switch (load_type) { 743 case DocumentState::NORMAL_LOAD: 744 PLT_HISTOGRAM(base::FieldTrial::MakeName( 745 "PLT.BeginToFinish_NormalLoad", "OverlappedReadImpact"), 746 begin_to_finish_all_loads); 747 break; 748 case DocumentState::LINK_LOAD_NORMAL: 749 PLT_HISTOGRAM(base::FieldTrial::MakeName( 750 "PLT.BeginToFinish_LinkLoadNormal", "OverlappedReadImpact"), 751 begin_to_finish_all_loads); 752 break; 753 case DocumentState::LINK_LOAD_RELOAD: 754 PLT_HISTOGRAM(base::FieldTrial::MakeName( 755 "PLT.BeginToFinish_LinkLoadReload", "OverlappedReadImpact"), 756 begin_to_finish_all_loads); 757 break; 758 case DocumentState::LINK_LOAD_CACHE_STALE_OK: 759 PLT_HISTOGRAM(base::FieldTrial::MakeName( 760 "PLT.BeginToFinish_LinkLoadStaleOk", "OverlappedReadImpact"), 761 begin_to_finish_all_loads); 762 break; 763 default: 764 break; 765 } 766 } 767 768 // Site isolation metrics. 769 UMA_HISTOGRAM_COUNTS("SiteIsolation.PageLoadsWithCrossSiteFrameAccess", 770 cross_origin_access_count_); 771 UMA_HISTOGRAM_COUNTS("SiteIsolation.PageLoadsWithSameSiteFrameAccess", 772 same_origin_access_count_); 773 774 // Log the PLT to the info log. 775 LogPageLoadTime(document_state, frame->dataSource()); 776 777 // Since there are currently no guarantees that renderer histograms will be 778 // sent to the browser, we initiate a PostTask here to be sure that we send 779 // the histograms we generated. Without this call, pages that don't have an 780 // on-close-handler might generate data that is lost when the renderer is 781 // shutdown abruptly (perchance because the user closed the tab). 782 // TODO(jar) BUG=33233: This needs to be moved to a PostDelayedTask, and it 783 // should post when the onload is complete, so that it doesn't interfere with 784 // the next load. 785 content::RenderThread::Get()->UpdateHistograms( 786 content::kHistogramSynchronizerReservedSequenceNumber); 787 } 788 789 void PageLoadHistograms::ResetCrossFramePropertyAccess() { 790 cross_origin_access_count_ = 0; 791 same_origin_access_count_ = 0; 792 } 793 794 void PageLoadHistograms::FrameWillClose(WebFrame* frame) { 795 Dump(frame); 796 } 797 798 void PageLoadHistograms::ClosePage() { 799 // TODO(davemoore) This code should be removed once willClose() gets 800 // called when a page is destroyed. page_load_histograms_.Dump() is safe 801 // to call multiple times for the same frame, but it will simplify things. 802 Dump(render_view()->GetWebView()->mainFrame()); 803 ResetCrossFramePropertyAccess(); 804 } 805 806 void PageLoadHistograms::LogPageLoadTime(const DocumentState* document_state, 807 const WebDataSource* ds) const { 808 // Because this function gets called on every page load, 809 // take extra care to optimize it away if logging is turned off. 810 if (logging::LOG_INFO < logging::GetMinLogLevel()) 811 return; 812 813 DCHECK(document_state); 814 DCHECK(ds); 815 GURL url(ds->request().url()); 816 Time start = document_state->start_load_time(); 817 Time finish = document_state->finish_load_time(); 818 // TODO(mbelshe): should we log more stats? 819 VLOG(1) << "PLT: " << (finish - start).InMilliseconds() << "ms " 820 << url.spec(); 821 } 822
