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