Prerender: fix flaky page load metrics tests

chrome/browser/page_load_metrics/page_load_metrics_browsertest.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 "base/files/scoped_temp_dir.h"
 #include "base/macros.h"
 #include "base/test/histogram_tester.h"
 #include "base/time/time.h"
 #include "chrome/browser/page_load_metrics/metrics_web_contents_observer.h"
 #include "chrome/browser/page_load_metrics/observers/aborts_page_load_metrics_observer.h"
 #include "chrome/browser/page_load_metrics/observers/core_page_load_metrics_observer.h"
 #include "chrome/browser/page_load_metrics/observers/document_write_page_load_metrics_observer.h"
 #include "chrome/browser/page_load_metrics/observers/no_state_prefetch_page_load_metrics_observer.h"
 #include "chrome/browser/page_load_metrics/page_load_tracker.h"
 #include "chrome/browser/prerender/prerender_histograms.h"
 #include "chrome/browser/prerender/prerender_origin.h"
 #include "chrome/browser/profiles/profile.h"
 #include "chrome/browser/ui/browser.h"
 #include "chrome/browser/ui/browser_navigator_params.h"
 #include "chrome/browser/ui/tabs/tab_strip_model.h"
+#include "chrome/common/page_load_metrics/page_load_metrics_messages.h"
 #include "chrome/common/pref_names.h"
 #include "chrome/common/url_constants.h"
 #include "chrome/test/base/in_process_browser_test.h"
 #include "chrome/test/base/ui_test_utils.h"
 #include "components/prefs/pref_service.h"
 #include "content/public/browser/browser_thread.h"
+#include "content/public/browser/render_process_host.h"
+#include "content/public/browser/render_view_host.h"
 #include "content/public/test/browser_test_utils.h"
 #include "content/public/test/download_test_observer.h"
 #include "net/http/failing_http_transaction_factory.h"
 #include "net/http/http_cache.h"
 #include "net/test/embedded_test_server/embedded_test_server.h"
 #include "net/test/url_request/url_request_failed_job.h"
 #include "net/url_request/url_request_context.h"
 #include "net/url_request/url_request_context_getter.h"
 
