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