Create a PageTimingSender for subframe documents without a committed load

What:
Create a PageTimingSender for frames that abort their initial navigation
with a doc.write to render content. This is done by observing
document element without a committed load.

Why:
This behavior has been seen numerous times in the wild causing, where
PLM byte metrics are not catching the majority of network usage by the
page. In a number of instances, there are video players loaded inside of
these frames causing most network bytes to be unattributed to the
PageLoad.

This also affects the HeavyAdIntervention, which uses PLM measurements
to trigger unloading.

How:
For these types of loads, we will not send paint timing, render data,
or metadata updates to the browser process. There is currently a lack
of understanding regarding paint timing in frames like this. There is
also no browser process machinery to merge timing updates in frames that
do not have loads (as we cannot get a navigation start offset).

It is unclear the effect that this change will have overall on metrics.
Anecdotally, it is not expected to not produce a significant change due
to being a fairly nuanced edge case.

Bug: 914893
Change-Id: Ic696e693e11f2d7cdcd8c97e9418a55d7bf4b2a0
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1822218Reviewed-by: Bryan McQuade <bmcquade@chromium.org>
Commit-Queue: John Delaney <johnidel@chromium.org>
Cr-Commit-Position: refs/heads/master@{#782709}

chrome/browser/page_load_metrics/observers/ad_metrics/ads_page_load_metrics_observer_browsertest.cc

@@ -554,8 +554,8 @@ IN_PROC_BROWSER_TEST_F(AdsPageLoadMetricsObserverBrowserTest,
                        DocOverwritesNavigation) {
   content::DOMMessageQueue msg_queue;
 
-  base::HistogramTester histogram_tester;
-
+  ukm::TestAutoSetUkmRecorder ukm_recorder;
+  auto waiter = CreatePageLoadMetricsTestWaiter();
   ui_test_utils::NavigateToURL(
       browser(), embedded_test_server()->GetURL(
                      "/ads_observer/docwrite_provisional_frame.html"));
@@ -566,10 +566,16 @@ IN_PROC_BROWSER_TEST_F(AdsPageLoadMetricsObserverBrowserTest,
   // Navigate away to force the histogram recording.
   ui_test_utils::NavigateToURL(browser(), GURL(url::kAboutBlankURL));
 
-  // TODO(johnidel): Check that the subresources of the new frame are reported
-  // correctly. Resources from a failed provisional load are not reported to
-  // resource data updates, causing this adframe to not be recorded. This is an
-  // uncommon case but should be reported. See crbug.com/914893.
+  auto entries =
+      ukm_recorder.GetEntriesByName(ukm::builders::AdFrameLoad::kEntryName);
+  EXPECT_EQ(1u, entries.size());
+  ukm_recorder.ExpectEntryMetric(
+      entries.front(), ukm::builders::AdFrameLoad::kLoading_NumResourcesName,
+      3);
+
+  // TODO(https://crbug.com/): We should verify that we also receive FCP for
+  // frames that are loaded in this manner. Currently timing updates are not
+  // sent for aborted navigations due to doc.write.
 }
 
 // Test that a blank ad subframe that is docwritten correctly reports metrics.

chrome/browser/page_load_metrics/page_load_metrics_browsertest.cc

@@ -887,6 +887,19 @@ IN_PROC_BROWSER_TEST_F(PageLoadMetricsBrowserTest, SameUrlNavigation) {
   VerifyNavigationMetrics({url, url});
 }
 
+IN_PROC_BROWSER_TEST_F(PageLoadMetricsBrowserTest,
+                       DocWriteAbortsSubframeNavigation) {
+  ASSERT_TRUE(embedded_test_server()->Start());
+
+  auto waiter = CreatePageLoadMetricsTestWaiter();
+  ui_test_utils::NavigateToURL(
+      browser(), embedded_test_server()->GetURL(
+                     "/page_load_metrics/doc_write_aborts_subframe.html"));
+  waiter->AddMinimumCompleteResourcesExpectation(4);
+  waiter->Wait();
+  EXPECT_FALSE(waiter->DidObserveInPage(TimingField::kFirstPaint));
+}
+
 IN_PROC_BROWSER_TEST_F(PageLoadMetricsBrowserTest, NonHtmlMainResource) {
   ASSERT_TRUE(embedded_test_server()->Start());
 

chrome/test/data/ads_observer/ad_iframe_writer.js

@@ -12,7 +12,7 @@ function createAdIframe() {
 
 function createAdIframeWithSrc(src) {
   let frame = document.createElement('iframe');
-  document.body.appendChild(frame);
   frame.src = src;
+  document.body.appendChild(frame);
   return frame;
 }

chrome/test/data/ads_observer/docwrite_provisional_frame.html

@@ -7,9 +7,8 @@
     window.domAutomationController.send(e.data);
   });
 
-  adIframe = createAdIframe();
+  adIframe = createAdIframeWithSrc("/slow?100");
   adIframe.id = "slow_frame";
-  adIframe.src = "/slow?100";
 
   // slow takes 100 seconds to load, plenty of time to overwrite the
   // provisional load.

chrome/test/data/page_load_metrics/doc_write_aborts_subframe.html

+<html>
+  <link rel="stylesheet" href="seamless-iframe.css">
+  <body>
+    <iframe src="/slow?100" id="frame" class="seamless"></iframe>
+    <script>
+      let frame = document.getElementById("frame");
+      let doc = frame.contentDocument;
+      doc.open();
+      doc.write("<html>Rewritten. <img src=pixel.png> </html>");
+      doc.close();
+    </script>
+  </body>
+</html>

components/page_load_metrics/renderer/metrics_render_frame_observer.cc

@@ -39,12 +39,16 @@ base::TimeTicks ClampToStart(base::TimeTicks event, base::TimeTicks start) {
 
 class MojoPageTimingSender : public PageTimingSender {
  public:
-  explicit MojoPageTimingSender(content::RenderFrame* render_frame) {
+  explicit MojoPageTimingSender(content::RenderFrame* render_frame,
+                                bool limited_sending_mode)
+      : limited_sending_mode_(limited_sending_mode) {
     DCHECK(render_frame);
     render_frame->GetRemoteAssociatedInterfaces()->GetInterface(
         &page_load_metrics_);
   }
+
   ~MojoPageTimingSender() override = default;
+
   void SendTiming(const mojom::PageLoadTimingPtr& timing,
                   const mojom::FrameMetadataPtr& metadata,
                   mojom::PageLoadFeaturesPtr new_features,
@@ -55,10 +59,12 @@ class MojoPageTimingSender : public PageTimingSender {
                   mojom::InputTimingPtr input_timing_delta) override {
     DCHECK(page_load_metrics_);
     page_load_metrics_->UpdateTiming(
-        timing->Clone(), metadata->Clone(), std::move(new_features),
-        std::move(resources), render_data.Clone(), cpu_timing->Clone(),
+        limited_sending_mode_ ? CreatePageLoadTiming() : timing->Clone(),
+        metadata->Clone(), std::move(new_features), std::move(resources),
+        render_data.Clone(), cpu_timing->Clone(),
         std::move(new_deferred_resource_data), std::move(input_timing_delta));
   }
+
   void SubmitThroughputData(ukm::SourceId source_id,
                             int aggregated_percent,
                             int impl_percent,
@@ -74,6 +80,13 @@ class MojoPageTimingSender : public PageTimingSender {
   }
 
  private:
+  // Indicates that this sender should not send timing updates or frame render
+  // data updates.
+  // TODO(https://crbug.com/1097127): When timing updates are handled for cases
+  // where we have a subframe document and no committed navigation, this can be
+  // removed.
+  bool limited_sending_mode_ = false;
+
   // Use associated interface to make sure mojo messages are ordered with regard
   // to legacy IPC messages.
   mojo::AssociatedRemote<mojom::PageLoadMetrics> page_load_metrics_;
@@ -259,6 +272,47 @@ void MetricsRenderFrameObserver::DidFailProvisionalLoad() {
   provisional_frame_resource_data_use_.reset();
 }
 
+void MetricsRenderFrameObserver::DidCreateDocumentElement() {
+  // If we do not have a render frame or are already tracking this frame, ignore
+  // the new document element.
+  if (HasNoRenderFrame() || page_timing_metrics_sender_)
+    return;
+
+  // We should only track committed navigations for the main frame so ignore new
+  // document elements in the main frame.
+  if (render_frame()->IsMainFrame())
+    return;
+
+  // Every frame creates an initial about:blank document element prior to
+  // receiving a navigation to about:blank. Ignore this initial document
+  // element.
+  if (!first_document_observed_) {
+    first_document_observed_ = true;
+    return;
+  }
+
+  // A new document element was created in a frame that did not commit a
+  // provisional load. This can be due to a doc.write in the frame that aborted
+  // a navigation. Create a page timing sender to track this load. This sender
+  // will only send resource usage updates to the browser process. There
+  // currently is not infrastructure in the browser process to monitor this case
+  // and properly handle timing updates without a committed load.
+  // TODO(https://crbug.com/1097127): Implement proper handling of timing
+  // updates in the browser process and create a normal page timing sender.
+
+  // It should not be possible to have a |provisional_frame_resource_data_use_|
+  // object at this point. If we did, it means we reached
+  // ReadyToCommitNavigation() and aborted prior to load commit which should not
+  // be possible.
+  DCHECK(!provisional_frame_resource_data_use_);
+
+  Timing timing = GetTiming();
+  page_timing_metrics_sender_ = std::make_unique<PageTimingMetricsSender>(
+      CreatePageTimingSender(true /* limited_sending_mode */), CreateTimer(),
+      std::move(timing.relative_timing), timing.monotonic_timing,
+      std::make_unique<PageResourceDataUse>());
+}
+
 void MetricsRenderFrameObserver::DidCommitProvisionalLoad(
     ui::PageTransition transition) {
   // Make sure to release the sender for a previous navigation, if we have one.
@@ -278,7 +332,7 @@ void MetricsRenderFrameObserver::DidCommitProvisionalLoad(
 
   Timing timing = GetTiming();
   page_timing_metrics_sender_ = std::make_unique<PageTimingMetricsSender>(
-      CreatePageTimingSender(), CreateTimer(),
+      CreatePageTimingSender(false /* limited_sending_mode*/), CreateTimer(),
       std::move(timing.relative_timing), timing.monotonic_timing,
       std::move(provisional_frame_resource_data_use_));
 }
@@ -311,7 +365,8 @@ void MetricsRenderFrameObserver::OnThroughputDataAvailable(
     int impl_percent,
     base::Optional<int> main_percent) {
   std::unique_ptr<MojoPageTimingSender> sender =
-      std::make_unique<MojoPageTimingSender>(render_frame());
+      std::make_unique<MojoPageTimingSender>(render_frame(),
+                                             false /* limited_sending_mode */);
   sender->SubmitThroughputData(source_id, aggregated_percent, impl_percent,
                                main_percent);
 }
@@ -580,9 +635,9 @@ std::unique_ptr<base::OneShotTimer> MetricsRenderFrameObserver::CreateTimer() {
 }
 
 std::unique_ptr<PageTimingSender>
-MetricsRenderFrameObserver::CreatePageTimingSender() {
+MetricsRenderFrameObserver::CreatePageTimingSender(bool limited_sending_mode) {
   return base::WrapUnique<PageTimingSender>(
-      new MojoPageTimingSender(render_frame()));
+      new MojoPageTimingSender(render_frame(), limited_sending_mode));
 }
 
 bool MetricsRenderFrameObserver::HasNoRenderFrame() const {

components/page_load_metrics/renderer/metrics_render_frame_observer.h

@@ -78,6 +78,7 @@ class MetricsRenderFrameObserver
       blink::WebDocumentLoader* document_loader) override;
   void DidFailProvisionalLoad() override;
   void DidCommitProvisionalLoad(ui::PageTransition transition) override;
+  void DidCreateDocumentElement() override;
   void OnDestruct() override;
 
   // Invoked when a frame is going away. This is our last chance to send IPCs
@@ -129,9 +130,14 @@ class MetricsRenderFrameObserver
   void SendMetrics();
   virtual Timing GetTiming() const;
   virtual std::unique_ptr<base::OneShotTimer> CreateTimer();
-  virtual std::unique_ptr<PageTimingSender> CreatePageTimingSender();
+  virtual std::unique_ptr<PageTimingSender> CreatePageTimingSender(
+      bool limited_sending_mode);
   virtual bool HasNoRenderFrame() const;
 
+  // Whether the initial about:blank document loaded into every frame was
+  // observed.
+  bool first_document_observed_ = false;
+
   // Collects the data use of the frame request for a provisional load until the
   // load is committed. We want to collect data use for completed navigations in
   // this class, but the various navigation callbacks do not provide enough data

components/page_load_metrics/renderer/metrics_render_frame_observer_unittest.cc

@@ -32,7 +32,8 @@ class TestMetricsRenderFrameObserver : public MetricsRenderFrameObserver,
     return std::move(timer);
   }
 
-  std::unique_ptr<PageTimingSender> CreatePageTimingSender() override {
+  std::unique_ptr<PageTimingSender> CreatePageTimingSender(
+      bool limited_sending_mode) override {
     return base::WrapUnique<PageTimingSender>(
         new FakePageTimingSender(&validator_));
   }