+namespace {
+
+// Waits until a PageLoadMetricsMsg_TimingUpdated message IPC is received
+// matching a PageLoadTiming. See WaitForMatchingIPC for details.
+class TimingUpdatedObserver : public content::BrowserMessageFilter {
+ public:
+  explicit TimingUpdatedObserver(content::RenderWidgetHost* render_widget_host)
+      : content::BrowserMessageFilter(PageLoadMetricsMsgStart) {
+    render_widget_host->GetProcess()->AddFilter(this);
+
+    // Roundtrip to the IO thread, to ensure that the filter is properly
+    // installed.
+    content::BrowserThread::PostTaskAndReply(
+        content::BrowserThread::IO, FROM_HERE, base::Bind(&base::DoNothing),
+        base::Bind(&TimingUpdatedObserver::Quit, this));
+    run_loop_.reset(new base::RunLoop());
+    run_loop_->Run();
+    run_loop_.reset(nullptr);
+  }
+
+  // Instructs observer to also watch for |count|
+  // WebLoadingBehaviorDocumentWriteBlockReload events.
+  void MatchDocumentWriteBlockReload(int count) {
+    match_document_write_block_reload_ = count;
+  }
+
+  // Waits for a TimingUpdated IPC that matches the template PageLoadTiming
+  // given to the constructor. An IPC matches when its PageLoadTiming contains a
+  // non-zero field that is non-zero in the template.
+  void WaitForMatchingIPC() {
+    DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
+    if (matched_timing_update_)
+      return;
+
+    run_loop_.reset(new base::RunLoop());
+    run_loop_->Run();
+    run_loop_.reset(nullptr);
+  }
+
+  page_load_metrics::PageLoadTiming* template_timing() {

[Bryan McQuade, 2017/02/17 18:54:48]

looking at this some more i think my suggestion to use a PageLoadTiming to do
matching was perhaps not so great. the '// Set to nonzero for matching.' bits
are a touch confusing.

in hindsight I think I prefer a bitfield enum e.g.
enum ExpectedTimingFields {
  FIRST_PAINT = 1<<0;
  FIRST_CONTENTFUL_PAINT = 1<<1;
}

which you pass into the constructor of the TimingUpdatedObserver.

I'm fine leaving it as you have it, but feel free to make this change if you
think it's better and doesn't add too much complexity.

we could extend the enum only as needed.

[mattcary, 2017/02/20 10:25:25]

Done.

+    return &template_timing_;
+  }
+
+ private:
+  bool OnMessageReceived(const IPC::Message& message) override {
+    DCHECK_CURRENTLY_ON(content::BrowserThread::IO);
+
+    IPC_BEGIN_MESSAGE_MAP(TimingUpdatedObserver, message)
+      IPC_MESSAGE_HANDLER(PageLoadMetricsMsg_TimingUpdated, OnTimingUpdated)
+    IPC_END_MESSAGE_MAP()
+
+    return false;
+  }
+
+  bool OnTimingUpdated(const page_load_metrics::PageLoadTiming& timing,
+                       const page_load_metrics::PageLoadMetadata& metadata) {
+    if (match_document_write_block_reload_ > 0 &&
+        metadata.behavior_flags &
+            blink::WebLoadingBehaviorFlag::
+                WebLoadingBehaviorDocumentWriteBlockReload) {
+      --match_document_write_block_reload_;
+    }
+
+    if (match_document_write_block_reload_ > 0) {
+      return true;
+    }
+
+    if ((!template_timing_.dom_content_loaded_event_start ||
+         timing.dom_content_loaded_event_start) &&
+        (!template_timing_.load_event_start || timing.load_event_start) &&
+        (!template_timing_.first_layout || timing.first_layout) &&
+        (!template_timing_.first_paint || timing.first_paint) &&
+        (!template_timing_.first_text_paint || timing.first_text_paint) &&
+        (!template_timing_.first_image_paint || timing.first_image_paint) &&
+        (!template_timing_.first_contentful_paint ||
+         timing.first_contentful_paint) &&
+        (!template_timing_.first_meaningful_paint ||
+         timing.first_meaningful_paint) &&
+        (!template_timing_.parse_start || timing.parse_start) &&
+        (!template_timing_.parse_stop || timing.parse_stop)) {
+      // Ensure that any other handlers of this message, for example the real
+      // PageLoadMetric observers, get a chance to handle this message before
+      // this waiter unblocks.
+      content::BrowserThread::PostTask(
+          content::BrowserThread::IO, FROM_HERE,
+          base::Bind(&TimingUpdatedObserver::BounceTimingUpdate, this, timing,
+                     metadata));
+    }
+    return true;
+  }
+
+  void BounceTimingUpdate(const page_load_metrics::PageLoadTiming& timing,
+                          const page_load_metrics::PageLoadMetadata& metadata) {
+    content::BrowserThread::PostTask(
+        content::BrowserThread::UI, FROM_HERE,
+        base::Bind(&TimingUpdatedObserver::SetTimingUpdatedAndQuit, this));
+  }
+
+  void Quit() {
+    DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
+    if (run_loop_)
+      run_loop_->Quit();
+  }
+
+  void SetTimingUpdatedAndQuit() {
+    DCHECK_CURRENTLY_ON(content::BrowserThread::UI);
+    matched_timing_update_ = true;
+    Quit();
+  }
+
+  ~TimingUpdatedObserver() override {}
+
+  std::unique_ptr<base::RunLoop> run_loop_;
+  page_load_metrics::PageLoadTiming template_timing_;
+  bool matched_timing_update_ = false;
+  int match_document_write_block_reload_ = 0;
+};
+
+}  // namespace
+
 class PageLoadMetricsBrowserTest : public InProcessBrowserTest {
  public:
   PageLoadMetricsBrowserTest() {}
   ~PageLoadMetricsBrowserTest() override {}
 
  protected:
   void NavigateToUntrackedUrl() {
     ui_test_utils::NavigateToURL(browser(), GURL(url::kAboutBlankURL));
   }
 
   bool NoPageLoadMetricsRecorded() {
     return histogram_tester_.GetTotalCountsForPrefix("PageLoad.").empty();
   }
 
+  scoped_refptr<TimingUpdatedObserver> CreateEmptyTimingUpdatedObserver() {
+    content::WebContents* web_contents =
+        browser()->tab_strip_model()->GetActiveWebContents();
+    scoped_refptr<TimingUpdatedObserver> observer(new TimingUpdatedObserver(
+        web_contents->GetRenderViewHost()->GetWidget()));
+    return observer;
+  }
+
+  scoped_refptr<TimingUpdatedObserver> CreateFCPTimingUpdatedObserver() {
+    scoped_refptr<TimingUpdatedObserver> observer =
+        CreateEmptyTimingUpdatedObserver();
+    observer->template_timing()->first_contentful_paint =
+        base::TimeDelta::FromInternalValue(1);  // Set to nonzero for matching.
+    return observer;
+  }
+
   base::HistogramTester histogram_tester_;
 
  private:
   DISALLOW_COPY_AND_ASSIGN(PageLoadMetricsBrowserTest);
 };
 
 void FailAllNetworkTransactions(net::URLRequestContextGetter* getter) {
   DCHECK_CURRENTLY_ON(content::BrowserThread::IO);
   net::HttpCache* cache(
       getter->GetURLRequestContext()->http_transaction_factory()->GetCache());
@@ skipping 131 matching lines @@
       browser(), embedded_test_server()->GetURL("/download-test3.gif"));
   downloads_observer.WaitForFinished();
 
   NavigateToUntrackedUrl();
   EXPECT_TRUE(NoPageLoadMetricsRecorded());
 }
 
 IN_PROC_BROWSER_TEST_F(PageLoadMetricsBrowserTest, PreloadDocumentWrite) {
   ASSERT_TRUE(embedded_test_server()->Start());
 
+  scoped_refptr<TimingUpdatedObserver> fcp_observer =
+      CreateFCPTimingUpdatedObserver();
+
   ui_test_utils::NavigateToURL(
       browser(), embedded_test_server()->GetURL(
                      "/page_load_metrics/document_write_external_script.html"));
-  NavigateToUntrackedUrl();
+  fcp_observer->WaitForMatchingIPC();
 
   histogram_tester_.ExpectTotalCount(
       internal::kHistogramDocWriteParseStartToFirstContentfulPaint, 1);
 }
 
 IN_PROC_BROWSER_TEST_F(PageLoadMetricsBrowserTest, NoPreloadDocumentWrite) {
   ASSERT_TRUE(embedded_test_server()->Start());
 
   ui_test_utils::NavigateToURL(
       browser(), embedded_test_server()->GetURL(
                      "/page_load_metrics/document_write_no_script.html"));
   NavigateToUntrackedUrl();
 
   histogram_tester_.ExpectTotalCount(
       internal::kHistogramDocWriteParseStartToFirstContentfulPaint, 0);
 }
 
 IN_PROC_BROWSER_TEST_F(PageLoadMetricsBrowserTest, NoDocumentWrite) {
   ASSERT_TRUE(embedded_test_server()->Start());
 
+  scoped_refptr<TimingUpdatedObserver> fcp_observer =
+      CreateFCPTimingUpdatedObserver();
+
   ui_test_utils::NavigateToURL(browser(),
                                embedded_test_server()->GetURL("/title1.html"));
-  NavigateToUntrackedUrl();
+  fcp_observer->WaitForMatchingIPC();
+
   histogram_tester_.ExpectTotalCount(
       internal::kHistogramDocWriteParseStartToFirstContentfulPaint, 0);
   histogram_tester_.ExpectTotalCount(
       internal::kHistogramDocWriteBlockParseStartToFirstContentfulPaint, 0);
   histogram_tester_.ExpectTotalCount(internal::kHistogramDocWriteBlockCount, 0);
 }
 
 IN_PROC_BROWSER_TEST_F(PageLoadMetricsBrowserTest, DocumentWriteBlock) {
   ASSERT_TRUE(embedded_test_server()->Start());
 
+  scoped_refptr<TimingUpdatedObserver> fcp_observer =
+      CreateFCPTimingUpdatedObserver();
+
   ui_test_utils::NavigateToURL(
       browser(), embedded_test_server()->GetURL(
                      "/page_load_metrics/document_write_script_block.html"));
-  NavigateToUntrackedUrl();
+  fcp_observer->WaitForMatchingIPC();
 
   histogram_tester_.ExpectTotalCount(
       internal::kHistogramDocWriteBlockParseStartToFirstContentfulPaint, 1);
   histogram_tester_.ExpectTotalCount(internal::kHistogramDocWriteBlockCount, 1);
 }
 
 IN_PROC_BROWSER_TEST_F(PageLoadMetricsBrowserTest, DocumentWriteReload) {
   ASSERT_TRUE(embedded_test_server()->Start());
 
+  scoped_refptr<TimingUpdatedObserver> fcp_observer =
+      CreateFCPTimingUpdatedObserver();
+  scoped_refptr<TimingUpdatedObserver> reload_observer =
+      CreateEmptyTimingUpdatedObserver();
+  reload_observer->MatchDocumentWriteBlockReload(2);
+
   ui_test_utils::NavigateToURL(
       browser(), embedded_test_server()->GetURL(
                      "/page_load_metrics/document_write_script_block.html"));
 
   // Reload should not log the histogram as the script is not blocked.
   ui_test_utils::NavigateToURL(
       browser(), embedded_test_server()->GetURL(
                      "/page_load_metrics/document_write_script_block.html"));
 
   ui_test_utils::NavigateToURL(
       browser(), embedded_test_server()->GetURL(
                      "/page_load_metrics/document_write_script_block.html"));
 
   histogram_tester_.ExpectTotalCount(
       internal::kHistogramDocWriteBlockParseStartToFirstContentfulPaint, 1);
 
-  NavigateToUntrackedUrl();
+  fcp_observer->WaitForMatchingIPC();
+  reload_observer->WaitForMatchingIPC();
 
   histogram_tester_.ExpectTotalCount(
       internal::kHistogramDocWriteBlockParseStartToFirstContentfulPaint, 1);
 
   histogram_tester_.ExpectTotalCount(
       internal::kHistogramDocWriteBlockReloadCount, 2);
   histogram_tester_.ExpectTotalCount(internal::kHistogramDocWriteBlockCount, 1);
 }
 
 IN_PROC_BROWSER_TEST_F(PageLoadMetricsBrowserTest, DocumentWriteAsync) {
@@ skipping 31 matching lines @@
   NavigateToUntrackedUrl();
 
   histogram_tester_.ExpectTotalCount(
       internal::kHistogramDocWriteBlockParseStartToFirstContentfulPaint, 0);
   histogram_tester_.ExpectTotalCount(internal::kHistogramDocWriteBlockCount, 0);
 }
 
 IN_PROC_BROWSER_TEST_F(PageLoadMetricsBrowserTest, BadXhtml) {
   ASSERT_TRUE(embedded_test_server()->Start());
 
+  scoped_refptr<TimingUpdatedObserver> timing_observer =
+      CreateEmptyTimingUpdatedObserver();
+  timing_observer->template_timing()->first_paint =
+      base::TimeDelta::FromInternalValue(1);  // Set to nonzero for matching.
+
   // When an XHTML page contains invalid XML, it causes a paint of the error
   // message without a layout. Page load metrics currently treats this as an
   // error. Eventually, we'll fix this by special casing the handling of
   // documents with non-well-formed XML on the blink side. See crbug.com/627607
   // for more.
   ui_test_utils::NavigateToURL(
       browser(),
       embedded_test_server()->GetURL("/page_load_metrics/badxml.xhtml"));
-  NavigateToUntrackedUrl();
+
+  timing_observer->WaitForMatchingIPC();
 
   histogram_tester_.ExpectTotalCount(internal::kHistogramFirstLayout, 0);
   histogram_tester_.ExpectTotalCount(internal::kHistogramFirstPaint, 0);
   histogram_tester_.ExpectBucketCount(page_load_metrics::internal::kErrorEvents,
                                       page_load_metrics::ERR_BAD_TIMING_IPC, 1);
 }
 
 // Test code that aborts provisional navigations.
 // TODO(csharrison): Move these to unit tests once the navigation API in content
 // properly calls NavigationHandle/NavigationThrottle methods.
