Record first layout time UMA metric in PageLoadHistograms.

chrome/renderer/page_load_histograms.cc

Index: chrome/renderer/page_load_histograms.cc
diff --git a/chrome/renderer/page_load_histograms.cc b/chrome/renderer/page_load_histograms.cc
index 97f7c382dd053a425a55340f3daa622cca0f1fd6..b11ef12ce313b8ad88a21801478d10642b667315 100644
--- a/chrome/renderer/page_load_histograms.cc
+++ b/chrome/renderer/page_load_histograms.cc
@@ -6,6 +6,7 @@
 
 #include <string>
 
+#include "base/bind.h"
 #include "base/command_line.h"
 #include "base/logging.h"
 #include "base/metrics/field_trial.h"
@@ -827,30 +828,45 @@ void DumpDeprecatedHistograms(const WebPerformance& performance,
 }  // 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());
 
@@ -874,6 +890,8 @@ void PageLoadHistograms::Dump(WebFrame* frame) {
     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,
@@ -905,6 +923,29 @@ void PageLoadHistograms::Dump(WebFrame* frame) {
       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);
 }
@@ -916,6 +957,38 @@ void PageLoadHistograms::ClosePage() {
   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,