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,
+      const page_load_metrics::PageLoadTiming& template_timing)
+      : content::BrowserMessageFilter(PageLoadMetricsMsgStart),
+        template_timing_(template_timing) {
+    DCHECK(template_timing_.dom_content_loaded_event_start ||

[Bryan McQuade, 2017/02/16 18:18:14]

could you use !template_timing_.IsEmpty() here? I see you are excluding the
navigation_start field from testing - maybe to make this more future proof, and
given that it's non perf critical test code, you coul do this:

// Make sure at least one TimeDelta field is non-empty
PageLoadTiming tmp(template_timing_);
tmp.navigation_start = base::Time();
DCHECK(!tmp.IsEmpty());

[mattcary, 2017/02/17 09:37:47]

Thanks, IsEmpty is much better. I don't think the navigation_start field is
critical.

+           template_timing_.load_event_start || template_timing_.first_layout ||
+           template_timing_.first_paint || template_timing_.first_text_paint ||
+           template_timing_.first_image_paint ||
+           template_timing_.first_contentful_paint ||
+           template_timing_.first_meaningful_paint ||
+           template_timing_.parse_start || template_timing_.parse_stop);
+
+    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);
+  }
+
+  // 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();

[Bryan McQuade, 2017/02/16 18:18:14]

can we have this time out and fail after some amount of time (a few seconds)?
otherwise iiuc the test will hang forever if a matching IPC isn't received,
which seems undesirable.

[mattcary, 2017/02/17 09:37:47]

The test harness will time out tests. It seems better to continue to use that
mechanism rather than add an additional one---for example, there are
command-line flags that can adjust timeouts, which can be useful in debugging
things, and adding another timeout will complicate that.

+    run_loop_.reset(nullptr);
+  }
+
+ private:
+  bool OnMessageReceived(const IPC::Message& message) override {
+    DCHECK_CURRENTLY_ON(content::BrowserThread::IO);
+
+    bool unused;

[droger, 2017/02/16 16:33:12]

Do we really need this variable (since the function always return false anyway)?

[mattcary, 2017/02/16 17:43:28]

Probably not, but I didn't know what the convention was. I think we need the
IPC_MESSAGE_UNHANDLED in order to prevent the compiler from complaining about a
missing default: in the switch, but I didn't know if there was a convention
about what to put in as the argument.

I'll poke around the code and see if I can find a relevant example.

[mattcary, 2017/02/17 09:37:47]

Seems to work without the unhandled case. Hooray!

+    IPC_BEGIN_MESSAGE_MAP(TimingUpdatedObserver, message)
+      IPC_MESSAGE_HANDLER(PageLoadMetricsMsg_TimingUpdated, OnTimingUpdated)
+      IPC_MESSAGE_UNHANDLED(unused = false)
+    IPC_END_MESSAGE_MAP()
+
+    return false;
+  }
+
+  bool OnTimingUpdated(const page_load_metrics::PageLoadTiming& timing,
+                       const page_load_metrics::PageLoadMetadata& metadata) {
+    if ((template_timing_.dom_content_loaded_event_start &&
+         timing.dom_content_loaded_event_start) ||

[droger, 2017/02/16 16:33:12]

Not exactly sure what would be the use case for setting multiple fields in the
template, but intuitively I would use && instead of ||.

The use case would be that you would call WaitForMatchingIPC with a template
including all the fields you want to test, and then check them.


Using || might also work, but then you need to call WaitForMatchingIPC multiple
times with different templates?

[mattcary, 2017/02/16 17:43:28]

Since I'm just checking on the single metric it's all theoretical :)

I can change to && unless Bryan has an objection.

[Bryan McQuade, 2017/02/16 18:18:14]

yeah i think i agree that we should verify that all specified values in the
template are set in the IPC value. it's ok for a value to be present in the IPC
value but not in the template, though.

[mattcary, 2017/02/17 09:37:47]

Done.

+        (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;
+};
+
+}  // 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> CreateFCPTimingUpdatedObserver() {
+    content::WebContents* web_contents =
+        browser()->tab_strip_model()->GetActiveWebContents();
+    page_load_metrics::PageLoadTiming template_timing;
+    template_timing.first_contentful_paint =

[Bryan McQuade, 2017/02/16 18:18:14]

maybe add a comment noting that the actual value is unimportant, and that all we
want to do is make sure the value is set?

[mattcary, 2017/02/17 09:37:47]

Done.

+        base::TimeDelta::FromInternalValue(1);
+    scoped_refptr<TimingUpdatedObserver> observer(new TimingUpdatedObserver(
+        web_contents->GetRenderViewHost()->GetWidget(), template_timing));
+    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 448 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);
 }