src/chrome/renderer/page_load_histograms.cc

   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
  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(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.
 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.
 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|.
 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(
 181       response_headers.get(), NULL);
 182 }
 183
 184 // Returns true if the provided URL is a referrer string that came from
 185 // a Google Web Search results page. This is a little non-deterministic
 186 // because desktop and mobile websearch differ and sometimes just provide
 187 // http://www.google.com/ as the referrer. In the case of /url we can be sure
 188 // that it came from websearch but we will be generous and allow for cases
 189 // where a non-Google URL was provided a bare Google URL as a referrer.
 190 // The domain validation matches the code used by the prerenderer for similar
 191 // purposes.
 192 // TODO(pmeenan): Remove the fuzzy logic when the referrer is reliable
 193 bool IsFromGoogleSearchResult(const GURL& url, const GURL& referrer) {
 194   if (!StartsWithASCII(referrer.host(), "www.google.", true))
 195     return false;
 196   if (StartsWithASCII(referrer.path(), "/url", true))
 197     return true;
 198   bool is_possible_search_referrer =
 199       referrer.path().empty() ||
 200       referrer.path() == "/" ||
 201       StartsWithASCII(referrer.path(), "/search", true) ||
 202       StartsWithASCII(referrer.path(), "/webhp", true);
 203   if (is_possible_search_referrer &&
 204       !StartsWithASCII(url.host(), "www.google", true))
 205     return true;
 206   return false;
 207 }
 208
 209 // Extracts a Google Web Search and Chrome joint experiment ID from a referrer
 210 // that came from a Google Web Search results page. An experiment ID is embedded
 211 // in a query string as a "gcjeid=" parameter value.
 212 int GetQueryStringBasedExperiment(const GURL& referrer) {
 213   std::string value;
 214   if (!net::GetValueForKeyInQuery(referrer, "gcjeid", &value))
 215     return kNoExperiment;
 216
 217   int experiment_id;
 218   if (!base::StringToInt(value, &experiment_id))
 219     return kNoExperiment;
 220   if (0 < experiment_id && experiment_id <= kMaxExperimentID)
 221     return experiment_id;
 222   return kNoExperiment;
 223 }
 224
 225 void DumpHistograms(const WebPerformance& performance,
 226                     DocumentState* document_state,
 227                     bool data_reduction_proxy_was_used,
 228                     bool came_from_websearch,
 229                     int websearch_chrome_joint_experiment_id,
 230                     bool is_preview) {
 231   // This function records new histograms based on the Navigation Timing
 232   // records. As such, the histograms should not depend on the deprecated timing
 233   // information collected in DocumentState. However, here for some reason we
 234   // check if document_state->request_time() is null. TODO(ppi): find out why
 235   // and remove DocumentState from the parameter list.
 236   Time request = document_state->request_time();
 237
 238   Time navigation_start = Time::FromDoubleT(performance.navigationStart());
 239   Time redirect_start = Time::FromDoubleT(performance.redirectStart());
 240   Time redirect_end = Time::FromDoubleT(performance.redirectEnd());
 241   Time fetch_start = Time::FromDoubleT(performance.fetchStart());
 242   Time domain_lookup_start = Time::FromDoubleT(performance.domainLookupStart());
 243   Time domain_lookup_end = Time::FromDoubleT(performance.domainLookupEnd());
 244   Time connect_start = Time::FromDoubleT(performance.connectStart());
 245   Time connect_end = Time::FromDoubleT(performance.connectEnd());
 246   Time request_start = Time::FromDoubleT(performance.requestStart());
 247   Time response_start = Time::FromDoubleT(performance.responseStart());
 248   Time response_end = Time::FromDoubleT(performance.responseEnd());
 249   Time dom_loading = Time::FromDoubleT(performance.domLoading());
 250   Time dom_interactive = Time::FromDoubleT(performance.domInteractive());
 251   Time dom_content_loaded_start =
 252       Time::FromDoubleT(performance.domContentLoadedEventStart());
 253   Time dom_content_loaded_end =
 254       Time::FromDoubleT(performance.domContentLoadedEventEnd());
 255   Time load_event_start = Time::FromDoubleT(performance.loadEventStart());
 256   Time load_event_end = Time::FromDoubleT(performance.loadEventEnd());
 257   Time begin = (request.is_null() ? navigation_start : request_start);
 258
 259   DCHECK(!navigation_start.is_null());
 260
 261   // It is possible for a document to have navigation_start time, but no
 262   // request_start. An example is doing a window.open, which synchronously
 263   // loads "about:blank", then using document.write add a meta http-equiv
 264   // refresh tag, which causes a navigation. In such case, we will arrive at
 265   // this function with no request/response timing data and identical load
 266   // start/end values. Avoid logging this case, as it doesn't add any
 267   // meaningful information to the histogram.
 268   if (request_start.is_null())
 269     return;
 270
 271   // TODO(dominich): Investigate conditions under which |load_event_start| and
 272   // |load_event_end| may be NULL as in the non-PT_ case below. Examples in
 273   // http://crbug.com/112006.
 274   // DCHECK(!load_event_start.is_null());
 275   // DCHECK(!load_event_end.is_null());
 276
 277   if (document_state->web_timing_histograms_recorded())
 278     return;
 279   document_state->set_web_timing_histograms_recorded(true);
 280
 281   if (!redirect_start.is_null() && !redirect_end.is_null()) {
 282     PLT_HISTOGRAM_DRP("PLT.NT_Redirect", redirect_end - redirect_start,
 283                       data_reduction_proxy_was_used);
 284     PLT_HISTOGRAM_DRP(
 285         "PLT.NT_DelayBeforeFetchRedirect",
 286         (fetch_start - navigation_start) - (redirect_end - redirect_start),
 287         data_reduction_proxy_was_used);
 288   } else {
 289     PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeFetch",
 290                       fetch_start - navigation_start,
 291                       data_reduction_proxy_was_used);
 292   }
 293   PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeDomainLookup",
 294                     domain_lookup_start - fetch_start,
 295                     data_reduction_proxy_was_used);
 296   PLT_HISTOGRAM_DRP("PLT.NT_DomainLookup",
 297                     domain_lookup_end - domain_lookup_start,
 298                     data_reduction_proxy_was_used);
 299   PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeConnect",
 300                     connect_start - domain_lookup_end,
 301                     data_reduction_proxy_was_used);
 302   PLT_HISTOGRAM_DRP("PLT.NT_Connect", connect_end - connect_start,
 303                     data_reduction_proxy_was_used);
 304   PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeRequest",
 305                     request_start - connect_end,
 306                     data_reduction_proxy_was_used);
 307   PLT_HISTOGRAM_DRP("PLT.NT_Request", response_start - request_start,
 308                     data_reduction_proxy_was_used);
 309   PLT_HISTOGRAM_DRP("PLT.NT_Response", response_end - response_start,
 310                     data_reduction_proxy_was_used);
 311
 312   if (!dom_loading.is_null()) {
 313     PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeDomLoading",
 314                       dom_loading - response_start,
 315                       data_reduction_proxy_was_used);
 316   }
 317   if (!dom_interactive.is_null() && !dom_loading.is_null()) {
 318     PLT_HISTOGRAM_DRP("PLT.NT_DomLoading",
 319                       dom_interactive - dom_loading,
 320                       data_reduction_proxy_was_used);
 321   }
 322   if (!dom_content_loaded_start.is_null() && !dom_interactive.is_null()) {
 323     PLT_HISTOGRAM_DRP("PLT.NT_DomInteractive",
 324                       dom_content_loaded_start - dom_interactive,
 325                       data_reduction_proxy_was_used);
 326   }
 327   if (!dom_content_loaded_start.is_null() &&
 328       !dom_content_loaded_end.is_null() ) {
 329     PLT_HISTOGRAM_DRP("PLT.NT_DomContentLoaded",
 330                       dom_content_loaded_end - dom_content_loaded_start,
 331                       data_reduction_proxy_was_used);
 332   }
 333   if (!dom_content_loaded_end.is_null() && !load_event_start.is_null()) {
 334     PLT_HISTOGRAM_DRP("PLT.NT_DelayBeforeLoadEvent",
 335                       load_event_start - dom_content_loaded_end,
 336                       data_reduction_proxy_was_used);
 337   }
 338
 339   // TODO(simonjam): There is no way to distinguish between abandonment and
 340   // intentional Javascript navigation before the load event fires.
 341   // TODO(dominich): Load type breakdown
 342   if (!load_event_start.is_null()) {
 343     PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_BeginToFinishDoc",
 344                                    load_event_start - begin,
 345                                    came_from_websearch,
 346                                    websearch_chrome_joint_experiment_id,
 347                                    is_preview);
 348     PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_CommitToFinishDoc",
 349                                    load_event_start - response_start,
 350                                    came_from_websearch,
 351                                    websearch_chrome_joint_experiment_id,
 352                                    is_preview);
 353     PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_RequestToFinishDoc",
 354                                    load_event_start - navigation_start,
 355                                    came_from_websearch,
 356                                    websearch_chrome_joint_experiment_id,
 357                                    is_preview);
 358     if (data_reduction_proxy_was_used) {
 359       PLT_HISTOGRAM("PLT.PT_BeginToFinishDoc_DataReductionProxy",
 360                     load_event_start - begin);
 361       PLT_HISTOGRAM("PLT.PT_CommitToFinishDoc_DataReductionProxy",
 362                     load_event_start - response_start);
 363       PLT_HISTOGRAM("PLT.PT_RequestToFinishDoc_DataReductionProxy",
 364                     load_event_start - navigation_start);
 365     }
 366   }
 367   if (!load_event_end.is_null()) {
 368     PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_BeginToFinish",
 369                                    load_event_end - begin,
 370                                    came_from_websearch,
 371                                    websearch_chrome_joint_experiment_id,
 372                                    is_preview);
 373     PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_CommitToFinish",
 374                                    load_event_end - response_start,
 375                                    came_from_websearch,
 376                                    websearch_chrome_joint_experiment_id,
 377                                    is_preview);
 378     PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_RequestToFinish",
 379                                    load_event_end - navigation_start,
 380                                    came_from_websearch,
 381                                    websearch_chrome_joint_experiment_id,
 382                                    is_preview);
 383     PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_StartToFinish",
 384                                    load_event_end - request_start,
 385                                    came_from_websearch,
 386                                    websearch_chrome_joint_experiment_id,
 387                                    is_preview);
 388     if (data_reduction_proxy_was_used) {
 389       PLT_HISTOGRAM("PLT.PT_BeginToFinish_DataReductionProxy",
 390                     load_event_end - begin);
 391       PLT_HISTOGRAM("PLT.PT_CommitToFinish_DataReductionProxy",
 392                     load_event_end - response_start);
 393       PLT_HISTOGRAM("PLT.PT_RequestToFinish_DataReductionProxy",
 394                     load_event_end - navigation_start);
 395       PLT_HISTOGRAM("PLT.PT_StartToFinish_DataReductionProxy",
 396                     load_event_end - request_start);
 397     }
 398   }
 399   if (!load_event_start.is_null() && !load_event_end.is_null()) {
 400     PLT_HISTOGRAM("PLT.PT_FinishDocToFinish",
 401                   load_event_end - load_event_start);
 402     PLT_HISTOGRAM_DRP("PLT.NT_LoadEvent",
 403                       load_event_end - load_event_start,
 404                       data_reduction_proxy_was_used);
 405
 406     if (data_reduction_proxy_was_used)
 407       PLT_HISTOGRAM("PLT.PT_FinishDocToFinish_DataReductionProxy",
 408                     load_event_end - load_event_start);
 409   }
 410   if (!dom_content_loaded_start.is_null()) {
 411     PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_RequestToDomContentLoaded",
 412                                    dom_content_loaded_start - navigation_start,
 413                                    came_from_websearch,
 414                                    websearch_chrome_joint_experiment_id,
 415                                    is_preview);
 416     if (data_reduction_proxy_was_used)
 417       PLT_HISTOGRAM("PLT.PT_RequestToDomContentLoaded_DataReductionProxy",
 418                     dom_content_loaded_start - navigation_start);
 419   }
 420   PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_BeginToCommit",
 421                                  response_start - begin,
 422                                  came_from_websearch,
 423                                  websearch_chrome_joint_experiment_id,
 424                                  is_preview);
 425   PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_RequestToStart",
 426                                  request_start - navigation_start,
 427                                  came_from_websearch,
 428                                  websearch_chrome_joint_experiment_id,
 429                                  is_preview);
 430   PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_StartToCommit",
 431                                  response_start - request_start,
 432                                  came_from_websearch,
 433                                  websearch_chrome_joint_experiment_id,
 434                                  is_preview);
 435   PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.PT_RequestToCommit",
 436                                  response_start - navigation_start,
 437                                  came_from_websearch,
 438                                  websearch_chrome_joint_experiment_id,
 439                                  is_preview);
 440   if (data_reduction_proxy_was_used) {
 441     PLT_HISTOGRAM("PLT.PT_BeginToCommit_DataReductionProxy",
 442                   response_start - begin);
 443     PLT_HISTOGRAM("PLT.PT_RequestToStart_DataReductionProxy",
 444                   request_start - navigation_start);
 445     PLT_HISTOGRAM("PLT.PT_StartToCommit_DataReductionProxy",
 446                   response_start - request_start);
 447     PLT_HISTOGRAM("PLT.PT_RequestToCommit_DataReductionProxy",
 448                   response_start - navigation_start);
 449   }
 450 }
 451
 452 // These histograms are based on the timing information collected in
 453 // DocumentState. They should be transitioned to equivalents based on the
 454 // Navigation Timing records (see DumpPerformanceTiming()) or dropped if not
 455 // needed. Please do not add new metrics based on DocumentState.
 456 void DumpDeprecatedHistograms(const WebPerformance& performance,
 457                               DocumentState* document_state,
 458                               bool data_reduction_proxy_was_used,
 459                               bool came_from_websearch,
 460                               int websearch_chrome_joint_experiment_id,
 461                               bool is_preview,
 462                               URLPattern::SchemeMasks scheme_type) {
 463   // If we've already dumped, do nothing.
 464   // This simple bool works because we only dump for the main frame.
 465   if (document_state->load_histograms_recorded())
 466     return;
 467
 468   // Abort if any of these is missing.
 469   Time start = document_state->start_load_time();
 470   Time commit = document_state->commit_load_time();
 471   Time navigation_start =
 472       Time::FromDoubleT(performance.navigationStart());
 473   if (start.is_null() || commit.is_null() || navigation_start.is_null())
 474     return;
 475
 476   // We properly handle null values for the next 3 variables.
 477   Time request = document_state->request_time();
 478   Time first_paint = document_state->first_paint_time();
 479   Time first_paint_after_load = document_state->first_paint_after_load_time();
 480   Time finish_doc = document_state->finish_document_load_time();
 481   Time finish_all_loads = document_state->finish_load_time();
 482
 483   // Handle case where user hits "stop" or "back" before loading completely.
 484   // Note that this makes abandoned page loads be recorded as if they were
 485   // completed, polluting the metrics with artifically short completion times.
 486   // We are not fixing this as these metrics are being dropped as deprecated.
 487   if (finish_doc.is_null()) {
 488     finish_doc = Time::Now();
 489     document_state->set_finish_document_load_time(finish_doc);
 490   }
 491   if (finish_all_loads.is_null()) {
 492     finish_all_loads = Time::Now();
 493     document_state->set_finish_load_time(finish_all_loads);
 494   }
 495
 496   document_state->set_load_histograms_recorded(true);
 497
 498   // Note: Client side redirects will have no request time.
 499   Time begin = request.is_null() ? start : request;
 500   TimeDelta begin_to_finish_doc = finish_doc - begin;
 501   TimeDelta begin_to_finish_all_loads = finish_all_loads - begin;
 502   TimeDelta start_to_finish_all_loads = finish_all_loads - start;
 503   TimeDelta start_to_commit = commit - start;
 504
 505   DocumentState::LoadType load_type = document_state->load_type();
 506
 507   // The above code sanitized all values of times, in preparation for creating
 508   // actual histograms.  The remainder of this code could be run at destructor
 509   // time for the document_state, since all data is intact.
 510
 511   // Aggregate PLT data across all link types.
 512   UMA_HISTOGRAM_ENUMERATION("PLT.LoadType", load_type,
 513       DocumentState::kLoadTypeMax);
 514   PLT_HISTOGRAM("PLT.StartToCommit", start_to_commit);
 515   PLT_HISTOGRAM("PLT.CommitToFinishDoc", finish_doc - commit);
 516   PLT_HISTOGRAM("PLT.FinishDocToFinish", finish_all_loads - finish_doc);
 517   PLT_HISTOGRAM("PLT.BeginToCommit", commit - begin);
 518   PLT_HISTOGRAM("PLT.StartToFinish", start_to_finish_all_loads);
 519   if (!request.is_null()) {
 520     PLT_HISTOGRAM("PLT.RequestToStart", start - request);
 521     PLT_HISTOGRAM("PLT.RequestToFinish", finish_all_loads - request);
 522   }
 523   PLT_HISTOGRAM("PLT.CommitToFinish", finish_all_loads - commit);
 524
 525   scoped_ptr<TimeDelta> begin_to_first_paint;
 526   scoped_ptr<TimeDelta> commit_to_first_paint;
 527   if (!first_paint.is_null()) {
 528     // 'first_paint' can be before 'begin' for an unknown reason.
 529     // See bug http://crbug.com/125273 for details.
 530     if (begin <= first_paint) {
 531       begin_to_first_paint.reset(new TimeDelta(first_paint - begin));
 532       PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.BeginToFirstPaint",
 533                                      *begin_to_first_paint,
 534                                      came_from_websearch,
 535                                      websearch_chrome_joint_experiment_id,
 536                                      is_preview);
 537     }
 538
 539     // Conditional was previously a DCHECK. Changed due to multiple bot
 540     // failures, listed in crbug.com/383963
 541     if (commit <= first_paint) {
 542       commit_to_first_paint.reset(new TimeDelta(first_paint - commit));
 543       PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.CommitToFirstPaint",
 544                                      *commit_to_first_paint,
 545                                      came_from_websearch,
 546                                      websearch_chrome_joint_experiment_id,
 547                                      is_preview);
 548     }
 549   }
 550   if (!first_paint_after_load.is_null()) {
 551     // 'first_paint_after_load' can be before 'begin' for an unknown reason.
 552     // See bug http://crbug.com/125273 for details.
 553     if (begin <= first_paint_after_load) {
 554       PLT_HISTOGRAM("PLT.BeginToFirstPaintAfterLoad",
 555           first_paint_after_load - begin);
 556     }
 557     // Both following conditionals were previously DCHECKs. Changed due to
 558     // multiple bot failures, listed in crbug.com/383963
 559     if (commit <= first_paint_after_load) {
 560       PLT_HISTOGRAM("PLT.CommitToFirstPaintAfterLoad",
 561           first_paint_after_load - commit);
 562     }
 563     if (finish_all_loads <= first_paint_after_load) {
 564       PLT_HISTOGRAM("PLT.FinishToFirstPaintAfterLoad",
 565           first_paint_after_load - finish_all_loads);
 566     }
 567   }
 568   PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.BeginToFinishDoc", begin_to_finish_doc,
 569                                  came_from_websearch,
 570                                  websearch_chrome_joint_experiment_id,
 571                                  is_preview);
 572   PLT_HISTOGRAM_WITH_GWS_VARIANT("PLT.BeginToFinish", begin_to_finish_all_loads,
 573                                  came_from_websearch,
 574                                  websearch_chrome_joint_experiment_id,
 575                                  is_preview);
 576
 577   // Load type related histograms.
 578   switch (load_type) {
 579     case DocumentState::UNDEFINED_LOAD:
 580       PLT_HISTOGRAM("PLT.BeginToFinishDoc_UndefLoad", begin_to_finish_doc);
 581       PLT_HISTOGRAM("PLT.BeginToFinish_UndefLoad", begin_to_finish_all_loads);
 582       break;
 583     case DocumentState::RELOAD:
 584       PLT_HISTOGRAM("PLT.BeginToFinishDoc_Reload", begin_to_finish_doc);
 585       PLT_HISTOGRAM("PLT.BeginToFinish_Reload", begin_to_finish_all_loads);
 586       break;
 587     case DocumentState::HISTORY_LOAD:
 588       PLT_HISTOGRAM("PLT.BeginToFinishDoc_HistoryLoad", begin_to_finish_doc);
 589       PLT_HISTOGRAM("PLT.BeginToFinish_HistoryLoad", begin_to_finish_all_loads);
 590       break;
 591     case DocumentState::NORMAL_LOAD:
 592       PLT_HISTOGRAM("PLT.BeginToFinishDoc_NormalLoad", begin_to_finish_doc);
 593       PLT_HISTOGRAM("PLT.BeginToFinish_NormalLoad", begin_to_finish_all_loads);
 594       break;
 595     case DocumentState::LINK_LOAD_NORMAL:
 596       PLT_HISTOGRAM("PLT.BeginToFinishDoc_LinkLoadNormal",
 597           begin_to_finish_doc);
 598       PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadNormal",
 599                     begin_to_finish_all_loads);
 600       break;
 601     case DocumentState::LINK_LOAD_RELOAD:
 602       PLT_HISTOGRAM("PLT.BeginToFinishDoc_LinkLoadReload",
 603            begin_to_finish_doc);
 604       PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadReload",
 605                     begin_to_finish_all_loads);
 606       break;
 607     case DocumentState::LINK_LOAD_CACHE_STALE_OK:
 608       PLT_HISTOGRAM("PLT.BeginToFinishDoc_LinkLoadStaleOk",
 609            begin_to_finish_doc);
 610       PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadStaleOk",
 611                     begin_to_finish_all_loads);
 612       break;
 613     case DocumentState::LINK_LOAD_CACHE_ONLY:
 614       PLT_HISTOGRAM("PLT.BeginToFinishDoc_LinkLoadCacheOnly",
 615            begin_to_finish_doc);
 616       PLT_HISTOGRAM("PLT.BeginToFinish_LinkLoadCacheOnly",
 617                     begin_to_finish_all_loads);
 618       break;
 619     default:
 620       break;
 621   }
 622
 623   if (data_reduction_proxy_was_used) {
 624     PLT_HISTOGRAM("PLT.BeginToFinishDoc_SpdyProxy", begin_to_finish_doc);
 625     PLT_HISTOGRAM("PLT.BeginToFinish_SpdyProxy", begin_to_finish_all_loads);
 626   }
 627
 628   if (document_state->was_prefetcher()) {
 629     PLT_HISTOGRAM("PLT.BeginToFinishDoc_ContentPrefetcher",
 630                   begin_to_finish_doc);
 631     PLT_HISTOGRAM("PLT.BeginToFinish_ContentPrefetcher",
 632                   begin_to_finish_all_loads);
 633   }
 634   if (document_state->was_referred_by_prefetcher()) {
 635     PLT_HISTOGRAM("PLT.BeginToFinishDoc_ContentPrefetcherReferrer",
 636                   begin_to_finish_doc);
 637     PLT_HISTOGRAM("PLT.BeginToFinish_ContentPrefetcherReferrer",
 638                   begin_to_finish_all_loads);
 639   }
 640
 641   const bool use_webrequest_histogram =
 642       ChromeContentRendererClient::WasWebRequestUsedBySomeExtensions();
 643   if (use_webrequest_histogram) {
 644     switch (load_type) {
 645       case DocumentState::NORMAL_LOAD:
 646         PLT_HISTOGRAM(
 647             "PLT.BeginToFinish_NormalLoad_ExtensionWebRequest",
 648             begin_to_finish_all_loads);
 649         break;
 650       case DocumentState::LINK_LOAD_NORMAL:
 651         PLT_HISTOGRAM(
 652             "PLT.BeginToFinish_LinkLoadNormal_ExtensionWebRequest",
 653             begin_to_finish_all_loads);
 654         break;
 655       case DocumentState::LINK_LOAD_RELOAD:
 656         PLT_HISTOGRAM(
 657             "PLT.BeginToFinish_LinkLoadReload_ExtensionWebRequest",
 658             begin_to_finish_all_loads);
 659         break;
 660       case DocumentState::LINK_LOAD_CACHE_STALE_OK:
 661         PLT_HISTOGRAM(
 662             "PLT.BeginToFinish_LinkLoadStaleOk_ExtensionWebRequest",
 663             begin_to_finish_all_loads);
 664         break;
 665       default:
 666         break;
 667     }
 668   }
 669 }
 670
 671 }  // namespace
 672
 673 PageLoadHistograms::PageLoadHistograms(content::RenderView* render_view)
 674     : content::RenderViewObserver(render_view) {
 675 }
 676
 677 void PageLoadHistograms::Dump(WebFrame* frame) {
 678   // We only dump histograms for main frames.
 679   // In the future, it may be interesting to tag subframes and dump them too.
 680   if (!frame || frame->parent())
 681     return;
 682
 683   // Only dump for supported schemes.
 684   URLPattern::SchemeMasks scheme_type =
 685       GetSupportedSchemeType(frame->document().url());
 686   if (scheme_type == 0)
 687     return;
 688
 689   // Ignore multipart requests.
 690   if (frame->dataSource()->response().isMultipartPayload())
 691     return;
 692
 693   DocumentState* document_state =
 694       DocumentState::FromDataSource(frame->dataSource());
 695
 696   bool data_reduction_proxy_was_used = DataReductionProxyWasUsed(frame);
 697   bool came_from_websearch =
 698       IsFromGoogleSearchResult(frame->document().url(),
 699                                GURL(frame->document().referrer()));
 700   int websearch_chrome_joint_experiment_id = kNoExperiment;
 701   bool is_preview = false;
 702   if (came_from_websearch) {
 703     websearch_chrome_joint_experiment_id =
 704         GetQueryStringBasedExperiment(GURL(frame->document().referrer()));
 705     is_preview = ViaHeaderContains(frame, "1.1 Google Instant Proxy Preview");
 706   }
 707
 708   // Metrics based on the timing information recorded for the Navigation Timing
 709   // API - http://www.w3.org/TR/navigation-timing/.
 710   DumpHistograms(frame->performance(), document_state,
 711                  data_reduction_proxy_was_used,
 712                  came_from_websearch,
 713                  websearch_chrome_joint_experiment_id,
 714                  is_preview);
 715
 716   // Old metrics based on the timing information stored in DocumentState. These
 717   // are deprecated and should go away.
 718   DumpDeprecatedHistograms(frame->performance(), document_state,
 719                            data_reduction_proxy_was_used,
 720                            came_from_websearch,
 721                            websearch_chrome_joint_experiment_id,
 722                            is_preview,
 723                            scheme_type);
 724
 725   // Log the PLT to the info log.
 726   LogPageLoadTime(document_state, frame->dataSource());
 727
 728   // Since there are currently no guarantees that renderer histograms will be
 729   // sent to the browser, we initiate a PostTask here to be sure that we send
 730   // the histograms we generated.  Without this call, pages that don't have an
 731   // on-close-handler might generate data that is lost when the renderer is
 732   // shutdown abruptly (perchance because the user closed the tab).
 733   // TODO(jar) BUG=33233: This needs to be moved to a PostDelayedTask, and it
 734   // should post when the onload is complete, so that it doesn't interfere with
 735   // the next load.
 736   content::RenderThread::Get()->UpdateHistograms(
 737       content::kHistogramSynchronizerReservedSequenceNumber);
 738 }
 739
 740 void PageLoadHistograms::FrameWillClose(WebFrame* frame) {
 741   Dump(frame);
 742 }
 743
 744 void PageLoadHistograms::ClosePage() {
 745   // TODO(davemoore) This code should be removed once willClose() gets
 746   // called when a page is destroyed. page_load_histograms_.Dump() is safe
 747   // to call multiple times for the same frame, but it will simplify things.
 748   Dump(render_view()->GetWebView()->mainFrame());
 749 }
 750
 751 void PageLoadHistograms::LogPageLoadTime(const DocumentState* document_state,
 752                                          const WebDataSource* ds) const {
 753   // Because this function gets called on every page load,
 754   // take extra care to optimize it away if logging is turned off.
 755   if (logging::LOG_INFO < logging::GetMinLogLevel())
 756     return;
 757
 758   DCHECK(document_state);
 759   DCHECK(ds);
 760   GURL url(ds->request().url());
 761   Time start = document_state->start_load_time();
 762   Time finish = document_state->finish_load_time();
 763   // TODO(mbelshe): should we log more stats?
 764   VLOG(1) << "PLT: " << (finish - start).InMilliseconds() << "ms "
 765           << url.spec();
 766 }