@@ skipping 170 matching lines @@
 
   histogram_tester_.ExpectUniqueSample(
       internal::kHistogramFirstMeaningfulPaintStatus,
       internal::FIRST_MEANINGFUL_PAINT_DID_NOT_REACH_NETWORK_STABLE, 1);
   histogram_tester_.ExpectTotalCount(
       internal::kHistogramFirstMeaningfulPaint, 0);
   histogram_tester_.ExpectTotalCount(
       internal::kHistogramParseStartToFirstMeaningfulPaint, 0);
 }
 
-// Flaky on Linux (timing out or failing in an expectation) crbug.com/657022
-#if defined(OS_LINUX)
-#define MAYBE_NoStatePrefetchObserverCacheable \
-  DISABLED_NoStatePrefetchObserverCacheable
-#else
-#define MAYBE_NoStatePrefetchObserverCacheable NoStatePrefetchObserverCacheable
-#endif
 IN_PROC_BROWSER_TEST_F(PageLoadMetricsBrowserTest,
-                       MAYBE_NoStatePrefetchObserverCacheable) {
+                       NoStatePrefetchObserverCacheable) {
   ASSERT_TRUE(embedded_test_server()->Start());
 
+  scoped_refptr<TimingUpdatedObserver> fcp_observer =
+      CreateFCPTimingUpdatedObserver();
+
   ui_test_utils::NavigateToURL(browser(),
                                embedded_test_server()->GetURL("/title1.html"));
-  NavigateToUntrackedUrl();
+
+  fcp_observer->WaitForMatchingIPC();
 
   histogram_tester_.ExpectTotalCount(
       "Prerender.none_PrefetchTTFCP.Reference.NoStore.Visible", 0);
   histogram_tester_.ExpectTotalCount(
       "Prerender.none_PrefetchTTFCP.Reference.Cacheable.Visible", 1);
 }
 
