Record first layout time UMA metric in PageLoadHistograms.

chrome/renderer/page_load_histograms.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "chrome/renderer/page_load_histograms.h"
 
 #include <string>
 
+#include "base/bind.h"
 #include "base/command_line.h"
 #include "base/logging.h"
 #include "base/metrics/field_trial.h"
 #include "base/metrics/histogram.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/strings/string_split.h"
 #include "base/strings/string_util.h"
 #include "base/strings/stringprintf.h"
 #include "base/strings/utf_string_conversions.h"
 #include "base/time/time.h"
@@ skipping 801 matching lines @@
         break;
       default:
         break;
     }
   }
 }
 
 }  // namespace
 
 PageLoadHistograms::PageLoadHistograms(content::RenderView* render_view)
-    : content::RenderViewObserver(render_view) {
+    : content::RenderViewObserver(render_view),
+      dumped_first_layout_histograms_(false),
+      weak_factory_(this) {
 }
 
-void PageLoadHistograms::Dump(WebFrame* frame) {
+PageLoadHistograms::~PageLoadHistograms() {
+}
+
+bool PageLoadHistograms::ShouldDump(WebFrame* frame) {
   // We only dump histograms for main frames.
   // In the future, it may be interesting to tag subframes and dump them too.
   if (!frame || frame->parent())
-    return;
+    return false;
 
   // If the main frame lives in a different process, don't do anything.
   // Histogram data will be recorded by the real main frame.
   if (frame->isWebRemoteFrame())
-    return;
+    return false;
 
   // Only dump for supported schemes.
   URLPattern::SchemeMasks scheme_type =
       GetSupportedSchemeType(frame->document().url());
   if (scheme_type == 0)
-    return;
+    return false;
 
   // Ignore multipart requests.
   if (frame->dataSource()->response().isMultipartPayload())
+    return false;
+
+  return true;
+}
+
+void PageLoadHistograms::Dump(WebFrame* frame) {
+  if (!ShouldDump(frame))
     return;
 
+  URLPattern::SchemeMasks scheme_type =
+      GetSupportedSchemeType(frame->document().url());
+
   DocumentState* document_state =
       DocumentState::FromDataSource(frame->dataSource());
 
   bool data_reduction_proxy_was_used = false;
   data_reduction_proxy::LoFiStatus lofi_status =
       data_reduction_proxy::LOFI_STATUS_TEMPORARILY_OFF;
   if (!document_state->proxy_server().IsEmpty()) {
     Send(new DataReductionProxyViewHostMsg_DataReductionProxyStatus(
         document_state->proxy_server(), &data_reduction_proxy_was_used,
         &lofi_status));
   }
 
   bool came_from_websearch =
       IsFromGoogleSearchResult(frame->document().url(),
                                GURL(frame->document().referrer()));
   int websearch_chrome_joint_experiment_id = kNoExperiment;
   bool is_preview = false;
   if (came_from_websearch) {
     websearch_chrome_joint_experiment_id =
         GetQueryStringBasedExperiment(GURL(frame->document().referrer()));
     is_preview = ViaHeaderContains(frame, "1.1 Google Instant Proxy Preview");
   }
 
+  MaybeDumpFirstLayoutHistograms();
+
   // Metrics based on the timing information recorded for the Navigation Timing
   // API - http://www.w3.org/TR/navigation-timing/.
   DumpHistograms(frame->performance(), document_state,
                  data_reduction_proxy_was_used, lofi_status,
                  came_from_websearch, websearch_chrome_joint_experiment_id,
                  is_preview, scheme_type);
 
   // Old metrics based on the timing information stored in DocumentState. These
   // are deprecated and should go away.
   DumpDeprecatedHistograms(frame->performance(), document_state,
@@ skipping 11 matching lines @@
   // the histograms we generated.  Without this call, pages that don't have an
   // on-close-handler might generate data that is lost when the renderer is
   // shutdown abruptly (perchance because the user closed the tab).
   // TODO(jar) BUG=33233: This needs to be moved to a PostDelayedTask, and it
   // should post when the onload is complete, so that it doesn't interfere with
   // the next load.
   content::RenderThread::Get()->UpdateHistograms(
       content::kHistogramSynchronizerReservedSequenceNumber);
 }
 
+void PageLoadHistograms::MaybeDumpFirstLayoutHistograms() {
+  if (dumped_first_layout_histograms_)
+    return;
+
+  const WebPerformance& performance =
+    render_view()->GetWebView()->mainFrame()->performance();
+  Time first_layout = Time::FromDoubleT(performance.firstLayout());
+  if (first_layout.is_null())
+    return;
+
+  Time navigation_start = Time::FromDoubleT(performance.navigationStart());
+  if (!navigation_start.is_null())
+    PLT_HISTOGRAM("PLT.PT_NavigationStartToFirstLayout",
+                  first_layout - navigation_start);
+
+  Time response_start = Time::FromDoubleT(performance.responseStart());
+  if (!response_start.is_null())
+    PLT_HISTOGRAM("PLT.PT_ResponseStartToFirstLayout",
+                  first_layout - response_start);
+
+  dumped_first_layout_histograms_ = true;
+}
+
 void PageLoadHistograms::FrameWillClose(WebFrame* frame) {
   Dump(frame);
 }
 
 void PageLoadHistograms::ClosePage() {
   // TODO(davemoore) This code should be removed once willClose() gets
   // called when a page is destroyed. page_load_histograms_.Dump() is safe
   // to call multiple times for the same frame, but it will simplify things.
   Dump(render_view()->GetWebView()->mainFrame());
 }
 
+void PageLoadHistograms::DidUpdateLayout() {

[Pat Meenan, 2015/07/09 19:29:27]

Just a sanity check, but do you know what the overhead is for the observer? 
Given that layouts can happen fairly frequently and we really only care about
the first layout I'd like to make sure we're not adding a bunch of overhead to
every layout (just by the observer existing).

[Bryan McQuade, 2015/07/09 19:35:04]

Should just be a function call, which is already being dispatched to an empty
implementation of the base class RenderViewObserver::DidUpdateLayout(). So no
new overhead there.

I did make sure to abort this method once dumped_first_layout_histograms_  is
true, which means we won't continue to post new async tasks once we've recorded
the first layout time.

So overall, I don't think we're looking at any real additional overhead.

+  // Normally, PageLoadHistograms dumps all histograms in the FrameWillClose or
+  // ClosePage callbacks, which happen as a page is being torn down. However,
+  // renderers that are killed by fast shutdown (for example, renderers closed
+  // due to the user closing a tab) don't get a chance to run these callbacks
+  // (see crbug.com/382542 for details).
+  //
+  // Longer term, we need to migrate histogram recording to happen earlier in
+  // the page load life cycle, so histograms aren't lost when tabs are
+  // closed. As a first step, we use the RenderViewObserver::DidUpdateLayout
+  // callback to log first layout histograms earlier in the page load life
+  // cycle.
+
+  WebFrame* frame = render_view()->GetWebView()->mainFrame();
+  if (dumped_first_layout_histograms_ || !ShouldDump(frame))

[Pat Meenan, 2015/07/09 19:29:27]

Maybe fast exit the dumped_first_layout_histograms_ first before acquiring the
main frame to avoid the extra work for subsequent layouts?

[Bryan McQuade, 2015/07/09 19:35:04]

Good idea, done.

+    return;
+
+  // The canonical source for the 'first layout time' is the
+  // blink::WebPerformance object, so we need to read the first layout timestamp
+  // from that object, rather than taking our own timestamp in this
+  // callback. This DidUpdateLayout callback gets invoked in the midst of the
+  // layout process. The logic that records the first layout time in the
+  // blink::WebPerformance object may run later in the layout process, after
+  // DidUpdateLayout gets invoked. Thus, we schedule a callback to run
+  // MaybeDumpFirstLayoutHistograms asynchronously, after the layout process is
+  // complete.
+  content::RenderThread::Get()->GetTaskRunner()->PostTask(
+      FROM_HERE,
+      base::Bind(&PageLoadHistograms::MaybeDumpFirstLayoutHistograms,
+                 weak_factory_.GetWeakPtr()));
+}
+
 void PageLoadHistograms::LogPageLoadTime(const DocumentState* document_state,
                                          const WebDataSource* ds) const {
   // Because this function gets called on every page load,
   // take extra care to optimize it away if logging is turned off.
   if (logging::LOG_INFO < logging::GetMinLogLevel())
     return;
 
   DCHECK(document_state);
   DCHECK(ds);
   GURL url(ds->request().url());
   Time start = document_state->start_load_time();
   Time finish = document_state->finish_load_time();
   // TODO(mbelshe): should we log more stats?
   VLOG(1) << "PLT: " << (finish - start).InMilliseconds() << "ms "
           << url.spec();
 }