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 "net/http/http_response_headers.h"
28 #include "third_party/WebKit/public/platform/WebURLRequest.h"
29 #include "third_party/WebKit/public/platform/WebURLResponse.h"
30 #include "third_party/WebKit/public/web/WebDocument.h"
31 #include "third_party/WebKit/public/web/WebFrame.h"
32 #include "third_party/WebKit/public/web/WebPerformance.h"
33 #include "third_party/WebKit/public/web/WebView.h"
36 using blink::WebDataSource;
37 using blink::WebFrame;
38 using blink::WebPerformance;
39 using blink::WebString;
41 using base::TimeDelta;
42 using content::DocumentState;
44 const size_t kPLTCount = 100;
48 // ID indicating that no GWS-Chrome joint experiment is active.
49 const int kNoExperiment = 0;
51 // Max ID of GWS-Chrome joint experiment. If you change this value, please
52 // update PLT_HISTOGRAM_WITH_GWS_VARIANT accordingly.
53 const int kMaxExperimentID = 20;
56 return TimeDelta::FromMilliseconds(10);
59 return TimeDelta::FromMinutes(10);
62 // This function corresponds to PLT_HISTOGRAM macro invocation without caching.
63 // Use this for PLT histograms with dynamically generated names, which
64 // otherwise can't use the caching PLT_HISTOGRAM macro without code duplication.
65 void PltHistogramWithNoMacroCaching(const std::string& name,
66 const TimeDelta& sample) {
67 // The parameters should exacly match the parameters in
68 // UMA_HISTOGRAM_CUSTOM_TIMES macro.
69 base::HistogramBase* histogram_pointer = base::Histogram::FactoryTimeGet(
70 name, kPLTMin(), kPLTMax(), kPLTCount,
71 base::HistogramBase::kUmaTargetedHistogramFlag);
72 histogram_pointer->AddTime(sample);
75 // Various preview applicability states.
76 enum GwsPreviewState {
78 // Instant search clicks [not] applied, data reduction proxy used,
81 // Instant search clicks applied, data reduction proxy [not] used,
84 // Instant search clicks applied, data reduction proxy used,
85 // [not] from web search
89 // This records UMA corresponding to the PLT_HISTOGRAM macro without caching.
90 void PltHistogramWithGwsPreview(const char* name,
91 const TimeDelta& sample,
92 GwsPreviewState preview_state,
93 int preview_experiment_id) {
94 std::string preview_suffix;
95 switch (preview_state) {
96 case PREVIEW_WAS_SHOWN:
97 preview_suffix = "_WithPreview";
100 preview_suffix = "_Preview";
102 case PREVIEW_NOT_USED:
103 preview_suffix = "_NoPreview";
108 PltHistogramWithNoMacroCaching(name + preview_suffix, sample);
110 if (preview_experiment_id != kNoExperiment) {
111 std::string name_with_experiment_id = base::StringPrintf(
112 "%s%s_Experiment%d", name, preview_suffix.c_str(),
113 preview_experiment_id);
114 PltHistogramWithNoMacroCaching(name_with_experiment_id, sample);
118 #define PLT_HISTOGRAM(name, sample) \
119 UMA_HISTOGRAM_CUSTOM_TIMES(name, sample, kPLTMin(), kPLTMax(), kPLTCount);
121 #define PLT_HISTOGRAM_WITH_GWS_VARIANT( \
122 name, sample, came_from_websearch, websearch_chrome_joint_experiment_id, \
123 preview_state, preview_experiment_id) { \
124 PLT_HISTOGRAM(name, sample); \
125 if (came_from_websearch) { \
126 PLT_HISTOGRAM(base::StringPrintf("%s_FromGWS", name), sample) \
127 if (websearch_chrome_joint_experiment_id != kNoExperiment) { \
128 std::string name_with_experiment_id = base::StringPrintf( \
129 "%s_FromGWS_Experiment%d", \
130 name, websearch_chrome_joint_experiment_id); \
131 PltHistogramWithNoMacroCaching(name_with_experiment_id, sample); \
134 PltHistogramWithGwsPreview(name, sample, preview_state, \
135 preview_experiment_id); \
138 // In addition to PLT_HISTOGRAM, add the *_DataReductionProxy variant
139 // conditionally. This macro runs only in one thread.
140 #define PLT_HISTOGRAM_DRP(name, sample, data_reduction_proxy_was_used) \
142 static base::HistogramBase* counter(NULL); \
143 static base::HistogramBase* drp_counter(NULL); \
145 DCHECK(drp_counter == NULL); \
146 counter = base::Histogram::FactoryTimeGet( \
147 name, kPLTMin(), kPLTMax(), kPLTCount, \
148 base::Histogram::kUmaTargetedHistogramFlag); \
150 counter->AddTime(sample); \
151 if (!data_reduction_proxy_was_used) break; \
152 if (!drp_counter) { \
153 drp_counter = base::Histogram::FactoryTimeGet( \
154 std::string(name) + "_DataReductionProxy", \
155 kPLTMin(), kPLTMax(), kPLTCount, \
156 base::Histogram::kUmaTargetedHistogramFlag); \
158 drp_counter->AddTime(sample); \
161 // Returns the scheme type of the given URL if its type is one for which we
162 // dump page load histograms. Otherwise returns NULL.
163 URLPattern::SchemeMasks GetSupportedSchemeType(const GURL& url) {
164 if (url.SchemeIs("http"))
165 return URLPattern::SCHEME_HTTP;
166 else if (url.SchemeIs("https"))
167 return URLPattern::SCHEME_HTTPS;
168 return static_cast<URLPattern::SchemeMasks>(0);
171 // Helper function to check for string in 'via' header. Returns true if
172 // |via_value| is one of the values listed in the Via header and the response
173 // was fetched via a proxy.
174 bool ViaHeaderContains(WebFrame* frame, const std::string& via_value) {
175 const char kViaHeaderName[] = "Via";
177 DocumentState* document_state =
178 DocumentState::FromDataSource(frame->dataSource());
179 if (!document_state->was_fetched_via_proxy())
182 std::vector<std::string> values;
183 // Multiple via headers have already been coalesced and hence each value
184 // separated by a comma corresponds to a proxy. The value added by a proxy is
185 // not expected to contain any commas.
186 // Example., Via: 1.0 Compression proxy, 1.1 Google Instant Proxy Preview
188 frame->dataSource()->response().httpHeaderField(kViaHeaderName).utf8(),
190 return std::find(values.begin(), values.end(), via_value) != values.end();
193 // Returns true if the data reduction proxy was used. Note, this function will
194 // produce a false positive if a page is fetched using SPDY and using a proxy,
195 // and the data reduction proxy's via value is added to the Via header.
196 // TODO(bengr): Plumb the hostname of the proxy and check if it matches
197 // |SPDY_PROXY_AUTH_ORIGIN|.
198 bool DataReductionProxyWasUsed(WebFrame* frame) {
199 DocumentState* document_state =
200 DocumentState::FromDataSource(frame->dataSource());
201 if (!document_state->was_fetched_via_proxy())
204 std::string via_header =
205 base::UTF16ToUTF8(frame->dataSource()->response().httpHeaderField("Via"));
207 if (via_header.empty())
209 std::string headers = "HTTP/1.1 200 OK\nVia: " + via_header + "\n\n";
210 // Produce raw headers, expected by the |HttpResponseHeaders| constructor.
211 std::replace(headers.begin(), headers.end(), '\n', '\0');
212 scoped_refptr<net::HttpResponseHeaders> response_headers(
213 new net::HttpResponseHeaders(headers));
214 return response_headers->IsDataReductionProxyResponse();
217 // Returns true if the provided URL is a referrer string that came from
218 // a Google Web Search results page. This is a little non-deterministic
219 // because desktop and mobile websearch differ and sometimes just provide
220 // http://www.google.com/ as the referrer. In the case of /url we can be sure
221 // that it came from websearch but we will be generous and allow for cases
222 // where a non-Google URL was provided a bare Google URL as a referrer.
223 // The domain validation matches the code used by the prerenderer for similar
225 // TODO(pmeenan): Remove the fuzzy logic when the referrer is reliable
226 bool IsFromGoogleSearchResult(const GURL& url, const GURL& referrer) {
227 if (!StartsWithASCII(referrer.host(), "www.google.", true))
229 if (StartsWithASCII(referrer.path(), "/url", true))
231 bool is_possible_search_referrer =
232 referrer.path().empty() ||
233 referrer.path() == "/" ||
234 StartsWithASCII(referrer.path(), "/search", true) ||
235 StartsWithASCII(referrer.path(), "/webhp", true);
236 if (is_possible_search_referrer &&
237 !StartsWithASCII(url.host(), "www.google", true))
242 // Extracts a Google Web Search and Chrome joint experiment ID from a referrer
243 // that came from a Google Web Search results page. An experiment ID is embedded
244 // in a query string as a "gcjeid=" parameter value.
245 int GetQueryStringBasedExperiment(const GURL& referrer) {
247 if (!net::GetValueForKeyInQuery(referrer, "gcjeid", &value))
248 return kNoExperiment;
251 if (!base::StringToInt(value, &experiment_id))
252 return kNoExperiment;
253 if (0 < experiment_id && experiment_id <= kMaxExperimentID)
254 return experiment_id;
255 return kNoExperiment;
258 // Returns preview state by looking at url and referer url.
259 void GetPreviewState(WebFrame* frame,
260 bool came_from_websearch,
261 bool data_reduction_proxy_was_used,
262 GwsPreviewState* preview_state,
263 int* preview_experiment_id) {
264 // Conditions for GWS preview are,
265 // 1. Data reduction proxy was used.
266 // Determine the preview state (PREVIEW, PREVIEW_WAS_SHOWN, PREVIEW_NOT_USED)
267 // by inspecting the Via header.
268 if (data_reduction_proxy_was_used) {
269 if (came_from_websearch) {
270 *preview_state = ViaHeaderContains(
272 "1.1 Google Instant Proxy Preview") ? PREVIEW : PREVIEW_NOT_USED;
273 } else if (ViaHeaderContains(frame, "1.1 Google Instant Proxy")) {
274 *preview_state = PREVIEW_WAS_SHOWN;
275 *preview_experiment_id = GetQueryStringBasedExperiment(
276 GURL(frame->document().referrer()));
281 void DumpPerformanceTiming(const WebPerformance& performance,
282 DocumentState* document_state,
283 bool data_reduction_proxy_was_used,
284 bool came_from_websearch,
285 int websearch_chrome_joint_experiment_id,
286 GwsPreviewState preview_state,
287 int preview_experiment_id) {
288 Time request = document_state->request_time();
290 Time navigation_start = Time::FromDoubleT(performance.navigationStart());
291 Time redirect_start = Time::FromDoubleT(performance.redirectStart());
292 Time redirect_end = Time::FromDoubleT(performance.redirectEnd());
293 Time fetch_start = Time::FromDoubleT(performance.fetchStart());
294 Time domain_lookup_start = Time::FromDoubleT(performance.domainLookupStart());
295 Time domain_lookup_end = Time::FromDoubleT(performance.domainLookupEnd());
296 Time connect_start = Time::FromDoubleT(performance.connectStart());
297 Time connect_end = Time::FromDoubleT(performance.connectEnd());
298 Time request_start = Time::FromDoubleT(performance.requestStart());
299 Time response_start = Time::FromDoubleT(performance.responseStart());
300 Time response_end = Time::FromDoubleT(performance.responseEnd());
301 Time dom_loading = Time::FromDoubleT(performance.domLoading());
302 Time dom_interactive = Time::FromDoubleT(performance.domInteractive());
303 Time dom_content_loaded_start =
304 Time::FromDoubleT(performance.domContentLoadedEventStart());
305 Time dom_content_loaded_end =
306 Time::FromDoubleT(performance.domContentLoadedEventEnd());
307 Time load_event_start = Time::FromDoubleT(performance.loadEventStart());
308 Time load_event_end = Time::FromDoubleT(performance.loadEventEnd());
309 Time begin = (request.is_null() ? navigation_start : request_start);
311 DCHECK(!navigation_start.is_null());
313 // It is possible for a document to have navigation_start time, but no
314 // request_start. An example is doing a window.open, which synchronously
315 // loads "about:blank", then using document.write add a meta http-equiv
316 // refresh tag, which causes a navigation. In such case, we will arrive at
317 // this function with no request/response timing data and identical load
318 // start/end values. Avoid logging this case, as it doesn't add any
319 // meaningful information to the histogram.
320 if (request_start.is_null())
323 // TODO(dominich): Investigate conditions under which |load_event_start| and
324 // |load_event_end| may be NULL as in the non-PT_ case below. Examples in
325 // http://crbug.com/112006.
326 // DCHECK(!load_event_start.is_null());
327 // DCHECK(!load_event_end.is_null());
329 if (document_state->web_timing_histograms_recorded())
331 document_state->set_web_timing_histograms_recorded(true);
333 if (!redirect_start.is_null() && !redirect_end.is_null()) {
334 PLT_HISTOGRAM_DRP("PLT.NT_Redirect", redirect_end - redirect_start,
335 data_reduction_proxy_was_used);
337 "PLT.NT_DelayBeforeFetchRedirect",
338 (fetch_start - navigation_start) - (redirect_end - redirect_start),
339 data_reduction_proxy_was_used);
341 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeFetch",
342 fetch_start - navigation_start,
343 data_reduction_proxy_was_used);
345 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeDomainLookup",
346 domain_lookup_start - fetch_start,
347 data_reduction_proxy_was_used);
348 PLT_HISTOGRAM_DRP("PLT.NT_DomainLookup",
349 domain_lookup_end - domain_lookup_start,
350 data_reduction_proxy_was_used);
351 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeConnect",
352 connect_start - domain_lookup_end,
353 data_reduction_proxy_was_used);
354 PLT_HISTOGRAM_DRP("PLT.NT_Connect", connect_end - connect_start,
355 data_reduction_proxy_was_used);
356 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeRequest",
357 request_start - connect_end,
358 data_reduction_proxy_was_used);
359 PLT_HISTOGRAM_DRP("PLT.NT_Request", response_start - request_start,
360 data_reduction_proxy_was_used);
361 PLT_HISTOGRAM_DRP("PLT.NT_Response", response_end - response_start,
362 data_reduction_proxy_was_used);
364 if (!dom_loading.is_null()) {
365 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeDomLoading",
366 dom_loading - response_start,
367 data_reduction_proxy_was_used);
369 if (!dom_interactive.is_null() && !dom_loading.is_null()) {
370 PLT_HISTOGRAM_DRP("PLT.NT_DomLoading",
371 dom_interactive - dom_loading,
372 data_reduction_proxy_was_used);
374 if (!dom_content_loaded_start.is_null() && !dom_interactive.is_null()) {
375 PLT_HISTOGRAM_DRP("PLT.NT_DomInteractive",
376 dom_content_loaded_start - dom_interactive,
377 data_reduction_proxy_was_used);
379 if (!dom_content_loaded_start.is_null() &&
380 !dom_content_loaded_end.is_null() ) {
381 PLT_HISTOGRAM_DRP("PLT.NT_DomContentLoaded",
382 dom_content_loaded_end - dom_content_loaded_start,
383 data_reduction_proxy_was_used);
385 if (!dom_content_loaded_end.is_null() && !load_event_start.is_null()) {
386 PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeLoadEvent",
387 load_event_start - dom_content_loaded_end,
388 data_reduction_proxy_was_used);
391 // TODO(simonjam): There is no way to distinguish between abandonment and
392 // intentional Javascript navigation before the load event fires.
393 // TODO(dominich): Load type breakdown
394 if (!load_event_start.is_null()) {
395 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_BeginToFinishDoc",
396 load_event_start - begin,
398 websearch_chrome_joint_experiment_id,
399 preview_state, preview_experiment_id);
400 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_CommitToFinishDoc",
401 load_event_start - response_start,
403 websearch_chrome_joint_experiment_id,
404 preview_state, preview_experiment_id);
405 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_RequestToFinishDoc",
406 load_event_start - navigation_start,
408 websearch_chrome_joint_experiment_id,
409 preview_state, preview_experiment_id);
410 if (data_reduction_proxy_was_used) {
411 PLT_HISTOGRAM("PLT.PT_BeginToFinishDoc_DataReductionProxy",
412 load_event_start - begin);
413 PLT_HISTOGRAM("PLT.PT_CommitToFinishDoc_DataReductionProxy",
414 load_event_start - response_start);
415 PLT_HISTOGRAM("PLT.PT_RequestToFinishDoc_DataReductionProxy",
416 load_event_start - navigation_start);
419 if (!load_event_end.is_null()) {
420 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_BeginToFinish",
421 load_event_end - begin,
423 websearch_chrome_joint_experiment_id,
424 preview_state, preview_experiment_id);
425 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_CommitToFinish",
426 load_event_end - response_start,
428 websearch_chrome_joint_experiment_id,
429 preview_state, preview_experiment_id);
430 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_RequestToFinish",
431 load_event_end - navigation_start,
433 websearch_chrome_joint_experiment_id,
434 preview_state, preview_experiment_id);
435 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_StartToFinish",
436 load_event_end - request_start,
438 websearch_chrome_joint_experiment_id,
439 preview_state, preview_experiment_id);
440 if (data_reduction_proxy_was_used) {
441 PLT_HISTOGRAM("PLT.PT_BeginToFinish_DataReductionProxy",
442 load_event_end - begin);
443 PLT_HISTOGRAM("PLT.PT_CommitToFinish_DataReductionProxy",
444 load_event_end - response_start);
445 PLT_HISTOGRAM("PLT.PT_RequestToFinish_DataReductionProxy",
446 load_event_end - navigation_start);
447 PLT_HISTOGRAM("PLT.PT_StartToFinish_DataReductionProxy",
448 load_event_end - request_start);
451 if (!load_event_start.is_null() && !load_event_end.is_null()) {
452 PLT_HISTOGRAM("PLT.PT_FinishDocToFinish",
453 load_event_end - load_event_start);
454 PLT_HISTOGRAM_DRP("PLT.NT_LoadEvent",
455 load_event_end - load_event_start,
456 data_reduction_proxy_was_used);
458 if (data_reduction_proxy_was_used)
459 PLT_HISTOGRAM("PLT.PT_FinishDocToFinish_DataReductionProxy",
460 load_event_end - load_event_start);
462 if (!dom_content_loaded_start.is_null()) {
463 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_RequestToDomContentLoaded",
464 dom_content_loaded_start - navigation_start,
466 websearch_chrome_joint_experiment_id,
467 preview_state, preview_experiment_id);
468 if (data_reduction_proxy_was_used)
469 PLT_HISTOGRAM("PLT.PT_RequestToDomContentLoaded_DataReductionProxy",
470 dom_content_loaded_start - navigation_start);
472 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_BeginToCommit",
473 response_start - begin,
475 websearch_chrome_joint_experiment_id,
476 preview_state, preview_experiment_id);
477 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_RequestToStart",
478 request_start - navigation_start,
480 websearch_chrome_joint_experiment_id,
481 preview_state, preview_experiment_id);
482 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_StartToCommit",
483 response_start - request_start,
485 websearch_chrome_joint_experiment_id,
486 preview_state, preview_experiment_id);
487 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_RequestToCommit",
488 response_start - navigation_start,
490 websearch_chrome_joint_experiment_id,
491 preview_state, preview_experiment_id);
492 if (data_reduction_proxy_was_used) {
493 PLT_HISTOGRAM("PLT.PT_BeginToCommit_DataReductionProxy",
494 response_start - begin);
495 PLT_HISTOGRAM("PLT.PT_RequestToStart_DataReductionProxy",
496 request_start - navigation_start);
497 PLT_HISTOGRAM("PLT.PT_StartToCommit_DataReductionProxy",
498 response_start - request_start);
499 PLT_HISTOGRAM("PLT.PT_RequestToCommit_DataReductionProxy",
500 response_start - navigation_start);
504 enum MissingStartType {
506 COMMIT_MISSING = 0x2,
507 NAV_START_MISSING = 0x4,
508 MISSING_START_TYPE_MAX = 0x8
512 FINISH_DOC_MISSING = 0x1,
513 FINISH_ALL_LOADS_MISSING = 0x2,
514 LOAD_EVENT_START_MISSING = 0x4,
515 LOAD_EVENT_END_MISSING = 0x8,
516 ABANDON_TYPE_MAX = 0x10
521 PageLoadHistograms::PageLoadHistograms(content::RenderView* render_view)
522 : content::RenderViewObserver(render_view),
523 cross_origin_access_count_(0),
524 same_origin_access_count_(0) {
527 void PageLoadHistograms::Dump(WebFrame* frame) {
528 // We only dump histograms for main frames.
529 // In the future, it may be interesting to tag subframes and dump them too.
530 if (!frame || frame->parent())
533 // Only dump for supported schemes.
534 URLPattern::SchemeMasks scheme_type =
535 GetSupportedSchemeType(frame->document().url());
536 if (scheme_type == 0)
539 // Ignore multipart requests.
540 if (frame->dataSource()->response().isMultipartPayload())
543 DocumentState* document_state =
544 DocumentState::FromDataSource(frame->dataSource());
546 bool data_reduction_proxy_was_used = DataReductionProxyWasUsed(frame);
547 bool came_from_websearch =
548 IsFromGoogleSearchResult(frame->document().url(),
549 GURL(frame->document().referrer()));
550 int websearch_chrome_joint_experiment_id = kNoExperiment;
551 if (came_from_websearch) {
552 websearch_chrome_joint_experiment_id =
553 GetQueryStringBasedExperiment(GURL(frame->document().referrer()));
556 GwsPreviewState preview_state = PREVIEW_NONE;
557 int preview_experiment_id = websearch_chrome_joint_experiment_id;
558 GetPreviewState(frame, came_from_websearch, data_reduction_proxy_was_used,
559 &preview_state, &preview_experiment_id);
561 // Times based on the Web Timing metrics.
562 // http://www.w3.org/TR/navigation-timing/
563 // TODO(tonyg, jar): We are in the process of vetting these metrics against
564 // the existing ones. Once we understand any differences, we will standardize
565 // on a single set of metrics.
566 DumpPerformanceTiming(frame->performance(), document_state,
567 data_reduction_proxy_was_used,
569 websearch_chrome_joint_experiment_id,
570 preview_state, preview_experiment_id);
572 // If we've already dumped, do nothing.
573 // This simple bool works because we only dump for the main frame.
574 if (document_state->load_histograms_recorded())
577 // Collect measurement times.
578 Time start = document_state->start_load_time();
579 Time commit = document_state->commit_load_time();
581 // TODO(tonyg, jar): Start can be missing after an in-document navigation and
582 // possibly other cases like a very premature abandonment of the page.
583 // The PLT.MissingStart histogram should help us troubleshoot and then we can
585 Time navigation_start =
586 Time::FromDoubleT(frame->performance().navigationStart());
587 int missing_start_type = 0;
588 missing_start_type |= start.is_null() ? START_MISSING : 0;
589 missing_start_type |= commit.is_null() ? COMMIT_MISSING : 0;
590 missing_start_type |= navigation_start.is_null() ? NAV_START_MISSING : 0;
591 UMA_HISTOGRAM_ENUMERATION("PLT.MissingStart", missing_start_type,
592 MISSING_START_TYPE_MAX);
593 if (missing_start_type)
596 // We properly handle null values for the next 3 variables.
597 Time request = document_state->request_time();
598 Time first_paint = document_state->first_paint_time();
599 Time first_paint_after_load = document_state->first_paint_after_load_time();
600 Time finish_doc = document_state->finish_document_load_time();
601 Time finish_all_loads = document_state->finish_load_time();
603 // TODO(tonyg, jar): We suspect a bug in abandonment counting, this temporary
604 // histogram should help us to troubleshoot.
605 Time load_event_start =
606 Time::FromDoubleT(frame->performance().loadEventStart());
607 Time load_event_end = Time::FromDoubleT(frame->performance().loadEventEnd());
608 int abandon_type = 0;
609 abandon_type |= finish_doc.is_null() ? FINISH_DOC_MISSING : 0;
610 abandon_type |= finish_all_loads.is_null() ? FINISH_ALL_LOADS_MISSING : 0;
611 abandon_type |= load_event_start.is_null() ? LOAD_EVENT_START_MISSING : 0;
612 abandon_type |= load_event_end.is_null() ? LOAD_EVENT_END_MISSING : 0;
613 UMA_HISTOGRAM_ENUMERATION("PLT.AbandonType", abandon_type, ABANDON_TYPE_MAX);
615 // Handle case where user hits "stop" or "back" before loading completely.
616 bool abandoned_page = finish_doc.is_null();
617 if (abandoned_page) {
618 finish_doc = Time::Now();
619 document_state->set_finish_document_load_time(finish_doc);
622 // TODO(jar): We should really discriminate the definition of "abandon" more
623 // finely. We should have:
624 // abandon_before_document_loaded
625 // abandon_before_onload_fired
627 if (finish_all_loads.is_null()) {
628 finish_all_loads = Time::Now();
629 document_state->set_finish_load_time(finish_all_loads);
631 DCHECK(!abandoned_page); // How can the doc have finished but not the page?
633 return; // Don't try to record a stat which is broken.
636 document_state->set_load_histograms_recorded(true);
638 // Note: Client side redirects will have no request time.
639 Time begin = request.is_null() ? start : request;
640 TimeDelta begin_to_finish_doc = finish_doc - begin;
641 TimeDelta begin_to_finish_all_loads = finish_all_loads - begin;
642 TimeDelta start_to_finish_all_loads = finish_all_loads - start;
643 TimeDelta start_to_commit = commit - start;
645 DocumentState::LoadType load_type = document_state->load_type();
647 // The above code sanitized all values of times, in preparation for creating
648 // actual histograms. The remainder of this code could be run at destructor
649 // time for the document_state, since all data is intact.
651 // Aggregate PLT data across all link types.
652 UMA_HISTOGRAM_ENUMERATION("PLT.Abandoned", abandoned_page ? 1 : 0, 2);
653 UMA_HISTOGRAM_ENUMERATION("PLT.LoadType", load_type,
654 DocumentState::kLoadTypeMax);
655 PLT_HISTOGRAM("PLT.StartToCommit", start_to_commit);
656 PLT_HISTOGRAM("PLT.CommitToFinishDoc", finish_doc - commit);
657 PLT_HISTOGRAM("PLT.FinishDocToFinish", finish_all_loads - finish_doc);
658 PLT_HISTOGRAM("PLT.BeginToCommit", commit - begin);
659 PLT_HISTOGRAM("PLT.StartToFinish", start_to_finish_all_loads);
660 if (!request.is_null()) {
661 PLT_HISTOGRAM("PLT.RequestToStart", start - request);
662 PLT_HISTOGRAM("PLT.RequestToFinish", finish_all_loads - request);
664 PLT_HISTOGRAM("PLT.CommitToFinish", finish_all_loads - commit);
666 scoped_ptr<TimeDelta> begin_to_first_paint;
667 scoped_ptr<TimeDelta> commit_to_first_paint;
668 if (!first_paint.is_null()) {
669 // 'first_paint' can be before 'begin' for an unknown reason.
670 // See bug http://crbug.com/125273 for details.
671 if (begin <= first_paint) {
672 begin_to_first_paint.reset(new TimeDelta(first_paint - begin));
673 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.BeginToFirstPaint",
674 *begin_to_first_paint,
676 websearch_chrome_joint_experiment_id,
677 preview_state, preview_experiment_id);
679 DCHECK(commit <= first_paint);
680 commit_to_first_paint.reset(new TimeDelta(first_paint - commit));
681 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.CommitToFirstPaint",
682 *commit_to_first_paint,
684 websearch_chrome_joint_experiment_id,
685 preview_state, preview_experiment_id);
687 if (!first_paint_after_load.is_null()) {
688 // 'first_paint_after_load' can be before 'begin' for an unknown reason.
689 // See bug http://crbug.com/125273 for details.
690 if (begin <= first_paint_after_load) {
691 PLT_HISTOGRAM("PLT.BeginToFirstPaintAfterLoad",
692 first_paint_after_load - begin);
694 DCHECK(commit <= first_paint_after_load);
695 PLT_HISTOGRAM("PLT.CommitToFirstPaintAfterLoad",
696 first_paint_after_load - commit);
697 DCHECK(finish_all_loads <= first_paint_after_load);
698 PLT_HISTOGRAM("PLT.FinishToFirstPaintAfterLoad",
699 first_paint_after_load - finish_all_loads);
701 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.BeginToFinishDoc", begin_to_finish_doc,
703 websearch_chrome_joint_experiment_id,
704 preview_state, preview_experiment_id);
705 PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.BeginToFinish", begin_to_finish_all_loads,
707 websearch_chrome_joint_experiment_id,
708 preview_state, preview_experiment_id);
710 // Load type related histograms.
712 case DocumentState::UNDEFINED_LOAD:
713 PLT_HISTOGRAM("PLT.BeginToFinishDoc_UndefLoad", begin_to_finish_doc);
714 PLT_HISTOGRAM("PLT.BeginToFinish_UndefLoad", begin_to_finish_all_loads);
716 case DocumentState::RELOAD:
717 PLT_HISTOGRAM("PLT.BeginToFinishDoc_Reload", begin_to_finish_doc);
718 PLT_HISTOGRAM("PLT.BeginToFinish_Reload", begin_to_finish_all_loads);
720 case DocumentState::HISTORY_LOAD:
721 PLT_HISTOGRAM("PLT.BeginToFinishDoc_HistoryLoad", begin_to_finish_doc);
722 PLT_HISTOGRAM("PLT.BeginToFinish_HistoryLoad", begin_to_finish_all_loads);
724 case DocumentState::NORMAL_LOAD:
725 PLT_HISTOGRAM("PLT.BeginToFinishDoc_NormalLoad", begin_to_finish_doc);
726 PLT_HISTOGRAM("PLT.BeginToFinish_NormalLoad", begin_to_finish_all_loads);
728 case DocumentState::LINK_LOAD_NORMAL:
729 PLT_HISTOGRAM("PLT.BeginToFinishDoc_LinkLoadNormal",
730 begin_to_finish_doc);
731 PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadNormal",
732 begin_to_finish_all_loads);
734 case DocumentState::LINK_LOAD_RELOAD:
735 PLT_HISTOGRAM("PLT.BeginToFinishDoc_LinkLoadReload",
736 begin_to_finish_doc);
737 PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadReload",
738 begin_to_finish_all_loads);
740 case DocumentState::LINK_LOAD_CACHE_STALE_OK:
741 PLT_HISTOGRAM("PLT.BeginToFinishDoc_LinkLoadStaleOk",
742 begin_to_finish_doc);
743 PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadStaleOk",
744 begin_to_finish_all_loads);
746 case DocumentState::LINK_LOAD_CACHE_ONLY:
747 PLT_HISTOGRAM("PLT.BeginToFinishDoc_LinkLoadCacheOnly",
748 begin_to_finish_doc);
749 PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadCacheOnly",
750 begin_to_finish_all_loads);
756 if (data_reduction_proxy_was_used) {
757 UMA_HISTOGRAM_ENUMERATION(
758 "PLT.Abandoned_SpdyProxy", abandoned_page ? 1 : 0, 2);
759 PLT_HISTOGRAM("PLT.BeginToFinishDoc_SpdyProxy", begin_to_finish_doc);
760 PLT_HISTOGRAM("PLT.BeginToFinish_SpdyProxy", begin_to_finish_all_loads);
763 if (document_state->was_prefetcher()) {
764 PLT_HISTOGRAM("PLT.BeginToFinishDoc_ContentPrefetcher",
765 begin_to_finish_doc);
766 PLT_HISTOGRAM("PLT.BeginToFinish_ContentPrefetcher",
767 begin_to_finish_all_loads);
769 if (document_state->was_referred_by_prefetcher()) {
770 PLT_HISTOGRAM("PLT.BeginToFinishDoc_ContentPrefetcherReferrer",
771 begin_to_finish_doc);
772 PLT_HISTOGRAM("PLT.BeginToFinish_ContentPrefetcherReferrer",
773 begin_to_finish_all_loads);
775 if (document_state->was_after_preconnect_request()) {
776 PLT_HISTOGRAM("PLT.BeginToFinishDoc_AfterPreconnectRequest",
777 begin_to_finish_doc);
778 PLT_HISTOGRAM("PLT.BeginToFinish_AfterPreconnectRequest",
779 begin_to_finish_all_loads);
782 // TODO(mpcomplete): remove the extension-related histograms after we collect
783 // enough data. http://crbug.com/100411
784 const bool use_adblock_histogram =
785 ChromeContentRendererClient::IsAdblockInstalled();
786 if (use_adblock_histogram) {
787 UMA_HISTOGRAM_ENUMERATION(
788 "PLT.Abandoned_ExtensionAdblock",
789 abandoned_page ? 1 : 0, 2);
791 case DocumentState::NORMAL_LOAD:
793 "PLT.BeginToFinish_NormalLoad_ExtensionAdblock",
794 begin_to_finish_all_loads);
796 case DocumentState::LINK_LOAD_NORMAL:
798 "PLT.BeginToFinish_LinkLoadNormal_ExtensionAdblock",
799 begin_to_finish_all_loads);
801 case DocumentState::LINK_LOAD_RELOAD:
803 "PLT.BeginToFinish_LinkLoadReload_ExtensionAdblock",
804 begin_to_finish_all_loads);
806 case DocumentState::LINK_LOAD_CACHE_STALE_OK:
808 "PLT.BeginToFinish_LinkLoadStaleOk_ExtensionAdblock",
809 begin_to_finish_all_loads);
816 const bool use_adblockplus_histogram =
817 ChromeContentRendererClient::IsAdblockPlusInstalled();
818 if (use_adblockplus_histogram) {
819 UMA_HISTOGRAM_ENUMERATION(
820 "PLT.Abandoned_ExtensionAdblockPlus",
821 abandoned_page ? 1 : 0, 2);
823 case DocumentState::NORMAL_LOAD:
825 "PLT.BeginToFinish_NormalLoad_ExtensionAdblockPlus",
826 begin_to_finish_all_loads);
828 case DocumentState::LINK_LOAD_NORMAL:
830 "PLT.BeginToFinish_LinkLoadNormal_ExtensionAdblockPlus",
831 begin_to_finish_all_loads);
833 case DocumentState::LINK_LOAD_RELOAD:
835 "PLT.BeginToFinish_LinkLoadReload_ExtensionAdblockPlus",
836 begin_to_finish_all_loads);
838 case DocumentState::LINK_LOAD_CACHE_STALE_OK:
840 "PLT.BeginToFinish_LinkLoadStaleOk_ExtensionAdblockPlus",
841 begin_to_finish_all_loads);
848 const bool use_webrequest_adblock_histogram =
849 ChromeContentRendererClient::IsAdblockWithWebRequestInstalled();
850 if (use_webrequest_adblock_histogram) {
851 UMA_HISTOGRAM_ENUMERATION(
852 "PLT.Abandoned_ExtensionWebRequestAdblock",
853 abandoned_page ? 1 : 0, 2);
855 case DocumentState::NORMAL_LOAD:
857 "PLT.BeginToFinish_NormalLoad_ExtensionWebRequestAdblock",
858 begin_to_finish_all_loads);
860 case DocumentState::LINK_LOAD_NORMAL:
862 "PLT.BeginToFinish_LinkLoadNormal_ExtensionWebRequestAdblock",
863 begin_to_finish_all_loads);
865 case DocumentState::LINK_LOAD_RELOAD:
867 "PLT.BeginToFinish_LinkLoadReload_ExtensionWebRequestAdblock",
868 begin_to_finish_all_loads);
870 case DocumentState::LINK_LOAD_CACHE_STALE_OK:
872 "PLT.BeginToFinish_LinkLoadStaleOk_ExtensionWebRequestAdblock",
873 begin_to_finish_all_loads);
880 const bool use_webrequest_adblockplus_histogram =
881 ChromeContentRendererClient::
882 IsAdblockPlusWithWebRequestInstalled();
883 if (use_webrequest_adblockplus_histogram) {
884 UMA_HISTOGRAM_ENUMERATION(
885 "PLT.Abandoned_ExtensionWebRequestAdblockPlus",
886 abandoned_page ? 1 : 0, 2);
888 case DocumentState::NORMAL_LOAD:
890 "PLT.BeginToFinish_NormalLoad_ExtensionWebRequestAdblockPlus",
891 begin_to_finish_all_loads);
893 case DocumentState::LINK_LOAD_NORMAL:
895 "PLT.BeginToFinish_LinkLoadNormal_ExtensionWebRequestAdblockPlus",
896 begin_to_finish_all_loads);
898 case DocumentState::LINK_LOAD_RELOAD:
900 "PLT.BeginToFinish_LinkLoadReload_ExtensionWebRequestAdblockPlus",
901 begin_to_finish_all_loads);
903 case DocumentState::LINK_LOAD_CACHE_STALE_OK:
905 "PLT.BeginToFinish_LinkLoadStaleOk_ExtensionWebRequestAdblockPlus",
906 begin_to_finish_all_loads);
913 const bool use_webrequest_other_histogram =
914 ChromeContentRendererClient::
915 IsOtherExtensionWithWebRequestInstalled();
916 if (use_webrequest_other_histogram) {
917 UMA_HISTOGRAM_ENUMERATION(
918 "PLT.Abandoned_ExtensionWebRequestOther",
919 abandoned_page ? 1 : 0, 2);
921 case DocumentState::NORMAL_LOAD:
923 "PLT.BeginToFinish_NormalLoad_ExtensionWebRequestOther",
924 begin_to_finish_all_loads);
926 case DocumentState::LINK_LOAD_NORMAL:
928 "PLT.BeginToFinish_LinkLoadNormal_ExtensionWebRequestOther",
929 begin_to_finish_all_loads);
931 case DocumentState::LINK_LOAD_RELOAD:
933 "PLT.BeginToFinish_LinkLoadReload_ExtensionWebRequestOther",
934 begin_to_finish_all_loads);
936 case DocumentState::LINK_LOAD_CACHE_STALE_OK:
938 "PLT.BeginToFinish_LinkLoadStaleOk_ExtensionWebRequestOther",
939 begin_to_finish_all_loads);
946 // Record SpdyCwnd results.
947 if (document_state->was_fetched_via_spdy()) {
949 case DocumentState::LINK_LOAD_NORMAL:
950 PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadNormal_cwndDynamic",
951 begin_to_finish_all_loads);
952 PLT_HISTOGRAM("PLT.StartToFinish_LinkLoadNormal_cwndDynamic",
953 start_to_finish_all_loads);
954 PLT_HISTOGRAM("PLT.StartToCommit_LinkLoadNormal_cwndDynamic",
957 case DocumentState::NORMAL_LOAD:
958 PLT_HISTOGRAM("PLT.BeginToFinish_NormalLoad_cwndDynamic",
959 begin_to_finish_all_loads);
960 PLT_HISTOGRAM("PLT.StartToFinish_NormalLoad_cwndDynamic",
961 start_to_finish_all_loads);
962 PLT_HISTOGRAM("PLT.StartToCommit_NormalLoad_cwndDynamic",
970 // Record page load time and abandonment rates for proxy cases.
971 if (document_state->was_fetched_via_proxy()) {
972 if (scheme_type == URLPattern::SCHEME_HTTPS) {
973 PLT_HISTOGRAM("PLT.StartToFinish.Proxy.https", start_to_finish_all_loads);
974 UMA_HISTOGRAM_ENUMERATION("PLT.Abandoned.Proxy.https",
975 abandoned_page ? 1 : 0, 2);
977 DCHECK(scheme_type == URLPattern::SCHEME_HTTP);
978 PLT_HISTOGRAM("PLT.StartToFinish.Proxy.http", start_to_finish_all_loads);
979 UMA_HISTOGRAM_ENUMERATION("PLT.Abandoned.Proxy.http",
980 abandoned_page ? 1 : 0, 2);
983 if (scheme_type == URLPattern::SCHEME_HTTPS) {
984 PLT_HISTOGRAM("PLT.StartToFinish.NoProxy.https",
985 start_to_finish_all_loads);
986 UMA_HISTOGRAM_ENUMERATION("PLT.Abandoned.NoProxy.https",
987 abandoned_page ? 1 : 0, 2);
989 DCHECK(scheme_type == URLPattern::SCHEME_HTTP);
990 PLT_HISTOGRAM("PLT.StartToFinish.NoProxy.http",
991 start_to_finish_all_loads);
992 UMA_HISTOGRAM_ENUMERATION("PLT.Abandoned.NoProxy.http",
993 abandoned_page ? 1 : 0, 2);
997 // Site isolation metrics.
998 UMA_HISTOGRAM_COUNTS("SiteIsolation.PageLoadsWithCrossSiteFrameAccess",
999 cross_origin_access_count_);
1000 UMA_HISTOGRAM_COUNTS("SiteIsolation.PageLoadsWithSameSiteFrameAccess",
1001 same_origin_access_count_);
1003 // Log the PLT to the info log.
1004 LogPageLoadTime(document_state, frame->dataSource());
1006 // Since there are currently no guarantees that renderer histograms will be
1007 // sent to the browser, we initiate a PostTask here to be sure that we send
1008 // the histograms we generated. Without this call, pages that don't have an
1009 // on-close-handler might generate data that is lost when the renderer is
1010 // shutdown abruptly (perchance because the user closed the tab).
1011 // TODO(jar) BUG=33233: This needs to be moved to a PostDelayedTask, and it
1012 // should post when the onload is complete, so that it doesn't interfere with
1014 content::RenderThread::Get()->UpdateHistograms(
1015 content::kHistogramSynchronizerReservedSequenceNumber);
1018 void PageLoadHistograms::ResetCrossFramePropertyAccess() {
1019 cross_origin_access_count_ = 0;
1020 same_origin_access_count_ = 0;
1023 void PageLoadHistograms::FrameWillClose(WebFrame* frame) {
1027 void PageLoadHistograms::ClosePage() {
1028 // TODO(davemoore) This code should be removed once willClose() gets
1029 // called when a page is destroyed. page_load_histograms_.Dump() is safe
1030 // to call multiple times for the same frame, but it will simplify things.
1031 Dump(render_view()->GetWebView()->mainFrame());
1032 ResetCrossFramePropertyAccess();
1035 void PageLoadHistograms::LogPageLoadTime(const DocumentState* document_state,
1036 const WebDataSource* ds) const {
1037 // Because this function gets called on every page load,
1038 // take extra care to optimize it away if logging is turned off.
1039 if (logging::LOG_INFO < logging::GetMinLogLevel())
1042 DCHECK(document_state);
1044 GURL url(ds->request().url());
1045 Time start = document_state->start_load_time();
1046 Time finish = document_state->finish_load_time();
1047 // TODO(mbelshe): should we log more stats?
1048 VLOG(1) << "PLT: " << (finish - start).InMilliseconds() << "ms "