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