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 37using blink::WebDataSource; 38using blink::WebFrame; 39using blink::WebPerformance; 40using blink::WebString; 41using base::Time; 42using base::TimeDelta; 43using content::DocumentState; 44 45const size_t kPLTCount = 100; 46 47namespace { 48 49// ID indicating that no GWS-Chrome joint experiment is active. 50const 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. 54const int kMaxExperimentID = 20; 55 56TimeDelta kPLTMin() { 57 return TimeDelta::FromMilliseconds(10); 58} 59TimeDelta 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. 66void 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. 77void 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. 136URLPattern::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. 146bool 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|. 164bool 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( 181 response_headers.get(), NULL); 182} 183 184// Returns true if the provided URL is a referrer string that came from 185// a Google Web Search results page. This is a little non-deterministic 186// because desktop and mobile websearch differ and sometimes just provide 187// http://www.google.com/ as the referrer. In the case of /url we can be sure 188// that it came from websearch but we will be generous and allow for cases 189// where a non-Google URL was provided a bare Google URL as a referrer. 190// The domain validation matches the code used by the prerenderer for similar 191// purposes. 192// TODO(pmeenan): Remove the fuzzy logic when the referrer is reliable 193bool IsFromGoogleSearchResult(const GURL& url, const GURL& referrer) { 194 if (!StartsWithASCII(referrer.host(), "www.google.", true)) 195 return false; 196 if (StartsWithASCII(referrer.path(), "/url", true)) 197 return true; 198 bool is_possible_search_referrer = 199 referrer.path().empty() || 200 referrer.path() == "/" || 201 StartsWithASCII(referrer.path(), "/search", true) || 202 StartsWithASCII(referrer.path(), "/webhp", true); 203 if (is_possible_search_referrer && 204 !StartsWithASCII(url.host(), "www.google", true)) 205 return true; 206 return false; 207} 208 209// Extracts a Google Web Search and Chrome joint experiment ID from a referrer 210// that came from a Google Web Search results page. An experiment ID is embedded 211// in a query string as a "gcjeid=" parameter value. 212int GetQueryStringBasedExperiment(const GURL& referrer) { 213 std::string value; 214 if (!net::GetValueForKeyInQuery(referrer, "gcjeid", &value)) 215 return kNoExperiment; 216 217 int experiment_id; 218 if (!base::StringToInt(value, &experiment_id)) 219 return kNoExperiment; 220 if (0 < experiment_id && experiment_id <= kMaxExperimentID) 221 return experiment_id; 222 return kNoExperiment; 223} 224 225void DumpHistograms(const WebPerformance& performance, 226 DocumentState* document_state, 227 bool data_reduction_proxy_was_used, 228 bool came_from_websearch, 229 int websearch_chrome_joint_experiment_id, 230 bool is_preview) { 231 // This function records new histograms based on the Navigation Timing 232 // records. As such, the histograms should not depend on the deprecated timing 233 // information collected in DocumentState. However, here for some reason we 234 // check if document_state->request_time() is null. TODO(ppi): find out why 235 // and remove DocumentState from the parameter list. 236 Time request = document_state->request_time(); 237 238 Time navigation_start = Time::FromDoubleT(performance.navigationStart()); 239 Time redirect_start = Time::FromDoubleT(performance.redirectStart()); 240 Time redirect_end = Time::FromDoubleT(performance.redirectEnd()); 241 Time fetch_start = Time::FromDoubleT(performance.fetchStart()); 242 Time domain_lookup_start = Time::FromDoubleT(performance.domainLookupStart()); 243 Time domain_lookup_end = Time::FromDoubleT(performance.domainLookupEnd()); 244 Time connect_start = Time::FromDoubleT(performance.connectStart()); 245 Time connect_end = Time::FromDoubleT(performance.connectEnd()); 246 Time request_start = Time::FromDoubleT(performance.requestStart()); 247 Time response_start = Time::FromDoubleT(performance.responseStart()); 248 Time response_end = Time::FromDoubleT(performance.responseEnd()); 249 Time dom_loading = Time::FromDoubleT(performance.domLoading()); 250 Time dom_interactive = Time::FromDoubleT(performance.domInteractive()); 251 Time dom_content_loaded_start = 252 Time::FromDoubleT(performance.domContentLoadedEventStart()); 253 Time dom_content_loaded_end = 254 Time::FromDoubleT(performance.domContentLoadedEventEnd()); 255 Time load_event_start = Time::FromDoubleT(performance.loadEventStart()); 256 Time load_event_end = Time::FromDoubleT(performance.loadEventEnd()); 257 Time begin = (request.is_null() ? navigation_start : request_start); 258 259 DCHECK(!navigation_start.is_null()); 260 261 // It is possible for a document to have navigation_start time, but no 262 // request_start. An example is doing a window.open, which synchronously 263 // loads "about:blank", then using document.write add a meta http-equiv 264 // refresh tag, which causes a navigation. In such case, we will arrive at 265 // this function with no request/response timing data and identical load 266 // start/end values. Avoid logging this case, as it doesn't add any 267 // meaningful information to the histogram. 268 if (request_start.is_null()) 269 return; 270 271 // TODO(dominich): Investigate conditions under which |load_event_start| and 272 // |load_event_end| may be NULL as in the non-PT_ case below. Examples in 273 // http://crbug.com/112006. 274 // DCHECK(!load_event_start.is_null()); 275 // DCHECK(!load_event_end.is_null()); 276 277 if (document_state->web_timing_histograms_recorded()) 278 return; 279 document_state->set_web_timing_histograms_recorded(true); 280 281 if (!redirect_start.is_null() && !redirect_end.is_null()) { 282 PLT_HISTOGRAM_DRP("PLT.NT_Redirect", redirect_end - redirect_start, 283 data_reduction_proxy_was_used); 284 PLT_HISTOGRAM_DRP( 285 "PLT.NT_DelayBeforeFetchRedirect", 286 (fetch_start - navigation_start) - (redirect_end - redirect_start), 287 data_reduction_proxy_was_used); 288 } else { 289 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeFetch", 290 fetch_start - navigation_start, 291 data_reduction_proxy_was_used); 292 } 293 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeDomainLookup", 294 domain_lookup_start - fetch_start, 295 data_reduction_proxy_was_used); 296 PLT_HISTOGRAM_DRP("PLT.NT_DomainLookup", 297 domain_lookup_end - domain_lookup_start, 298 data_reduction_proxy_was_used); 299 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeConnect", 300 connect_start - domain_lookup_end, 301 data_reduction_proxy_was_used); 302 PLT_HISTOGRAM_DRP("PLT.NT_Connect", connect_end - connect_start, 303 data_reduction_proxy_was_used); 304 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeRequest", 305 request_start - connect_end, 306 data_reduction_proxy_was_used); 307 PLT_HISTOGRAM_DRP("PLT.NT_Request", response_start - request_start, 308 data_reduction_proxy_was_used); 309 PLT_HISTOGRAM_DRP("PLT.NT_Response", response_end - response_start, 310 data_reduction_proxy_was_used); 311 312 if (!dom_loading.is_null()) { 313 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeDomLoading", 314 dom_loading - response_start, 315 data_reduction_proxy_was_used); 316 } 317 if (!dom_interactive.is_null() && !dom_loading.is_null()) { 318 PLT_HISTOGRAM_DRP("PLT.NT_DomLoading", 319 dom_interactive - dom_loading, 320 data_reduction_proxy_was_used); 321 } 322 if (!dom_content_loaded_start.is_null() && !dom_interactive.is_null()) { 323 PLT_HISTOGRAM_DRP("PLT.NT_DomInteractive", 324 dom_content_loaded_start - dom_interactive, 325 data_reduction_proxy_was_used); 326 } 327 if (!dom_content_loaded_start.is_null() && 328 !dom_content_loaded_end.is_null() ) { 329 PLT_HISTOGRAM_DRP("PLT.NT_DomContentLoaded", 330 dom_content_loaded_end - dom_content_loaded_start, 331 data_reduction_proxy_was_used); 332 } 333 if (!dom_content_loaded_end.is_null() && !load_event_start.is_null()) { 334 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeLoadEvent", 335 load_event_start - dom_content_loaded_end, 336 data_reduction_proxy_was_used); 337 } 338 339 // TODO(simonjam): There is no way to distinguish between abandonment and 340 // intentional Javascript navigation before the load event fires. 341 // TODO(dominich): Load type breakdown 342 if (!load_event_start.is_null()) { 343 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_BeginToFinishDoc", 344 load_event_start - begin, 345 came_from_websearch, 346 websearch_chrome_joint_experiment_id, 347 is_preview); 348 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_CommitToFinishDoc", 349 load_event_start - response_start, 350 came_from_websearch, 351 websearch_chrome_joint_experiment_id, 352 is_preview); 353 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_RequestToFinishDoc", 354 load_event_start - navigation_start, 355 came_from_websearch, 356 websearch_chrome_joint_experiment_id, 357 is_preview); 358 if (data_reduction_proxy_was_used) { 359 PLT_HISTOGRAM("PLT.PT_BeginToFinishDoc_DataReductionProxy", 360 load_event_start - begin); 361 PLT_HISTOGRAM("PLT.PT_CommitToFinishDoc_DataReductionProxy", 362 load_event_start - response_start); 363 PLT_HISTOGRAM("PLT.PT_RequestToFinishDoc_DataReductionProxy", 364 load_event_start - navigation_start); 365 } 366 } 367 if (!load_event_end.is_null()) { 368 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_BeginToFinish", 369 load_event_end - begin, 370 came_from_websearch, 371 websearch_chrome_joint_experiment_id, 372 is_preview); 373 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_CommitToFinish", 374 load_event_end - response_start, 375 came_from_websearch, 376 websearch_chrome_joint_experiment_id, 377 is_preview); 378 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_RequestToFinish", 379 load_event_end - navigation_start, 380 came_from_websearch, 381 websearch_chrome_joint_experiment_id, 382 is_preview); 383 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_StartToFinish", 384 load_event_end - request_start, 385 came_from_websearch, 386 websearch_chrome_joint_experiment_id, 387 is_preview); 388 if (data_reduction_proxy_was_used) { 389 PLT_HISTOGRAM("PLT.PT_BeginToFinish_DataReductionProxy", 390 load_event_end - begin); 391 PLT_HISTOGRAM("PLT.PT_CommitToFinish_DataReductionProxy", 392 load_event_end - response_start); 393 PLT_HISTOGRAM("PLT.PT_RequestToFinish_DataReductionProxy", 394 load_event_end - navigation_start); 395 PLT_HISTOGRAM("PLT.PT_StartToFinish_DataReductionProxy", 396 load_event_end - request_start); 397 } 398 } 399 if (!load_event_start.is_null() && !load_event_end.is_null()) { 400 PLT_HISTOGRAM("PLT.PT_FinishDocToFinish", 401 load_event_end - load_event_start); 402 PLT_HISTOGRAM_DRP("PLT.NT_LoadEvent", 403 load_event_end - load_event_start, 404 data_reduction_proxy_was_used); 405 406 if (data_reduction_proxy_was_used) 407 PLT_HISTOGRAM("PLT.PT_FinishDocToFinish_DataReductionProxy", 408 load_event_end - load_event_start); 409 } 410 if (!dom_content_loaded_start.is_null()) { 411 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_RequestToDomContentLoaded", 412 dom_content_loaded_start - navigation_start, 413 came_from_websearch, 414 websearch_chrome_joint_experiment_id, 415 is_preview); 416 if (data_reduction_proxy_was_used) 417 PLT_HISTOGRAM("PLT.PT_RequestToDomContentLoaded_DataReductionProxy", 418 dom_content_loaded_start - navigation_start); 419 } 420 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_BeginToCommit", 421 response_start - begin, 422 came_from_websearch, 423 websearch_chrome_joint_experiment_id, 424 is_preview); 425 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_RequestToStart", 426 request_start - navigation_start, 427 came_from_websearch, 428 websearch_chrome_joint_experiment_id, 429 is_preview); 430 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_StartToCommit", 431 response_start - request_start, 432 came_from_websearch, 433 websearch_chrome_joint_experiment_id, 434 is_preview); 435 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_RequestToCommit", 436 response_start - navigation_start, 437 came_from_websearch, 438 websearch_chrome_joint_experiment_id, 439 is_preview); 440 if (data_reduction_proxy_was_used) { 441 PLT_HISTOGRAM("PLT.PT_BeginToCommit_DataReductionProxy", 442 response_start - begin); 443 PLT_HISTOGRAM("PLT.PT_RequestToStart_DataReductionProxy", 444 request_start - navigation_start); 445 PLT_HISTOGRAM("PLT.PT_StartToCommit_DataReductionProxy", 446 response_start - request_start); 447 PLT_HISTOGRAM("PLT.PT_RequestToCommit_DataReductionProxy", 448 response_start - navigation_start); 449 } 450} 451 452// These histograms are based on the timing information collected in 453// DocumentState. They should be transitioned to equivalents based on the 454// Navigation Timing records (see DumpPerformanceTiming()) or dropped if not 455// needed. Please do not add new metrics based on DocumentState. 456void DumpDeprecatedHistograms(const WebPerformance& performance, 457 DocumentState* document_state, 458 bool data_reduction_proxy_was_used, 459 bool came_from_websearch, 460 int websearch_chrome_joint_experiment_id, 461 bool is_preview, 462 URLPattern::SchemeMasks scheme_type) { 463 // If we've already dumped, do nothing. 464 // This simple bool works because we only dump for the main frame. 465 if (document_state->load_histograms_recorded()) 466 return; 467 468 // Abort if any of these is missing. 469 Time start = document_state->start_load_time(); 470 Time commit = document_state->commit_load_time(); 471 Time navigation_start = 472 Time::FromDoubleT(performance.navigationStart()); 473 if (start.is_null() || commit.is_null() || navigation_start.is_null()) 474 return; 475 476 // We properly handle null values for the next 3 variables. 477 Time request = document_state->request_time(); 478 Time first_paint = document_state->first_paint_time(); 479 Time first_paint_after_load = document_state->first_paint_after_load_time(); 480 Time finish_doc = document_state->finish_document_load_time(); 481 Time finish_all_loads = document_state->finish_load_time(); 482 483 // Handle case where user hits "stop" or "back" before loading completely. 484 // Note that this makes abandoned page loads be recorded as if they were 485 // completed, polluting the metrics with artifically short completion times. 486 // We are not fixing this as these metrics are being dropped as deprecated. 487 if (finish_doc.is_null()) { 488 finish_doc = Time::Now(); 489 document_state->set_finish_document_load_time(finish_doc); 490 } 491 if (finish_all_loads.is_null()) { 492 finish_all_loads = Time::Now(); 493 document_state->set_finish_load_time(finish_all_loads); 494 } 495 496 document_state->set_load_histograms_recorded(true); 497 498 // Note: Client side redirects will have no request time. 499 Time begin = request.is_null() ? start : request; 500 TimeDelta begin_to_finish_doc = finish_doc - begin; 501 TimeDelta begin_to_finish_all_loads = finish_all_loads - begin; 502 TimeDelta start_to_finish_all_loads = finish_all_loads - start; 503 TimeDelta start_to_commit = commit - start; 504 505 DocumentState::LoadType load_type = document_state->load_type(); 506 507 // The above code sanitized all values of times, in preparation for creating 508 // actual histograms. The remainder of this code could be run at destructor 509 // time for the document_state, since all data is intact. 510 511 // Aggregate PLT data across all link types. 512 UMA_HISTOGRAM_ENUMERATION("PLT.LoadType", load_type, 513 DocumentState::kLoadTypeMax); 514 PLT_HISTOGRAM("PLT.StartToCommit", start_to_commit); 515 PLT_HISTOGRAM("PLT.CommitToFinishDoc", finish_doc - commit); 516 PLT_HISTOGRAM("PLT.FinishDocToFinish", finish_all_loads - finish_doc); 517 PLT_HISTOGRAM("PLT.BeginToCommit", commit - begin); 518 PLT_HISTOGRAM("PLT.StartToFinish", start_to_finish_all_loads); 519 if (!request.is_null()) { 520 PLT_HISTOGRAM("PLT.RequestToStart", start - request); 521 PLT_HISTOGRAM("PLT.RequestToFinish", finish_all_loads - request); 522 } 523 PLT_HISTOGRAM("PLT.CommitToFinish", finish_all_loads - commit); 524 525 scoped_ptr<TimeDelta> begin_to_first_paint; 526 scoped_ptr<TimeDelta> commit_to_first_paint; 527 if (!first_paint.is_null()) { 528 // 'first_paint' can be before 'begin' for an unknown reason. 529 // See bug http://crbug.com/125273 for details. 530 if (begin <= first_paint) { 531 begin_to_first_paint.reset(new TimeDelta(first_paint - begin)); 532 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.BeginToFirstPaint", 533 *begin_to_first_paint, 534 came_from_websearch, 535 websearch_chrome_joint_experiment_id, 536 is_preview); 537 } 538 539 // Conditional was previously a DCHECK. Changed due to multiple bot 540 // failures, listed in crbug.com/383963 541 if (commit <= first_paint) { 542 commit_to_first_paint.reset(new TimeDelta(first_paint - commit)); 543 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.CommitToFirstPaint", 544 *commit_to_first_paint, 545 came_from_websearch, 546 websearch_chrome_joint_experiment_id, 547 is_preview); 548 } 549 } 550 if (!first_paint_after_load.is_null()) { 551 // 'first_paint_after_load' can be before 'begin' for an unknown reason. 552 // See bug http://crbug.com/125273 for details. 553 if (begin <= first_paint_after_load) { 554 PLT_HISTOGRAM("PLT.BeginToFirstPaintAfterLoad", 555 first_paint_after_load - begin); 556 } 557 // Both following conditionals were previously DCHECKs. Changed due to 558 // multiple bot failures, listed in crbug.com/383963 559 if (commit <= first_paint_after_load) { 560 PLT_HISTOGRAM("PLT.CommitToFirstPaintAfterLoad", 561 first_paint_after_load - commit); 562 } 563 if (finish_all_loads <= first_paint_after_load) { 564 PLT_HISTOGRAM("PLT.FinishToFirstPaintAfterLoad", 565 first_paint_after_load - finish_all_loads); 566 } 567 } 568 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.BeginToFinishDoc", begin_to_finish_doc, 569 came_from_websearch, 570 websearch_chrome_joint_experiment_id, 571 is_preview); 572 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.BeginToFinish", begin_to_finish_all_loads, 573 came_from_websearch, 574 websearch_chrome_joint_experiment_id, 575 is_preview); 576 577 // Load type related histograms. 578 switch (load_type) { 579 case DocumentState::UNDEFINED_LOAD: 580 PLT_HISTOGRAM("PLT.BeginToFinishDoc_UndefLoad", begin_to_finish_doc); 581 PLT_HISTOGRAM("PLT.BeginToFinish_UndefLoad", begin_to_finish_all_loads); 582 break; 583 case DocumentState::RELOAD: 584 PLT_HISTOGRAM("PLT.BeginToFinishDoc_Reload", begin_to_finish_doc); 585 PLT_HISTOGRAM("PLT.BeginToFinish_Reload", begin_to_finish_all_loads); 586 break; 587 case DocumentState::HISTORY_LOAD: 588 PLT_HISTOGRAM("PLT.BeginToFinishDoc_HistoryLoad", begin_to_finish_doc); 589 PLT_HISTOGRAM("PLT.BeginToFinish_HistoryLoad", begin_to_finish_all_loads); 590 break; 591 case DocumentState::NORMAL_LOAD: 592 PLT_HISTOGRAM("PLT.BeginToFinishDoc_NormalLoad", begin_to_finish_doc); 593 PLT_HISTOGRAM("PLT.BeginToFinish_NormalLoad", begin_to_finish_all_loads); 594 break; 595 case DocumentState::LINK_LOAD_NORMAL: 596 PLT_HISTOGRAM("PLT.BeginToFinishDoc_LinkLoadNormal", 597 begin_to_finish_doc); 598 PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadNormal", 599 begin_to_finish_all_loads); 600 break; 601 case DocumentState::LINK_LOAD_RELOAD: 602 PLT_HISTOGRAM("PLT.BeginToFinishDoc_LinkLoadReload", 603 begin_to_finish_doc); 604 PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadReload", 605 begin_to_finish_all_loads); 606 break; 607 case DocumentState::LINK_LOAD_CACHE_STALE_OK: 608 PLT_HISTOGRAM("PLT.BeginToFinishDoc_LinkLoadStaleOk", 609 begin_to_finish_doc); 610 PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadStaleOk", 611 begin_to_finish_all_loads); 612 break; 613 case DocumentState::LINK_LOAD_CACHE_ONLY: 614 PLT_HISTOGRAM("PLT.BeginToFinishDoc_LinkLoadCacheOnly", 615 begin_to_finish_doc); 616 PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadCacheOnly", 617 begin_to_finish_all_loads); 618 break; 619 default: 620 break; 621 } 622 623 if (data_reduction_proxy_was_used) { 624 PLT_HISTOGRAM("PLT.BeginToFinishDoc_SpdyProxy", begin_to_finish_doc); 625 PLT_HISTOGRAM("PLT.BeginToFinish_SpdyProxy", begin_to_finish_all_loads); 626 } 627 628 if (document_state->was_prefetcher()) { 629 PLT_HISTOGRAM("PLT.BeginToFinishDoc_ContentPrefetcher", 630 begin_to_finish_doc); 631 PLT_HISTOGRAM("PLT.BeginToFinish_ContentPrefetcher", 632 begin_to_finish_all_loads); 633 } 634 if (document_state->was_referred_by_prefetcher()) { 635 PLT_HISTOGRAM("PLT.BeginToFinishDoc_ContentPrefetcherReferrer", 636 begin_to_finish_doc); 637 PLT_HISTOGRAM("PLT.BeginToFinish_ContentPrefetcherReferrer", 638 begin_to_finish_all_loads); 639 } 640 641 const bool use_webrequest_histogram = 642 ChromeContentRendererClient::WasWebRequestUsedBySomeExtensions(); 643 if (use_webrequest_histogram) { 644 switch (load_type) { 645 case DocumentState::NORMAL_LOAD: 646 PLT_HISTOGRAM( 647 "PLT.BeginToFinish_NormalLoad_ExtensionWebRequest", 648 begin_to_finish_all_loads); 649 break; 650 case DocumentState::LINK_LOAD_NORMAL: 651 PLT_HISTOGRAM( 652 "PLT.BeginToFinish_LinkLoadNormal_ExtensionWebRequest", 653 begin_to_finish_all_loads); 654 break; 655 case DocumentState::LINK_LOAD_RELOAD: 656 PLT_HISTOGRAM( 657 "PLT.BeginToFinish_LinkLoadReload_ExtensionWebRequest", 658 begin_to_finish_all_loads); 659 break; 660 case DocumentState::LINK_LOAD_CACHE_STALE_OK: 661 PLT_HISTOGRAM( 662 "PLT.BeginToFinish_LinkLoadStaleOk_ExtensionWebRequest", 663 begin_to_finish_all_loads); 664 break; 665 default: 666 break; 667 } 668 } 669} 670 671} // namespace 672 673PageLoadHistograms::PageLoadHistograms(content::RenderView* render_view) 674 : content::RenderViewObserver(render_view) { 675} 676 677void PageLoadHistograms::Dump(WebFrame* frame) { 678 // We only dump histograms for main frames. 679 // In the future, it may be interesting to tag subframes and dump them too. 680 if (!frame || frame->parent()) 681 return; 682 683 // Only dump for supported schemes. 684 URLPattern::SchemeMasks scheme_type = 685 GetSupportedSchemeType(frame->document().url()); 686 if (scheme_type == 0) 687 return; 688 689 // Ignore multipart requests. 690 if (frame->dataSource()->response().isMultipartPayload()) 691 return; 692 693 DocumentState* document_state = 694 DocumentState::FromDataSource(frame->dataSource()); 695 696 bool data_reduction_proxy_was_used = DataReductionProxyWasUsed(frame); 697 bool came_from_websearch = 698 IsFromGoogleSearchResult(frame->document().url(), 699 GURL(frame->document().referrer())); 700 int websearch_chrome_joint_experiment_id = kNoExperiment; 701 bool is_preview = false; 702 if (came_from_websearch) { 703 websearch_chrome_joint_experiment_id = 704 GetQueryStringBasedExperiment(GURL(frame->document().referrer())); 705 is_preview = ViaHeaderContains(frame, "1.1 Google Instant Proxy Preview"); 706 } 707 708 // Metrics based on the timing information recorded for the Navigation Timing 709 // API - http://www.w3.org/TR/navigation-timing/. 710 DumpHistograms(frame->performance(), document_state, 711 data_reduction_proxy_was_used, 712 came_from_websearch, 713 websearch_chrome_joint_experiment_id, 714 is_preview); 715 716 // Old metrics based on the timing information stored in DocumentState. These 717 // are deprecated and should go away. 718 DumpDeprecatedHistograms(frame->performance(), document_state, 719 data_reduction_proxy_was_used, 720 came_from_websearch, 721 websearch_chrome_joint_experiment_id, 722 is_preview, 723 scheme_type); 724 725 // Log the PLT to the info log. 726 LogPageLoadTime(document_state, frame->dataSource()); 727 728 // Since there are currently no guarantees that renderer histograms will be 729 // sent to the browser, we initiate a PostTask here to be sure that we send 730 // the histograms we generated. Without this call, pages that don't have an 731 // on-close-handler might generate data that is lost when the renderer is 732 // shutdown abruptly (perchance because the user closed the tab). 733 // TODO(jar) BUG=33233: This needs to be moved to a PostDelayedTask, and it 734 // should post when the onload is complete, so that it doesn't interfere with 735 // the next load. 736 content::RenderThread::Get()->UpdateHistograms( 737 content::kHistogramSynchronizerReservedSequenceNumber); 738} 739 740void PageLoadHistograms::FrameWillClose(WebFrame* frame) { 741 Dump(frame); 742} 743 744void PageLoadHistograms::ClosePage() { 745 // TODO(davemoore) This code should be removed once willClose() gets 746 // called when a page is destroyed. page_load_histograms_.Dump() is safe 747 // to call multiple times for the same frame, but it will simplify things. 748 Dump(render_view()->GetWebView()->mainFrame()); 749} 750 751void PageLoadHistograms::LogPageLoadTime(const DocumentState* document_state, 752 const WebDataSource* ds) const { 753 // Because this function gets called on every page load, 754 // take extra care to optimize it away if logging is turned off. 755 if (logging::LOG_INFO < logging::GetMinLogLevel()) 756 return; 757 758 DCHECK(document_state); 759 DCHECK(ds); 760 GURL url(ds->request().url()); 761 Time start = document_state->start_load_time(); 762 Time finish = document_state->finish_load_time(); 763 // TODO(mbelshe): should we log more stats? 764 VLOG(1) << "PLT: " << (finish - start).InMilliseconds() << "ms " 765 << url.spec(); 766} 767