Buffer cross frame paint timing updates.

chrome/browser/page_load_metrics/metrics_web_contents_observer_unittest.cc

 // Copyright 2015 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/browser/page_load_metrics/metrics_web_contents_observer.h"
 
 #include <memory>
 #include <vector>
 
 #include "base/macros.h"
 #include "base/memory/ptr_util.h"
+#include "base/memory/weak_ptr.h"
 #include "base/process/kill.h"
 #include "base/test/histogram_tester.h"
 #include "base/time/time.h"
+#include "base/timer/mock_timer.h"
 #include "chrome/browser/page_load_metrics/metrics_navigation_throttle.h"
 #include "chrome/browser/page_load_metrics/page_load_metrics_embedder_interface.h"
 #include "chrome/browser/page_load_metrics/page_load_metrics_observer.h"
+#include "chrome/browser/page_load_metrics/page_load_metrics_update_dispatcher.h"
 #include "chrome/browser/page_load_metrics/page_load_tracker.h"
 #include "chrome/common/page_load_metrics/page_load_metrics_messages.h"
 #include "chrome/common/url_constants.h"
 #include "chrome/test/base/chrome_render_view_host_test_harness.h"
 #include "content/public/browser/navigation_handle.h"
 #include "content/public/browser/render_frame_host.h"
 #include "content/public/test/test_renderer_host.h"
 #include "content/public/test/web_contents_tester.h"
 #include "testing/gtest/include/gtest/gtest.h"
 #include "url/gurl.h"
 
 namespace page_load_metrics {
 
 namespace {
 
 const char kDefaultTestUrl[] = "https://google.com/";
 const char kDefaultTestUrlAnchor[] = "https://google.com/#samedocument";
 const char kDefaultTestUrl2[] = "https://whatever.com/";
 const char kFilteredStartUrl[] = "https://whatever.com/ignore-on-start";
 const char kFilteredCommitUrl[] = "https://whatever.com/ignore-on-commit";
 
+class WeakMockTimer : public base::MockTimer,
+                      public base::SupportsWeakPtr<WeakMockTimer> {
+ public:
+  WeakMockTimer()
+      : MockTimer(false /* retain_user_task */, false /* is_repeating */) {}
+};
+
 // Simple PageLoadMetricsObserver that copies observed PageLoadTimings into the
 // provided std::vector, so they can be analyzed by unit tests.
 class TestPageLoadMetricsObserver : public PageLoadMetricsObserver {
  public:
   TestPageLoadMetricsObserver(
       std::vector<mojom::PageLoadTimingPtr>* updated_timings,
       std::vector<mojom::PageLoadTimingPtr>* updated_subframe_timings,
       std::vector<mojom::PageLoadTimingPtr>* complete_timings,
       std::vector<GURL>* observed_committed_urls)
       : updated_timings_(updated_timings),
@@ skipping 73 matching lines @@
 
   bool IsNewTabPageUrl(const GURL& url) override { return is_ntp_; }
   void set_is_ntp(bool is_ntp) { is_ntp_ = is_ntp; }
   void RegisterObservers(PageLoadTracker* tracker) override {
     tracker->AddObserver(base::MakeUnique<TestPageLoadMetricsObserver>(
         &updated_timings_, &updated_subframe_timings_, &complete_timings_,
         &observed_committed_urls_));
     tracker->AddObserver(base::MakeUnique<FilteringPageLoadMetricsObserver>(
         &completed_filtered_urls_));
   }
+  std::unique_ptr<base::Timer> CreateTimer() override {
+    std::unique_ptr<WeakMockTimer> timer = base::MakeUnique<WeakMockTimer>();
+    most_recent_timer_ = timer->AsWeakPtr();
+    return std::move(timer);
+  }
   const std::vector<mojom::PageLoadTimingPtr>& updated_timings() const {
     return updated_timings_;
   }
   const std::vector<mojom::PageLoadTimingPtr>& complete_timings() const {
     return complete_timings_;
   }
   const std::vector<mojom::PageLoadTimingPtr>& updated_subframe_timings()
       const {
     return updated_subframe_timings_;
   }
 
   // currently_committed_urls passed to OnStart().
   const std::vector<GURL>& observed_committed_urls_from_on_start() const {
     return observed_committed_urls_;
   }
 
   // committed URLs passed to FilteringPageLoadMetricsObserver::OnComplete().
   const std::vector<GURL>& completed_filtered_urls() const {
     return completed_filtered_urls_;
   }
+  base::MockTimer* GetMostRecentTimer() const {
+    return most_recent_timer_.get();
+  }
 
  private:
   std::vector<mojom::PageLoadTimingPtr> updated_timings_;
   std::vector<mojom::PageLoadTimingPtr> updated_subframe_timings_;
   std::vector<mojom::PageLoadTimingPtr> complete_timings_;
   std::vector<GURL> observed_committed_urls_;
   std::vector<GURL> completed_filtered_urls_;
+  base::WeakPtr<WeakMockTimer> most_recent_timer_;
   bool is_ntp_;
 };
 
+void PopulatePageLoadTiming(mojom::PageLoadTiming* timing) {
+  page_load_metrics::InitPageLoadTimingForTest(timing);
+  timing->navigation_start = base::Time::FromDoubleT(1);
+  timing->response_start = base::TimeDelta::FromMilliseconds(10);
+  timing->parse_timing->parse_start = base::TimeDelta::FromMilliseconds(20);
+  timing->document_timing->first_layout = base::TimeDelta::FromMilliseconds(30);
+}
+
 }  //  namespace
 
 class MetricsWebContentsObserverTest : public ChromeRenderViewHostTestHarness {
  public:
   MetricsWebContentsObserverTest() : num_errors_(0) {}
 
   void SetUp() override {
     ChromeRenderViewHostTestHarness::SetUp();
     AttachObserver();
   }
 
   void NavigateToUntrackedUrl() {
     content::WebContentsTester::For(web_contents())
         ->NavigateAndCommit(GURL(url::kAboutBlankURL));
   }
 
+  // Returns the mock timer used for buffering updates in the
+  // PageLoadMetricsUpdateDispatcher.
+  base::MockTimer* GetMostRecentTimer() {
+    return embedder_interface_->GetMostRecentTimer();
+  }
+
   void SimulateTimingUpdate(const mojom::PageLoadTiming& timing) {
     SimulateTimingUpdate(timing, web_contents()->GetMainFrame());
   }
 
   void SimulateTimingUpdate(const mojom::PageLoadTiming& timing,
                             content::RenderFrameHost* render_frame_host) {
+    SimulateTimingUpdateWithoutFiringDispatchTimer(timing, render_frame_host);
+    // If sending the timing update caused the PageLoadMetricsUpdateDispatcher
+    // to schedule a buffering timer, then fire it now so metrics are dispatched
+    // to observers.
+    base::MockTimer* mock_timer = GetMostRecentTimer();
+    if (mock_timer && mock_timer->IsRunning())
+      mock_timer->Fire();
+  }
+
+  void SimulateTimingUpdateWithoutFiringDispatchTimer(
+      const mojom::PageLoadTiming& timing,
+      content::RenderFrameHost* render_frame_host) {
     observer()->OnTimingUpdated(render_frame_host, timing,
                                 mojom::PageLoadMetadata());
   }
 
   void AttachObserver() {
     auto embedder_interface =
         base::MakeUnique<TestPageLoadMetricsEmbedderInterface>();
     embedder_interface_ = embedder_interface.get();
     MetricsWebContentsObserver* observer =
         MetricsWebContentsObserver::CreateForWebContents(
@@ skipping 534 matching lines @@
 
   ASSERT_EQ(1, CountUpdatedTimingReported());
   EXPECT_TRUE(timing.Equals(*updated_timings().back()));
 
   content::RenderFrameHostTester* rfh_tester =
       content::RenderFrameHostTester::For(main_rfh());
   content::RenderFrameHost* subframe = rfh_tester->AppendChild("subframe");
 
   // Dispatch a timing update for the child frame that includes a first paint.
   mojom::PageLoadTiming subframe_timing;
-  page_load_metrics::InitPageLoadTimingForTest(&subframe_timing);
-  subframe_timing.navigation_start = base::Time::FromDoubleT(2);
-  subframe_timing.response_start = base::TimeDelta::FromMilliseconds(10);
-  subframe_timing.parse_timing->parse_start =
-      base::TimeDelta::FromMilliseconds(20);
-  subframe_timing.document_timing->first_layout =
-      base::TimeDelta::FromMilliseconds(30);
+  PopulatePageLoadTiming(&subframe_timing);
   subframe_timing.paint_timing->first_paint =
       base::TimeDelta::FromMilliseconds(40);
   content::RenderFrameHostTester* subframe_tester =
       content::RenderFrameHostTester::For(subframe);
   subframe_tester->SimulateNavigationStart(GURL(kDefaultTestUrl2));
   subframe_tester->SimulateNavigationCommit(GURL(kDefaultTestUrl2));
   SimulateTimingUpdate(subframe_timing, subframe);
   subframe_tester->SimulateNavigationStop();
 
   // Though a first paint was dispatched in the child, it should not yet be
@@ skipping 35 matching lines @@
   ASSERT_EQ(1, CountCompleteTimingReported());
   ASSERT_EQ(2, CountUpdatedTimingReported());
   ASSERT_EQ(0, CountEmptyCompleteTimingReported());
 
   ASSERT_EQ(1, CountUpdatedSubFrameTimingReported());
   EXPECT_TRUE(subframe_timing.Equals(*updated_subframe_timings().back()));
 
   CheckNoErrorEvents();
 }
 
+// We buffer cross-frame paint updates to account for paint timings from
+// different frames arriving out of order.
+TEST_F(MetricsWebContentsObserverTest, OutOfOrderCrossFrameTiming2) {
+  // Dispatch a timing update for the main frame that includes a first
+  // paint. This should be buffered, with the dispatch timer running.
+  mojom::PageLoadTiming timing;
+  PopulatePageLoadTiming(&timing);
+  timing.paint_timing->first_paint = base::TimeDelta::FromMilliseconds(1000);
+  content::WebContentsTester* web_contents_tester =
+      content::WebContentsTester::For(web_contents());
+  web_contents_tester->NavigateAndCommit(GURL(kDefaultTestUrl));
+  SimulateTimingUpdateWithoutFiringDispatchTimer(timing, main_rfh());
+
+  EXPECT_TRUE(GetMostRecentTimer()->IsRunning());
+  ASSERT_EQ(0, CountUpdatedTimingReported());
+
+  content::RenderFrameHostTester* rfh_tester =
+      content::RenderFrameHostTester::For(main_rfh());
+
+  // Dispatch a timing update for a child frame that includes a first paint.
+  mojom::PageLoadTiming subframe_timing;
+  PopulatePageLoadTiming(&subframe_timing);
+  subframe_timing.paint_timing->first_paint =
+      base::TimeDelta::FromMilliseconds(500);
+  content::RenderFrameHost* subframe = rfh_tester->AppendChild("subframe");
+  content::RenderFrameHostTester* subframe_tester =
+      content::RenderFrameHostTester::For(subframe);
+  subframe_tester->SimulateNavigationStart(GURL(kDefaultTestUrl2));
+  subframe_tester->SimulateNavigationCommit(GURL(kDefaultTestUrl2));
+  SimulateTimingUpdateWithoutFiringDispatchTimer(subframe_timing, subframe);
+  subframe_tester->SimulateNavigationStop();
+
+  histogram_tester_.ExpectTotalCount(
+      page_load_metrics::internal::kHistogramOutOfOrderTiming, 1);
+
+  EXPECT_TRUE(GetMostRecentTimer()->IsRunning());
+  ASSERT_EQ(0, CountUpdatedTimingReported());
+
+  // At this point, the timing update is buffered, waiting for the timer to
+  // fire.
+  GetMostRecentTimer()->Fire();
+
+  // Firing the timer should produce a timing update. The update should be a
+  // merged view of the main frame timing, with a first paint timestamp from the
+  // subframe.
+  ASSERT_EQ(1, CountUpdatedTimingReported());
+  EXPECT_FALSE(timing.Equals(*updated_timings().back()));
+  EXPECT_TRUE(
+      updated_timings().back()->parse_timing->Equals(*timing.parse_timing));
+  EXPECT_TRUE(updated_timings().back()->document_timing->Equals(
+      *timing.document_timing));
+  EXPECT_FALSE(
+      updated_timings().back()->paint_timing->Equals(*timing.paint_timing));
+  EXPECT_TRUE(updated_timings().back()->paint_timing->first_paint);
+
+  // The first paint value should be the min of all received first paints, wich

[Charlie Harrison, 2017/05/26 19:31:34]

which

[Bryan McQuade, 2017/05/26 20:07:32]

Done

+  // in this case is the first paint from the subframe. Since it is offset by
+  // the subframe's navigation start, the received value should be >= the first
+  // paint value specified in the subframe.
+  EXPECT_GE(updated_timings().back()->paint_timing->first_paint,
+            subframe_timing.paint_timing->first_paint);
+  EXPECT_LT(updated_timings().back()->paint_timing->first_paint,
+            timing.paint_timing->first_paint);
+
+  base::TimeDelta initial_first_paint =
+      updated_timings().back()->paint_timing->first_paint.value();
+
+  // Dispatch a timing update for an additional child frame, with an earlier
+  // first paint time. This should cause an immediate update, without a timer
+  // delay.
+  subframe_timing.paint_timing->first_paint =
+      base::TimeDelta::FromMilliseconds(50);
+  content::RenderFrameHost* subframe2 = rfh_tester->AppendChild("subframe");
+  content::RenderFrameHostTester* subframe2_tester =
+      content::RenderFrameHostTester::For(subframe2);
+  subframe2_tester->SimulateNavigationStart(GURL(kDefaultTestUrl2));
+  subframe2_tester->SimulateNavigationCommit(GURL(kDefaultTestUrl2));
+  SimulateTimingUpdateWithoutFiringDispatchTimer(subframe_timing, subframe2);
+  subframe2_tester->SimulateNavigationStop();
+
+  base::TimeDelta updated_first_paint =
+      updated_timings().back()->paint_timing->first_paint.value();
+
+  EXPECT_FALSE(GetMostRecentTimer()->IsRunning());
+  ASSERT_EQ(2, CountUpdatedTimingReported());
+  EXPECT_LT(updated_first_paint, initial_first_paint);
+
+  histogram_tester_.ExpectTotalCount(
+      page_load_metrics::internal::kHistogramOutOfOrderTimingBuffered, 1);
+  histogram_tester_.ExpectBucketCount(
+      page_load_metrics::internal::kHistogramOutOfOrderTimingBuffered,
+      (initial_first_paint - updated_first_paint).InMilliseconds(), 1);
+
+  CheckNoErrorEvents();
+}
+
 }  // namespace page_load_metrics