-// Flaky on Linux (timing out or failing in an expectation) crbug.com/657022
-#if defined(OS_LINUX)
-#define MAYBE_NoStatePrefetchObserverNoStore \
-  DISABLED_NoStatePrefetchObserverNoStore
-#else
-#define MAYBE_NoStatePrefetchObserverNoStore NoStatePrefetchObserverNoStore
-#endif
 IN_PROC_BROWSER_TEST_F(PageLoadMetricsBrowserTest,
-                       MAYBE_NoStatePrefetchObserverNoStore) {
+                       NoStatePrefetchObserverNoStore) {
   ASSERT_TRUE(embedded_test_server()->Start());
 
+  scoped_refptr<TimingUpdatedObserver> fcp_observer =
+      CreateFCPTimingUpdatedObserver();
+
   ui_test_utils::NavigateToURL(browser(),
                                embedded_test_server()->GetURL("/nostore.html"));
-  NavigateToUntrackedUrl();
+
+  fcp_observer->WaitForMatchingIPC();
 
   histogram_tester_.ExpectTotalCount(
       "Prerender.none_PrefetchTTFCP.Reference.NoStore.Visible", 1);
   histogram_tester_.ExpectTotalCount(
       "Prerender.none_PrefetchTTFCP.Reference.Cacheable.Visible", 0);
 }
 
 IN_PROC_BROWSER_TEST_F(PageLoadMetricsBrowserTest, CSSTiming) {
   ASSERT_TRUE(embedded_test_server()->Start());
 
@@ skipping 21 matching lines @@
   ui_test_utils::NavigateToURL(browser(), embedded_test_server()->GetURL(
                                               "/page_load_metrics/large.html"));
   NavigateToUntrackedUrl();
 
   histogram_tester_.ExpectTotalCount(internal::kHistogramTotalBytes, 1);
 
   // Verify that there is a single sample recorded in the 10kB bucket (the size
   // of the main HTML response).
   histogram_tester_.ExpectBucketCount(internal::kHistogramTotalBytes, 10, 1);
 }