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.
5 #include "chrome/renderer/page_load_histograms.h"
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 "content/public/common/content_constants.h"
22 #include "content/public/renderer/document_state.h"
23 #include "content/public/renderer/render_thread.h"
24 #include "content/public/renderer/render_view.h"
25 #include "extensions/common/url_pattern.h"
26 #include "net/base/url_util.h"
27 #include "third_party/WebKit/public/platform/WebURLRequest.h"
28 #include "third_party/WebKit/public/platform/WebURLResponse.h"
29 #include "third_party/WebKit/public/web/WebDocument.h"
30 #include "third_party/WebKit/public/web/WebFrame.h"
31 #include "third_party/WebKit/public/web/WebPerformance.h"
32 #include "third_party/WebKit/public/web/WebView.h"
35 #if defined(SPDY_PROXY_AUTH_ORIGIN)
36 #include "net/http/http_response_headers.h"
39 using blink::WebDataSource;
40 using blink::WebFrame;
41 using blink::WebPerformance;
42 using blink::WebString;
44 using base::TimeDelta;
45 using content::DocumentState;
47 const size_t kPLTCount = 100;
51 // ID indicating that no GWS-Chrome joint experiment is active.
52 const int kNoExperiment = 0;
54 // Max ID of GWS-Chrome joint experiment. If you change this value, please
55 // update PLT_HISTOGRAM_WITH_GWS_VARIANT accordingly.
56 const int kMaxExperimentID = 20;
59 return TimeDelta::FromMilliseconds(10);
62 return TimeDelta::FromMinutes(10);
65 // This function corresponds to PLT_HISTOGRAM macro invocation without caching.
66 // Use this for PLT histograms with dynamically generated names, which
67 // otherwise can't use the caching PLT_HISTOGRAM macro without code duplication.
68 void PltHistogramWithNoMacroCaching(const std::string& name,
69 const TimeDelta& sample) {
70 // The parameters should exacly match the parameters in
71 // UMA_HISTOGRAM_CUSTOM_TIMES macro.
72 base::HistogramBase* histogram_pointer = base::Histogram::FactoryTimeGet(
73 name, kPLTMin(), kPLTMax(), kPLTCount,
74 base::HistogramBase::kUmaTargetedHistogramFlag);
75 histogram_pointer->AddTime(sample);
78 // Various preview applicability states.
79 enum GwsPreviewState {
81 // Instant search clicks [not] applied, data reduction proxy used,
84 // Instant search clicks applied, data reduction proxy [not] used,
87 // Instant search clicks applied, data reduction proxy used,
88 // [not] from web search
92 // This records UMA corresponding to the PLT_HISTOGRAM macro without caching.
93 void PltHistogramWithGwsPreview(const char* name,
94 const TimeDelta& sample,
95 GwsPreviewState preview_state,
96 int preview_experiment_id) {
97 std::string preview_suffix;
98 switch (preview_state) {
99 case PREVIEW_WAS_SHOWN:
100 preview_suffix = "_WithPreview";
103 preview_suffix = "_Preview";
105 case PREVIEW_NOT_USED:
106 preview_suffix = "_NoPreview";
111 PltHistogramWithNoMacroCaching(name + preview_suffix, sample);
113 if (preview_experiment_id != kNoExperiment) {
114 std::string name_with_experiment_id = base::StringPrintf(
115 "%s%s_Experiment%d", name, preview_suffix.c_str(),
116 preview_experiment_id);
117 PltHistogramWithNoMacroCaching(name_with_experiment_id, sample);
121 #define PLT_HISTOGRAM(name, sample) \
122 UMA_HISTOGRAM_CUSTOM_TIMES(name, sample, kPLTMin(), kPLTMax(), kPLTCount);
124 #define PLT_HISTOGRAM_WITH_GWS_VARIANT( \
125 name, sample, came_from_websearch, websearch_chrome_joint_experiment_id, \
126 preview_state, preview_experiment_id) { \
127 PLT_HISTOGRAM(name, sample); \
128 if (came_from_websearch) { \
129 PLT_HISTOGRAM(base::StringPrintf("%s_FromGWS", name), sample) \
130 if (websearch_chrome_joint_experiment_id != kNoExperiment) { \
131 std::string name_with_experiment_id = base::StringPrintf( \
132 "%s_FromGWS_Experiment%d", \
133 name, websearch_chrome_joint_experiment_id); \
134 PltHistogramWithNoMacroCaching(name_with_experiment_id, sample); \
137 PltHistogramWithGwsPreview(name, sample, preview_state, \
138 preview_experiment_id); \
141 // In addition to PLT_HISTOGRAM, add the *_DataReductionProxy variant
142 // conditionally. This macro runs only in one thread.
143 #define PLT_HISTOGRAM_DRP(name, sample, data_reduction_proxy_was_used) \
145 static base::HistogramBase* counter(NULL); \
146 static base::HistogramBase* drp_counter(NULL); \
148 DCHECK(drp_counter == NULL); \
149 counter = base::Histogram::FactoryTimeGet( \
150 name, kPLTMin(), kPLTMax(), kPLTCount, \
151 base::Histogram::kUmaTargetedHistogramFlag); \
153 counter->AddTime(sample); \
154 if (!data_reduction_proxy_was_used) break; \
155 if (!drp_counter) { \
156 drp_counter = base::Histogram::FactoryTimeGet( \
157 std::string(name) + "_DataReductionProxy", \
158 kPLTMin(), kPLTMax(), kPLTCount, \
159 base::Histogram::kUmaTargetedHistogramFlag); \
161 drp_counter->AddTime(sample); \
164 // Returns the scheme type of the given URL if its type is one for which we
165 // dump page load histograms. Otherwise returns NULL.
166 URLPattern::SchemeMasks GetSupportedSchemeType(const GURL& url) {
167 if (url.SchemeIs("http"))
168 return URLPattern::SCHEME_HTTP;
169 else if (url.SchemeIs("https"))
170 return URLPattern::SCHEME_HTTPS;
171 return static_cast<URLPattern::SchemeMasks>(0);
174 // Helper function to check for string in 'via' header. Returns true if
175 // |via_value| is one of the values listed in the Via header and the response
176 // was fetched via a proxy.
177 bool ViaHeaderContains(WebFrame* frame, const std::string& via_value) {
178 const char kViaHeaderName[] = "Via";
180 DocumentState* document_state =
181 DocumentState::FromDataSource(frame->dataSource());
182 if (!document_state->was_fetched_via_proxy())
185 std::vector<std::string> values;
186 // Multiple via headers have already been coalesced and hence each value
187 // separated by a comma corresponds to a proxy. The value added by a proxy is
188 // not expected to contain any commas.
189 // Example., Via: 1.0 Compression proxy, 1.1 Google promise preview
191 frame->dataSource()->response().httpHeaderField(kViaHeaderName).utf8(),
193 return std::find(values.begin(), values.end(), via_value) != values.end();
196 // Returns true if the data reduction proxy was used. Note, this function will
197 // produce a false positive if a page is fetched using SPDY and using a proxy,
198 // and the data reduction proxy's via value is added to the Via header.
199 // TODO(bengr): Plumb the hostname of the proxy and check if it matches
200 // |SPDY_PROXY_AUTH_ORIGIN|.
201 bool DataReductionProxyWasUsed(WebFrame* frame) {
202 #if defined(SPDY_PROXY_AUTH_ORIGIN)
203 DocumentState* document_state =
204 DocumentState::FromDataSource(frame->dataSource());
205 if (!document_state->was_fetched_via_proxy())
208 std::string via_header =
209 base::UTF16ToUTF8(frame->dataSource()->response().httpHeaderField("Via"));
211 if (via_header.empty())
213 std::string headers = "HTTP/1.1 200 OK\nVia: " + via_header + "\n\n";
214 // Produce raw headers, expected by the |HttpResponseHeaders| constructor.
215 std::replace(headers.begin(), headers.end(), '\n', '\0');
216 scoped_refptr<net::HttpResponseHeaders> response_headers(
217 new net::HttpResponseHeaders(headers));
218 return response_headers->IsChromeProxyResponse();
224 // Returns true if the provided URL is a referrer string that came from
225 // a Google Web Search results page. This is a little non-deterministic
226 // because desktop and mobile websearch differ and sometimes just provide
227 // http://www.google.com/ as the referrer. In the case of /url we can be sure
228 // that it came from websearch but we will be generous and allow for cases
229 // where a non-Google URL was provided a bare Google URL as a referrer.
230 // The domain validation matches the code used by the prerenderer for similar
232 // TODO(pmeenan): Remove the fuzzy logic when the referrer is reliable
233 bool IsFromGoogleSearchResult(const GURL& url, const GURL& referrer) {
234 if (!StartsWithASCII(referrer.host(), "www.google.", true))
236 if (StartsWithASCII(referrer.path(), "/url", true))
238 bool is_possible_search_referrer =
239 referrer.path().empty() ||
240 referrer.path() == "/" ||
241 StartsWithASCII(referrer.path(), "/search", true) ||
242 StartsWithASCII(referrer.path(), "/webhp", true);
243 if (is_possible_search_referrer &&
244 !StartsWithASCII(url.host(), "www.google", true))
249 // Extracts a Google Web Search and Chrome joint experiment ID from a referrer
250 // that came from a Google Web Search results page. An experiment ID is embedded
251 // in a query string as a "gcjeid=" parameter value.
252 int GetQueryStringBasedExperiment(const GURL& referrer) {
254 if (!net::GetValueForKeyInQuery(referrer, "gcjeid", &value))
255 return kNoExperiment;
258 if (!base::StringToInt(value, &experiment_id))
259 return kNoExperiment;
260 if (0 < experiment_id && experiment_id <= kMaxExperimentID)
261 return experiment_id;
262 return kNoExperiment;
265 // Returns preview state by looking at url and referer url.
266 void GetPreviewState(WebFrame* frame,
267 bool came_from_websearch,
268 bool data_reduction_proxy_was_used,
269 GwsPreviewState* preview_state,
270 int* preview_experiment_id) {
271 // Conditions for GWS preview are,
272 // 1. Data reduction proxy was used.
273 // Determine the preview state (PREVIEW, PREVIEW_WAS_SHOWN, PREVIEW_NOT_USED)
274 // by inspecting the Via header.
275 if (data_reduction_proxy_was_used) {
276 if (came_from_websearch) {
277 *preview_state = ViaHeaderContains(
278 frame, "1.1 Google Promise Preview") ? PREVIEW : PREVIEW_NOT_USED;
279 } else if (ViaHeaderContains(frame, "1.1 Google Promise Original")) {
280 *preview_state = PREVIEW_WAS_SHOWN;
281 *preview_experiment_id = GetQueryStringBasedExperiment(
282 GURL(frame->document().referrer()));
287 void DumpPerformanceTiming(const WebPerformance& performance,
288 DocumentState* document_state,
289 bool data_reduction_proxy_was_used,
290 bool came_from_websearch,
291 int websearch_chrome_joint_experiment_id,
292 GwsPreviewState preview_state,
293 int preview_experiment_id) {
294 Time request = document_state->request_time();
296 Time navigation_start = Time::FromDoubleT(performance.navigationStart());
297 Time redirect_start = Time::FromDoubleT(performance.redirectStart());
298 Time redirect_end = Time::FromDoubleT(performance.redirectEnd());
299 Time fetch_start = Time::FromDoubleT(performance.fetchStart());
300 Time domain_lookup_start = Time::FromDoubleT(performance.domainLookupStart());
301 Time domain_lookup_end = Time::FromDoubleT(performance.domainLookupEnd());
302 Time connect_start = Time::FromDoubleT(performance.connectStart());
303 Time connect_end = Time::FromDoubleT(performance.connectEnd());
304 Time request_start = Time::FromDoubleT(performance.requestStart());
305 Time response_start = Time::FromDoubleT(performance.responseStart());
306 Time response_end = Time::FromDoubleT(performance.responseEnd());
307 Time dom_loading = Time::FromDoubleT(performance.domLoading());
308 Time dom_interactive = Time::FromDoubleT(performance.domInteractive());
309 Time dom_content_loaded_start =
310 Time::FromDoubleT(performance.domContentLoadedEventStart());
311 Time dom_content_loaded_end =
312 Time::FromDoubleT(performance.domContentLoadedEventEnd());
313 Time load_event_start = Time::FromDoubleT(performance.loadEventStart());
314 Time load_event_end = Time::FromDoubleT(performance.loadEventEnd());
315 Time begin = (request.is_null() ? navigation_start : request_start);
317 DCHECK(!navigation_start.is_null());
319 // It is possible for a document to have navigation_start time, but no
320 // request_start. An example is doing a window.open, which synchronously
321 // loads "about:blank", then using document.write add a meta http-equiv
322 // refresh tag, which causes a navigation. In such case, we will arrive at
323 // this function with no request/response timing data and identical load
324 // start/end values. Avoid logging this case, as it doesn't add any
325 // meaningful information to the histogram.
326 if (request_start.is_null())
329 // TODO(dominich): Investigate conditions under which |load_event_start| and
330 // |load_event_end| may be NULL as in the non-PT_ case below. Examples in
331 // http://crbug.com/112006.
332 // DCHECK(!load_event_start.is_null());
333 // DCHECK(!load_event_end.is_null());
335 if (document_state->web_timing_histograms_recorded())
337 document_state->set_web_timing_histograms_recorded(true);
339 if (!redirect_start.is_null() && !redirect_end.is_null()) {
340 PLT_HISTOGRAM_DRP("PLT.NT_Redirect", redirect_end - redirect_start,
341 data_reduction_proxy_was_used);
343 "PLT.NT_DelayBeforeFetchRedirect",
344 (fetch_start - navigation_start) - (redirect_end - redirect_start),
345 data_reduction_proxy_was_used);
347 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeFetch",
348 fetch_start - navigation_start,
349 data_reduction_proxy_was_used);
351 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeDomainLookup",
352 domain_lookup_start - fetch_start,
353 data_reduction_proxy_was_used);
354 PLT_HISTOGRAM_DRP("PLT.NT_DomainLookup",
355 domain_lookup_end - domain_lookup_start,
356 data_reduction_proxy_was_used);
357 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeConnect",
358 connect_start - domain_lookup_end,
359 data_reduction_proxy_was_used);
360 PLT_HISTOGRAM_DRP("PLT.NT_Connect", connect_end - connect_start,
361 data_reduction_proxy_was_used);
362 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeRequest",
363 request_start - connect_end,
364 data_reduction_proxy_was_used);
365 PLT_HISTOGRAM_DRP("PLT.NT_Request", response_start - request_start,
366 data_reduction_proxy_was_used);
367 PLT_HISTOGRAM_DRP("PLT.NT_Response", response_end - response_start,
368 data_reduction_proxy_was_used);
370 if (!dom_loading.is_null()) {
371 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeDomLoading",
372 dom_loading - response_start,
373 data_reduction_proxy_was_used);
375 if (!dom_interactive.is_null() && !dom_loading.is_null()) {
376 PLT_HISTOGRAM_DRP("PLT.NT_DomLoading",
377 dom_interactive - dom_loading,
378 data_reduction_proxy_was_used);
380 if (!dom_content_loaded_start.is_null() && !dom_interactive.is_null()) {
381 PLT_HISTOGRAM_DRP("PLT.NT_DomInteractive",
382 dom_content_loaded_start - dom_interactive,
383 data_reduction_proxy_was_used);
385 if (!dom_content_loaded_start.is_null() &&
386 !dom_content_loaded_end.is_null() ) {
387 PLT_HISTOGRAM_DRP("PLT.NT_DomContentLoaded",
388 dom_content_loaded_end - dom_content_loaded_start,
389 data_reduction_proxy_was_used);
391 if (!dom_content_loaded_end.is_null() && !load_event_start.is_null()) {
392 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeLoadEvent",
393 load_event_start - dom_content_loaded_end,
394 data_reduction_proxy_was_used);
397 // TODO(simonjam): There is no way to distinguish between abandonment and
398 // intentional Javascript navigation before the load event fires.
399 // TODO(dominich): Load type breakdown
400 if (!load_event_start.is_null()) {
401 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_BeginToFinishDoc",
402 load_event_start - begin,
404 websearch_chrome_joint_experiment_id,
405 preview_state, preview_experiment_id);
406 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_CommitToFinishDoc",
407 load_event_start - response_start,
409 websearch_chrome_joint_experiment_id,
410 preview_state, preview_experiment_id);
411 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_RequestToFinishDoc",
412 load_event_start - navigation_start,
414 websearch_chrome_joint_experiment_id,
415 preview_state, preview_experiment_id);
416 if (data_reduction_proxy_was_used) {
417 PLT_HISTOGRAM("PLT.PT_BeginToFinishDoc_DataReductionProxy",
418 load_event_start - begin);
419 PLT_HISTOGRAM("PLT.PT_CommitToFinishDoc_DataReductionProxy",
420 load_event_start - response_start);
421 PLT_HISTOGRAM("PLT.PT_RequestToFinishDoc_DataReductionProxy",
422 load_event_start - navigation_start);
425 if (!load_event_end.is_null()) {
426 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_BeginToFinish",
427 load_event_end - begin,
429 websearch_chrome_joint_experiment_id,
430 preview_state, preview_experiment_id);
431 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_CommitToFinish",
432 load_event_end - response_start,
434 websearch_chrome_joint_experiment_id,
435 preview_state, preview_experiment_id);
436 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_RequestToFinish",
437 load_event_end - navigation_start,
439 websearch_chrome_joint_experiment_id,
440 preview_state, preview_experiment_id);
441 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_StartToFinish",
442 load_event_end - request_start,
444 websearch_chrome_joint_experiment_id,
445 preview_state, preview_experiment_id);
446 if (data_reduction_proxy_was_used) {
447 PLT_HISTOGRAM("PLT.PT_BeginToFinish_DataReductionProxy",
448 load_event_end - begin);
449 PLT_HISTOGRAM("PLT.PT_CommitToFinish_DataReductionProxy",
450 load_event_end - response_start);
451 PLT_HISTOGRAM("PLT.PT_RequestToFinish_DataReductionProxy",
452 load_event_end - navigation_start);
453 PLT_HISTOGRAM("PLT.PT_StartToFinish_DataReductionProxy",
454 load_event_end - request_start);
457 if (!load_event_start.is_null() && !load_event_end.is_null()) {
458 PLT_HISTOGRAM("PLT.PT_FinishDocToFinish",
459 load_event_end - load_event_start);
460 PLT_HISTOGRAM_DRP("PLT.NT_LoadEvent",
461 load_event_end - load_event_start,
462 data_reduction_proxy_was_used);
464 if (data_reduction_proxy_was_used)
465 PLT_HISTOGRAM("PLT.PT_FinishDocToFinish_DataReductionProxy",
466 load_event_end - load_event_start);
468 if (!dom_content_loaded_start.is_null()) {
469 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_RequestToDomContentLoaded",
470 dom_content_loaded_start - navigation_start,
472 websearch_chrome_joint_experiment_id,
473 preview_state, preview_experiment_id);
474 if (data_reduction_proxy_was_used)
475 PLT_HISTOGRAM("PLT.PT_RequestToDomContentLoaded_DataReductionProxy",
476 dom_content_loaded_start - navigation_start);
478 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_BeginToCommit",
479 response_start - begin,
481 websearch_chrome_joint_experiment_id,
482 preview_state, preview_experiment_id);
483 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_RequestToStart",
484 request_start - navigation_start,
486 websearch_chrome_joint_experiment_id,
487 preview_state, preview_experiment_id);
488 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_StartToCommit",
489 response_start - request_start,
491 websearch_chrome_joint_experiment_id,
492 preview_state, preview_experiment_id);
493 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_RequestToCommit",
494 response_start - navigation_start,
496 websearch_chrome_joint_experiment_id,
497 preview_state, preview_experiment_id);
498 if (data_reduction_proxy_was_used) {
499 PLT_HISTOGRAM("PLT.PT_BeginToCommit_DataReductionProxy",
500 response_start - begin);
501 PLT_HISTOGRAM("PLT.PT_RequestToStart_DataReductionProxy",
502 request_start - navigation_start);
503 PLT_HISTOGRAM("PLT.PT_StartToCommit_DataReductionProxy",
504 response_start - request_start);
505 PLT_HISTOGRAM("PLT.PT_RequestToCommit_DataReductionProxy",
506 response_start - navigation_start);
510 enum MissingStartType {
512 COMMIT_MISSING = 0x2,
513 NAV_START_MISSING = 0x4,
514 MISSING_START_TYPE_MAX = 0x8
518 FINISH_DOC_MISSING = 0x1,
519 FINISH_ALL_LOADS_MISSING = 0x2,
520 LOAD_EVENT_START_MISSING = 0x4,
521 LOAD_EVENT_END_MISSING = 0x8,
522 ABANDON_TYPE_MAX = 0x10
527 PageLoadHistograms::PageLoadHistograms(content::RenderView* render_view)
528 : content::RenderViewObserver(render_view),
529 cross_origin_access_count_(0),
530 same_origin_access_count_(0) {
533 void PageLoadHistograms::Dump(WebFrame* frame) {
534 // We only dump histograms for main frames.
535 // In the future, it may be interesting to tag subframes and dump them too.
536 if (!frame || frame->parent())
539 // Only dump for supported schemes.
540 URLPattern::SchemeMasks scheme_type =
541 GetSupportedSchemeType(frame->document().url());
542 if (scheme_type == 0)
545 // Ignore multipart requests.
546 if (frame->dataSource()->response().isMultipartPayload())
549 DocumentState* document_state =
550 DocumentState::FromDataSource(frame->dataSource());
552 bool data_reduction_proxy_was_used = DataReductionProxyWasUsed(frame);
553 bool came_from_websearch =
554 IsFromGoogleSearchResult(frame->document().url(),
555 GURL(frame->document().referrer()));
556 int websearch_chrome_joint_experiment_id = kNoExperiment;
557 if (came_from_websearch) {
558 websearch_chrome_joint_experiment_id =
559 GetQueryStringBasedExperiment(GURL(frame->document().referrer()));
562 GwsPreviewState preview_state = PREVIEW_NONE;
563 int preview_experiment_id = websearch_chrome_joint_experiment_id;
564 GetPreviewState(frame, came_from_websearch, data_reduction_proxy_was_used,
565 &preview_state, &preview_experiment_id);
567 // Times based on the Web Timing metrics.
568 // http://www.w3.org/TR/navigation-timing/
569 // TODO(tonyg, jar): We are in the process of vetting these metrics against
570 // the existing ones. Once we understand any differences, we will standardize
571 // on a single set of metrics.
572 DumpPerformanceTiming(frame->performance(), document_state,
573 data_reduction_proxy_was_used,
575 websearch_chrome_joint_experiment_id,
576 preview_state, preview_experiment_id);
578 // If we've already dumped, do nothing.
579 // This simple bool works because we only dump for the main frame.
580 if (document_state->load_histograms_recorded())
583 // Collect measurement times.
584 Time start = document_state->start_load_time();
585 Time commit = document_state->commit_load_time();
587 // TODO(tonyg, jar): Start can be missing after an in-document navigation and
588 // possibly other cases like a very premature abandonment of the page.
589 // The PLT.MissingStart histogram should help us troubleshoot and then we can
591 Time navigation_start =
592 Time::FromDoubleT(frame->performance().navigationStart());
593 int missing_start_type = 0;
594 missing_start_type |= start.is_null() ? START_MISSING : 0;
595 missing_start_type |= commit.is_null() ? COMMIT_MISSING : 0;
596 missing_start_type |= navigation_start.is_null() ? NAV_START_MISSING : 0;
597 UMA_HISTOGRAM_ENUMERATION("PLT.MissingStart", missing_start_type,
598 MISSING_START_TYPE_MAX);
599 if (missing_start_type)
602 // We properly handle null values for the next 3 variables.
603 Time request = document_state->request_time();
604 Time first_paint = document_state->first_paint_time();
605 Time first_paint_after_load = document_state->first_paint_after_load_time();
606 Time finish_doc = document_state->finish_document_load_time();
607 Time finish_all_loads = document_state->finish_load_time();
609 // TODO(tonyg, jar): We suspect a bug in abandonment counting, this temporary
610 // histogram should help us to troubleshoot.
611 Time load_event_start =
612 Time::FromDoubleT(frame->performance().loadEventStart());
613 Time load_event_end = Time::FromDoubleT(frame->performance().loadEventEnd());
614 int abandon_type = 0;
615 abandon_type |= finish_doc.is_null() ? FINISH_DOC_MISSING : 0;
616 abandon_type |= finish_all_loads.is_null() ? FINISH_ALL_LOADS_MISSING : 0;
617 abandon_type |= load_event_start.is_null() ? LOAD_EVENT_START_MISSING : 0;
618 abandon_type |= load_event_end.is_null() ? LOAD_EVENT_END_MISSING : 0;
619 UMA_HISTOGRAM_ENUMERATION("PLT.AbandonType", abandon_type, ABANDON_TYPE_MAX);
621 // Handle case where user hits "stop" or "back" before loading completely.
622 bool abandoned_page = finish_doc.is_null();
623 if (abandoned_page) {
624 finish_doc = Time::Now();
625 document_state->set_finish_document_load_time(finish_doc);
628 // TODO(jar): We should really discriminate the definition of "abandon" more
629 // finely. We should have:
630 // abandon_before_document_loaded
631 // abandon_before_onload_fired
633 if (finish_all_loads.is_null()) {
634 finish_all_loads = Time::Now();
635 document_state->set_finish_load_time(finish_all_loads);
637 DCHECK(!abandoned_page); // How can the doc have finished but not the page?
639 return; // Don't try to record a stat which is broken.
642 document_state->set_load_histograms_recorded(true);
644 // Note: Client side redirects will have no request time.
645 Time begin = request.is_null() ? start : request;
646 TimeDelta begin_to_finish_doc = finish_doc - begin;
647 TimeDelta begin_to_finish_all_loads = finish_all_loads - begin;
648 TimeDelta start_to_finish_all_loads = finish_all_loads - start;
649 TimeDelta start_to_commit = commit - start;
651 DocumentState::LoadType load_type = document_state->load_type();
653 // The above code sanitized all values of times, in preparation for creating
654 // actual histograms. The remainder of this code could be run at destructor
655 // time for the document_state, since all data is intact.
657 // Aggregate PLT data across all link types.
658 UMA_HISTOGRAM_ENUMERATION("PLT.Abandoned", abandoned_page ? 1 : 0, 2);
659 UMA_HISTOGRAM_ENUMERATION("PLT.LoadType", load_type,
660 DocumentState::kLoadTypeMax);
661 PLT_HISTOGRAM("PLT.StartToCommit", start_to_commit);
662 PLT_HISTOGRAM("PLT.CommitToFinishDoc", finish_doc - commit);
663 PLT_HISTOGRAM("PLT.FinishDocToFinish", finish_all_loads - finish_doc);
664 PLT_HISTOGRAM("PLT.BeginToCommit", commit - begin);
665 PLT_HISTOGRAM("PLT.StartToFinish", start_to_finish_all_loads);
666 if (!request.is_null()) {
667 PLT_HISTOGRAM("PLT.RequestToStart", start - request);
668 PLT_HISTOGRAM("PLT.RequestToFinish", finish_all_loads - request);
670 PLT_HISTOGRAM("PLT.CommitToFinish", finish_all_loads - commit);
672 scoped_ptr<TimeDelta> begin_to_first_paint;
673 scoped_ptr<TimeDelta> commit_to_first_paint;
674 if (!first_paint.is_null()) {
675 // 'first_paint' can be before 'begin' for an unknown reason.
676 // See bug http://crbug.com/125273 for details.
677 if (begin <= first_paint) {
678 begin_to_first_paint.reset(new TimeDelta(first_paint - begin));
679 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.BeginToFirstPaint",
680 *begin_to_first_paint,
682 websearch_chrome_joint_experiment_id,
683 preview_state, preview_experiment_id);
685 DCHECK(commit <= first_paint);
686 commit_to_first_paint.reset(new TimeDelta(first_paint - commit));
687 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.CommitToFirstPaint",
688 *commit_to_first_paint,
690 websearch_chrome_joint_experiment_id,
691 preview_state, preview_experiment_id);
693 if (!first_paint_after_load.is_null()) {
694 // 'first_paint_after_load' can be before 'begin' for an unknown reason.
695 // See bug http://crbug.com/125273 for details.
696 if (begin <= first_paint_after_load) {
697 PLT_HISTOGRAM("PLT.BeginToFirstPaintAfterLoad",
698 first_paint_after_load - begin);
700 DCHECK(commit <= first_paint_after_load);
701 PLT_HISTOGRAM("PLT.CommitToFirstPaintAfterLoad",
702 first_paint_after_load - commit);
703 DCHECK(finish_all_loads <= first_paint_after_load);
704 PLT_HISTOGRAM("PLT.FinishToFirstPaintAfterLoad",
705 first_paint_after_load - finish_all_loads);
707 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.BeginToFinishDoc", begin_to_finish_doc,
709 websearch_chrome_joint_experiment_id,
710 preview_state, preview_experiment_id);
711 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.BeginToFinish", begin_to_finish_all_loads,
713 websearch_chrome_joint_experiment_id,
714 preview_state, preview_experiment_id);
716 // Load type related histograms.
718 case DocumentState::UNDEFINED_LOAD:
719 PLT_HISTOGRAM("PLT.BeginToFinishDoc_UndefLoad", begin_to_finish_doc);
720 PLT_HISTOGRAM("PLT.BeginToFinish_UndefLoad", begin_to_finish_all_loads);
722 case DocumentState::RELOAD:
723 PLT_HISTOGRAM("PLT.BeginToFinishDoc_Reload", begin_to_finish_doc);
724 PLT_HISTOGRAM("PLT.BeginToFinish_Reload", begin_to_finish_all_loads);
726 case DocumentState::HISTORY_LOAD:
727 PLT_HISTOGRAM("PLT.BeginToFinishDoc_HistoryLoad", begin_to_finish_doc);
728 PLT_HISTOGRAM("PLT.BeginToFinish_HistoryLoad", begin_to_finish_all_loads);
730 case DocumentState::NORMAL_LOAD:
731 PLT_HISTOGRAM("PLT.BeginToFinishDoc_NormalLoad", begin_to_finish_doc);
732 PLT_HISTOGRAM("PLT.BeginToFinish_NormalLoad", begin_to_finish_all_loads);
734 case DocumentState::LINK_LOAD_NORMAL:
735 PLT_HISTOGRAM("PLT.BeginToFinishDoc_LinkLoadNormal",
736 begin_to_finish_doc);
737 PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadNormal",
738 begin_to_finish_all_loads);
740 case DocumentState::LINK_LOAD_RELOAD:
741 PLT_HISTOGRAM("PLT.BeginToFinishDoc_LinkLoadReload",
742 begin_to_finish_doc);
743 PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadReload",
744 begin_to_finish_all_loads);
746 case DocumentState::LINK_LOAD_CACHE_STALE_OK:
747 PLT_HISTOGRAM("PLT.BeginToFinishDoc_LinkLoadStaleOk",
748 begin_to_finish_doc);
749 PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadStaleOk",
750 begin_to_finish_all_loads);
752 case DocumentState::LINK_LOAD_CACHE_ONLY:
753 PLT_HISTOGRAM("PLT.BeginToFinishDoc_LinkLoadCacheOnly",
754 begin_to_finish_doc);
755 PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadCacheOnly",
756 begin_to_finish_all_loads);
762 if (data_reduction_proxy_was_used) {
763 UMA_HISTOGRAM_ENUMERATION(
764 "PLT.Abandoned_SpdyProxy", abandoned_page ? 1 : 0, 2);
765 PLT_HISTOGRAM("PLT.BeginToFinishDoc_SpdyProxy", begin_to_finish_doc);
766 PLT_HISTOGRAM("PLT.BeginToFinish_SpdyProxy", begin_to_finish_all_loads);
769 if (document_state->was_prefetcher()) {
770 PLT_HISTOGRAM("PLT.BeginToFinishDoc_ContentPrefetcher",
771 begin_to_finish_doc);
772 PLT_HISTOGRAM("PLT.BeginToFinish_ContentPrefetcher",
773 begin_to_finish_all_loads);
775 if (document_state->was_referred_by_prefetcher()) {
776 PLT_HISTOGRAM("PLT.BeginToFinishDoc_ContentPrefetcherReferrer",
777 begin_to_finish_doc);
778 PLT_HISTOGRAM("PLT.BeginToFinish_ContentPrefetcherReferrer",
779 begin_to_finish_all_loads);
781 if (document_state->was_after_preconnect_request()) {
782 PLT_HISTOGRAM("PLT.BeginToFinishDoc_AfterPreconnectRequest",
783 begin_to_finish_doc);
784 PLT_HISTOGRAM("PLT.BeginToFinish_AfterPreconnectRequest",
785 begin_to_finish_all_loads);
788 // TODO(mpcomplete): remove the extension-related histograms after we collect
789 // enough data. http://crbug.com/100411
790 const bool use_adblock_histogram =
791 ChromeContentRendererClient::IsAdblockInstalled();
792 if (use_adblock_histogram) {
793 UMA_HISTOGRAM_ENUMERATION(
794 "PLT.Abandoned_ExtensionAdblock",
795 abandoned_page ? 1 : 0, 2);
797 case DocumentState::NORMAL_LOAD:
799 "PLT.BeginToFinish_NormalLoad_ExtensionAdblock",
800 begin_to_finish_all_loads);
802 case DocumentState::LINK_LOAD_NORMAL:
804 "PLT.BeginToFinish_LinkLoadNormal_ExtensionAdblock",
805 begin_to_finish_all_loads);
807 case DocumentState::LINK_LOAD_RELOAD:
809 "PLT.BeginToFinish_LinkLoadReload_ExtensionAdblock",
810 begin_to_finish_all_loads);
812 case DocumentState::LINK_LOAD_CACHE_STALE_OK:
814 "PLT.BeginToFinish_LinkLoadStaleOk_ExtensionAdblock",
815 begin_to_finish_all_loads);
822 const bool use_adblockplus_histogram =
823 ChromeContentRendererClient::IsAdblockPlusInstalled();
824 if (use_adblockplus_histogram) {
825 UMA_HISTOGRAM_ENUMERATION(
826 "PLT.Abandoned_ExtensionAdblockPlus",
827 abandoned_page ? 1 : 0, 2);
829 case DocumentState::NORMAL_LOAD:
831 "PLT.BeginToFinish_NormalLoad_ExtensionAdblockPlus",
832 begin_to_finish_all_loads);
834 case DocumentState::LINK_LOAD_NORMAL:
836 "PLT.BeginToFinish_LinkLoadNormal_ExtensionAdblockPlus",
837 begin_to_finish_all_loads);
839 case DocumentState::LINK_LOAD_RELOAD:
841 "PLT.BeginToFinish_LinkLoadReload_ExtensionAdblockPlus",
842 begin_to_finish_all_loads);
844 case DocumentState::LINK_LOAD_CACHE_STALE_OK:
846 "PLT.BeginToFinish_LinkLoadStaleOk_ExtensionAdblockPlus",
847 begin_to_finish_all_loads);
854 const bool use_webrequest_adblock_histogram =
855 ChromeContentRendererClient::IsAdblockWithWebRequestInstalled();
856 if (use_webrequest_adblock_histogram) {
857 UMA_HISTOGRAM_ENUMERATION(
858 "PLT.Abandoned_ExtensionWebRequestAdblock",
859 abandoned_page ? 1 : 0, 2);
861 case DocumentState::NORMAL_LOAD:
863 "PLT.BeginToFinish_NormalLoad_ExtensionWebRequestAdblock",
864 begin_to_finish_all_loads);
866 case DocumentState::LINK_LOAD_NORMAL:
868 "PLT.BeginToFinish_LinkLoadNormal_ExtensionWebRequestAdblock",
869 begin_to_finish_all_loads);
871 case DocumentState::LINK_LOAD_RELOAD:
873 "PLT.BeginToFinish_LinkLoadReload_ExtensionWebRequestAdblock",
874 begin_to_finish_all_loads);
876 case DocumentState::LINK_LOAD_CACHE_STALE_OK:
878 "PLT.BeginToFinish_LinkLoadStaleOk_ExtensionWebRequestAdblock",
879 begin_to_finish_all_loads);
886 const bool use_webrequest_adblockplus_histogram =
887 ChromeContentRendererClient::
888 IsAdblockPlusWithWebRequestInstalled();
889 if (use_webrequest_adblockplus_histogram) {
890 UMA_HISTOGRAM_ENUMERATION(
891 "PLT.Abandoned_ExtensionWebRequestAdblockPlus",
892 abandoned_page ? 1 : 0, 2);
894 case DocumentState::NORMAL_LOAD:
896 "PLT.BeginToFinish_NormalLoad_ExtensionWebRequestAdblockPlus",
897 begin_to_finish_all_loads);
899 case DocumentState::LINK_LOAD_NORMAL:
901 "PLT.BeginToFinish_LinkLoadNormal_ExtensionWebRequestAdblockPlus",
902 begin_to_finish_all_loads);
904 case DocumentState::LINK_LOAD_RELOAD:
906 "PLT.BeginToFinish_LinkLoadReload_ExtensionWebRequestAdblockPlus",
907 begin_to_finish_all_loads);
909 case DocumentState::LINK_LOAD_CACHE_STALE_OK:
911 "PLT.BeginToFinish_LinkLoadStaleOk_ExtensionWebRequestAdblockPlus",
912 begin_to_finish_all_loads);
919 const bool use_webrequest_other_histogram =
920 ChromeContentRendererClient::
921 IsOtherExtensionWithWebRequestInstalled();
922 if (use_webrequest_other_histogram) {
923 UMA_HISTOGRAM_ENUMERATION(
924 "PLT.Abandoned_ExtensionWebRequestOther",
925 abandoned_page ? 1 : 0, 2);
927 case DocumentState::NORMAL_LOAD:
929 "PLT.BeginToFinish_NormalLoad_ExtensionWebRequestOther",
930 begin_to_finish_all_loads);
932 case DocumentState::LINK_LOAD_NORMAL:
934 "PLT.BeginToFinish_LinkLoadNormal_ExtensionWebRequestOther",
935 begin_to_finish_all_loads);
937 case DocumentState::LINK_LOAD_RELOAD:
939 "PLT.BeginToFinish_LinkLoadReload_ExtensionWebRequestOther",
940 begin_to_finish_all_loads);
942 case DocumentState::LINK_LOAD_CACHE_STALE_OK:
944 "PLT.BeginToFinish_LinkLoadStaleOk_ExtensionWebRequestOther",
945 begin_to_finish_all_loads);
952 // Record SpdyCwnd results.
953 if (document_state->was_fetched_via_spdy()) {
955 case DocumentState::LINK_LOAD_NORMAL:
956 PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadNormal_cwndDynamic",
957 begin_to_finish_all_loads);
958 PLT_HISTOGRAM("PLT.StartToFinish_LinkLoadNormal_cwndDynamic",
959 start_to_finish_all_loads);
960 PLT_HISTOGRAM("PLT.StartToCommit_LinkLoadNormal_cwndDynamic",
963 case DocumentState::NORMAL_LOAD:
964 PLT_HISTOGRAM("PLT.BeginToFinish_NormalLoad_cwndDynamic",
965 begin_to_finish_all_loads);
966 PLT_HISTOGRAM("PLT.StartToFinish_NormalLoad_cwndDynamic",
967 start_to_finish_all_loads);
968 PLT_HISTOGRAM("PLT.StartToCommit_NormalLoad_cwndDynamic",
976 // Record page load time and abandonment rates for proxy cases.
977 if (document_state->was_fetched_via_proxy()) {
978 if (scheme_type == URLPattern::SCHEME_HTTPS) {
979 PLT_HISTOGRAM("PLT.StartToFinish.Proxy.https", start_to_finish_all_loads);
980 UMA_HISTOGRAM_ENUMERATION("PLT.Abandoned.Proxy.https",
981 abandoned_page ? 1 : 0, 2);
983 DCHECK(scheme_type == URLPattern::SCHEME_HTTP);
984 PLT_HISTOGRAM("PLT.StartToFinish.Proxy.http", start_to_finish_all_loads);
985 UMA_HISTOGRAM_ENUMERATION("PLT.Abandoned.Proxy.http",
986 abandoned_page ? 1 : 0, 2);
989 if (scheme_type == URLPattern::SCHEME_HTTPS) {
990 PLT_HISTOGRAM("PLT.StartToFinish.NoProxy.https",
991 start_to_finish_all_loads);
992 UMA_HISTOGRAM_ENUMERATION("PLT.Abandoned.NoProxy.https",
993 abandoned_page ? 1 : 0, 2);
995 DCHECK(scheme_type == URLPattern::SCHEME_HTTP);
996 PLT_HISTOGRAM("PLT.StartToFinish.NoProxy.http",
997 start_to_finish_all_loads);
998 UMA_HISTOGRAM_ENUMERATION("PLT.Abandoned.NoProxy.http",
999 abandoned_page ? 1 : 0, 2);
1003 // Site isolation metrics.
1004 UMA_HISTOGRAM_COUNTS("SiteIsolation.PageLoadsWithCrossSiteFrameAccess",
1005 cross_origin_access_count_);
1006 UMA_HISTOGRAM_COUNTS("SiteIsolation.PageLoadsWithSameSiteFrameAccess",
1007 same_origin_access_count_);
1009 // Log the PLT to the info log.
1010 LogPageLoadTime(document_state, frame->dataSource());
1012 // Since there are currently no guarantees that renderer histograms will be
1013 // sent to the browser, we initiate a PostTask here to be sure that we send
1014 // the histograms we generated. Without this call, pages that don't have an
1015 // on-close-handler might generate data that is lost when the renderer is
1016 // shutdown abruptly (perchance because the user closed the tab).
1017 // TODO(jar) BUG=33233: This needs to be moved to a PostDelayedTask, and it
1018 // should post when the onload is complete, so that it doesn't interfere with
1020 content::RenderThread::Get()->UpdateHistograms(
1021 content::kHistogramSynchronizerReservedSequenceNumber);
1024 void PageLoadHistograms::ResetCrossFramePropertyAccess() {
1025 cross_origin_access_count_ = 0;
1026 same_origin_access_count_ = 0;
1029 void PageLoadHistograms::FrameWillClose(WebFrame* frame) {
1033 void PageLoadHistograms::ClosePage() {
1034 // TODO(davemoore) This code should be removed once willClose() gets
1035 // called when a page is destroyed. page_load_histograms_.Dump() is safe
1036 // to call multiple times for the same frame, but it will simplify things.
1037 Dump(render_view()->GetWebView()->mainFrame());
1038 ResetCrossFramePropertyAccess();
1041 void PageLoadHistograms::LogPageLoadTime(const DocumentState* document_state,
1042 const WebDataSource* ds) const {
1043 // Because this function gets called on every page load,
1044 // take extra care to optimize it away if logging is turned off.
1045 if (logging::LOG_INFO < logging::GetMinLogLevel())
1048 DCHECK(document_state);
1050 GURL url(ds->request().url());
1051 Time start = document_state->start_load_time();
1052 Time finish = document_state->finish_load_time();
1053 // TODO(mbelshe): should we log more stats?
1054 VLOG(1) << "PLT: " << (finish - start).InMilliseconds() << "ms "