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