OLD | NEW |
1 // Copyright 2015 The Chromium Authors. All rights reserved. | 1 // Copyright 2015 The Chromium Authors. All rights reserved. |
2 // Use of this source code is governed by a BSD-style license that can be | 2 // Use of this source code is governed by a BSD-style license that can be |
3 // found in the LICENSE file. | 3 // found in the LICENSE file. |
4 | 4 |
5 #include "chrome/browser/page_load_metrics/metrics_web_contents_observer.h" | 5 #include "chrome/browser/page_load_metrics/metrics_web_contents_observer.h" |
6 | 6 |
7 #include <memory> | 7 #include <memory> |
8 #include <vector> | 8 #include <vector> |
9 | 9 |
10 #include "base/macros.h" | 10 #include "base/macros.h" |
11 #include "base/memory/ptr_util.h" | 11 #include "base/memory/ptr_util.h" |
| 12 #include "base/memory/weak_ptr.h" |
12 #include "base/process/kill.h" | 13 #include "base/process/kill.h" |
13 #include "base/test/histogram_tester.h" | 14 #include "base/test/histogram_tester.h" |
14 #include "base/time/time.h" | 15 #include "base/time/time.h" |
| 16 #include "base/timer/mock_timer.h" |
15 #include "chrome/browser/page_load_metrics/metrics_navigation_throttle.h" | 17 #include "chrome/browser/page_load_metrics/metrics_navigation_throttle.h" |
16 #include "chrome/browser/page_load_metrics/page_load_metrics_embedder_interface.
h" | 18 #include "chrome/browser/page_load_metrics/page_load_metrics_embedder_interface.
h" |
17 #include "chrome/browser/page_load_metrics/page_load_metrics_observer.h" | 19 #include "chrome/browser/page_load_metrics/page_load_metrics_observer.h" |
18 #include "chrome/browser/page_load_metrics/page_load_tracker.h" | 20 #include "chrome/browser/page_load_metrics/page_load_tracker.h" |
19 #include "chrome/common/page_load_metrics/page_load_metrics_messages.h" | 21 #include "chrome/common/page_load_metrics/page_load_metrics_messages.h" |
| 22 #include "chrome/common/page_load_metrics/test/weak_mock_timer.h" |
20 #include "chrome/common/url_constants.h" | 23 #include "chrome/common/url_constants.h" |
21 #include "chrome/test/base/chrome_render_view_host_test_harness.h" | 24 #include "chrome/test/base/chrome_render_view_host_test_harness.h" |
22 #include "content/public/browser/navigation_handle.h" | 25 #include "content/public/browser/navigation_handle.h" |
23 #include "content/public/browser/render_frame_host.h" | 26 #include "content/public/browser/render_frame_host.h" |
24 #include "content/public/test/test_renderer_host.h" | 27 #include "content/public/test/test_renderer_host.h" |
25 #include "content/public/test/web_contents_tester.h" | 28 #include "content/public/test/web_contents_tester.h" |
26 #include "testing/gtest/include/gtest/gtest.h" | 29 #include "testing/gtest/include/gtest/gtest.h" |
27 #include "url/gurl.h" | 30 #include "url/gurl.h" |
28 | 31 |
29 namespace page_load_metrics { | 32 namespace page_load_metrics { |
(...skipping 80 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
110 void OnComplete(const mojom::PageLoadTiming& timing, | 113 void OnComplete(const mojom::PageLoadTiming& timing, |
111 const PageLoadExtraInfo& extra_info) override { | 114 const PageLoadExtraInfo& extra_info) override { |
112 completed_filtered_urls_->push_back(extra_info.url); | 115 completed_filtered_urls_->push_back(extra_info.url); |
113 } | 116 } |
114 | 117 |
115 private: | 118 private: |
116 std::vector<GURL>* const completed_filtered_urls_; | 119 std::vector<GURL>* const completed_filtered_urls_; |
117 }; | 120 }; |
118 | 121 |
119 class TestPageLoadMetricsEmbedderInterface | 122 class TestPageLoadMetricsEmbedderInterface |
120 : public PageLoadMetricsEmbedderInterface { | 123 : public PageLoadMetricsEmbedderInterface, |
| 124 public test::WeakMockTimerProvider { |
121 public: | 125 public: |
122 TestPageLoadMetricsEmbedderInterface() : is_ntp_(false) {} | 126 TestPageLoadMetricsEmbedderInterface() : is_ntp_(false) {} |
123 | 127 |
124 bool IsNewTabPageUrl(const GURL& url) override { return is_ntp_; } | 128 bool IsNewTabPageUrl(const GURL& url) override { return is_ntp_; } |
125 void set_is_ntp(bool is_ntp) { is_ntp_ = is_ntp; } | 129 void set_is_ntp(bool is_ntp) { is_ntp_ = is_ntp; } |
126 void RegisterObservers(PageLoadTracker* tracker) override { | 130 void RegisterObservers(PageLoadTracker* tracker) override { |
127 tracker->AddObserver(base::MakeUnique<TestPageLoadMetricsObserver>( | 131 tracker->AddObserver(base::MakeUnique<TestPageLoadMetricsObserver>( |
128 &updated_timings_, &updated_subframe_timings_, &complete_timings_, | 132 &updated_timings_, &updated_subframe_timings_, &complete_timings_, |
129 &observed_committed_urls_)); | 133 &observed_committed_urls_)); |
130 tracker->AddObserver(base::MakeUnique<FilteringPageLoadMetricsObserver>( | 134 tracker->AddObserver(base::MakeUnique<FilteringPageLoadMetricsObserver>( |
131 &completed_filtered_urls_)); | 135 &completed_filtered_urls_)); |
132 } | 136 } |
| 137 std::unique_ptr<base::Timer> CreateTimer() override { |
| 138 auto timer = base::MakeUnique<test::WeakMockTimer>(); |
| 139 SetMockTimer(timer->AsWeakPtr()); |
| 140 return std::move(timer); |
| 141 } |
133 const std::vector<mojom::PageLoadTimingPtr>& updated_timings() const { | 142 const std::vector<mojom::PageLoadTimingPtr>& updated_timings() const { |
134 return updated_timings_; | 143 return updated_timings_; |
135 } | 144 } |
136 const std::vector<mojom::PageLoadTimingPtr>& complete_timings() const { | 145 const std::vector<mojom::PageLoadTimingPtr>& complete_timings() const { |
137 return complete_timings_; | 146 return complete_timings_; |
138 } | 147 } |
139 const std::vector<mojom::PageLoadTimingPtr>& updated_subframe_timings() | 148 const std::vector<mojom::PageLoadTimingPtr>& updated_subframe_timings() |
140 const { | 149 const { |
141 return updated_subframe_timings_; | 150 return updated_subframe_timings_; |
142 } | 151 } |
(...skipping 10 matching lines...) Expand all Loading... |
153 | 162 |
154 private: | 163 private: |
155 std::vector<mojom::PageLoadTimingPtr> updated_timings_; | 164 std::vector<mojom::PageLoadTimingPtr> updated_timings_; |
156 std::vector<mojom::PageLoadTimingPtr> updated_subframe_timings_; | 165 std::vector<mojom::PageLoadTimingPtr> updated_subframe_timings_; |
157 std::vector<mojom::PageLoadTimingPtr> complete_timings_; | 166 std::vector<mojom::PageLoadTimingPtr> complete_timings_; |
158 std::vector<GURL> observed_committed_urls_; | 167 std::vector<GURL> observed_committed_urls_; |
159 std::vector<GURL> completed_filtered_urls_; | 168 std::vector<GURL> completed_filtered_urls_; |
160 bool is_ntp_; | 169 bool is_ntp_; |
161 }; | 170 }; |
162 | 171 |
| 172 void PopulatePageLoadTiming(mojom::PageLoadTiming* timing) { |
| 173 page_load_metrics::InitPageLoadTimingForTest(timing); |
| 174 timing->navigation_start = base::Time::FromDoubleT(1); |
| 175 timing->response_start = base::TimeDelta::FromMilliseconds(10); |
| 176 timing->parse_timing->parse_start = base::TimeDelta::FromMilliseconds(20); |
| 177 timing->document_timing->first_layout = base::TimeDelta::FromMilliseconds(30); |
| 178 } |
| 179 |
163 } // namespace | 180 } // namespace |
164 | 181 |
165 class MetricsWebContentsObserverTest : public ChromeRenderViewHostTestHarness { | 182 class MetricsWebContentsObserverTest : public ChromeRenderViewHostTestHarness { |
166 public: | 183 public: |
167 MetricsWebContentsObserverTest() : num_errors_(0) {} | 184 MetricsWebContentsObserverTest() : num_errors_(0) {} |
168 | 185 |
169 void SetUp() override { | 186 void SetUp() override { |
170 ChromeRenderViewHostTestHarness::SetUp(); | 187 ChromeRenderViewHostTestHarness::SetUp(); |
171 AttachObserver(); | 188 AttachObserver(); |
172 } | 189 } |
173 | 190 |
174 void NavigateToUntrackedUrl() { | 191 void NavigateToUntrackedUrl() { |
175 content::WebContentsTester::For(web_contents()) | 192 content::WebContentsTester::For(web_contents()) |
176 ->NavigateAndCommit(GURL(url::kAboutBlankURL)); | 193 ->NavigateAndCommit(GURL(url::kAboutBlankURL)); |
177 } | 194 } |
178 | 195 |
| 196 // Returns the mock timer used for buffering updates in the |
| 197 // PageLoadMetricsUpdateDispatcher. |
| 198 base::MockTimer* GetMostRecentTimer() { |
| 199 return embedder_interface_->GetMockTimer(); |
| 200 } |
| 201 |
179 void SimulateTimingUpdate(const mojom::PageLoadTiming& timing) { | 202 void SimulateTimingUpdate(const mojom::PageLoadTiming& timing) { |
180 SimulateTimingUpdate(timing, web_contents()->GetMainFrame()); | 203 SimulateTimingUpdate(timing, web_contents()->GetMainFrame()); |
181 } | 204 } |
182 | 205 |
183 void SimulateTimingUpdate(const mojom::PageLoadTiming& timing, | 206 void SimulateTimingUpdate(const mojom::PageLoadTiming& timing, |
184 content::RenderFrameHost* render_frame_host) { | 207 content::RenderFrameHost* render_frame_host) { |
| 208 SimulateTimingUpdateWithoutFiringDispatchTimer(timing, render_frame_host); |
| 209 // If sending the timing update caused the PageLoadMetricsUpdateDispatcher |
| 210 // to schedule a buffering timer, then fire it now so metrics are dispatched |
| 211 // to observers. |
| 212 base::MockTimer* mock_timer = GetMostRecentTimer(); |
| 213 if (mock_timer && mock_timer->IsRunning()) |
| 214 mock_timer->Fire(); |
| 215 } |
| 216 |
| 217 void SimulateTimingUpdateWithoutFiringDispatchTimer( |
| 218 const mojom::PageLoadTiming& timing, |
| 219 content::RenderFrameHost* render_frame_host) { |
185 observer()->OnTimingUpdated(render_frame_host, timing, | 220 observer()->OnTimingUpdated(render_frame_host, timing, |
186 mojom::PageLoadMetadata()); | 221 mojom::PageLoadMetadata()); |
187 } | 222 } |
188 | 223 |
189 void AttachObserver() { | 224 void AttachObserver() { |
190 auto embedder_interface = | 225 auto embedder_interface = |
191 base::MakeUnique<TestPageLoadMetricsEmbedderInterface>(); | 226 base::MakeUnique<TestPageLoadMetricsEmbedderInterface>(); |
192 embedder_interface_ = embedder_interface.get(); | 227 embedder_interface_ = embedder_interface.get(); |
193 MetricsWebContentsObserver* observer = | 228 MetricsWebContentsObserver* observer = |
194 MetricsWebContentsObserver::CreateForWebContents( | 229 MetricsWebContentsObserver::CreateForWebContents( |
(...skipping 534 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
729 | 764 |
730 ASSERT_EQ(1, CountUpdatedTimingReported()); | 765 ASSERT_EQ(1, CountUpdatedTimingReported()); |
731 EXPECT_TRUE(timing.Equals(*updated_timings().back())); | 766 EXPECT_TRUE(timing.Equals(*updated_timings().back())); |
732 | 767 |
733 content::RenderFrameHostTester* rfh_tester = | 768 content::RenderFrameHostTester* rfh_tester = |
734 content::RenderFrameHostTester::For(main_rfh()); | 769 content::RenderFrameHostTester::For(main_rfh()); |
735 content::RenderFrameHost* subframe = rfh_tester->AppendChild("subframe"); | 770 content::RenderFrameHost* subframe = rfh_tester->AppendChild("subframe"); |
736 | 771 |
737 // Dispatch a timing update for the child frame that includes a first paint. | 772 // Dispatch a timing update for the child frame that includes a first paint. |
738 mojom::PageLoadTiming subframe_timing; | 773 mojom::PageLoadTiming subframe_timing; |
739 page_load_metrics::InitPageLoadTimingForTest(&subframe_timing); | 774 PopulatePageLoadTiming(&subframe_timing); |
740 subframe_timing.navigation_start = base::Time::FromDoubleT(2); | |
741 subframe_timing.response_start = base::TimeDelta::FromMilliseconds(10); | |
742 subframe_timing.parse_timing->parse_start = | |
743 base::TimeDelta::FromMilliseconds(20); | |
744 subframe_timing.document_timing->first_layout = | |
745 base::TimeDelta::FromMilliseconds(30); | |
746 subframe_timing.paint_timing->first_paint = | 775 subframe_timing.paint_timing->first_paint = |
747 base::TimeDelta::FromMilliseconds(40); | 776 base::TimeDelta::FromMilliseconds(40); |
748 content::RenderFrameHostTester* subframe_tester = | 777 content::RenderFrameHostTester* subframe_tester = |
749 content::RenderFrameHostTester::For(subframe); | 778 content::RenderFrameHostTester::For(subframe); |
750 subframe_tester->SimulateNavigationStart(GURL(kDefaultTestUrl2)); | 779 subframe_tester->SimulateNavigationStart(GURL(kDefaultTestUrl2)); |
751 subframe_tester->SimulateNavigationCommit(GURL(kDefaultTestUrl2)); | 780 subframe_tester->SimulateNavigationCommit(GURL(kDefaultTestUrl2)); |
752 SimulateTimingUpdate(subframe_timing, subframe); | 781 SimulateTimingUpdate(subframe_timing, subframe); |
753 subframe_tester->SimulateNavigationStop(); | 782 subframe_tester->SimulateNavigationStop(); |
754 | 783 |
755 // Though a first paint was dispatched in the child, it should not yet be | 784 // Though a first paint was dispatched in the child, it should not yet be |
(...skipping 35 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... |
791 ASSERT_EQ(1, CountCompleteTimingReported()); | 820 ASSERT_EQ(1, CountCompleteTimingReported()); |
792 ASSERT_EQ(2, CountUpdatedTimingReported()); | 821 ASSERT_EQ(2, CountUpdatedTimingReported()); |
793 ASSERT_EQ(0, CountEmptyCompleteTimingReported()); | 822 ASSERT_EQ(0, CountEmptyCompleteTimingReported()); |
794 | 823 |
795 ASSERT_EQ(1, CountUpdatedSubFrameTimingReported()); | 824 ASSERT_EQ(1, CountUpdatedSubFrameTimingReported()); |
796 EXPECT_TRUE(subframe_timing.Equals(*updated_subframe_timings().back())); | 825 EXPECT_TRUE(subframe_timing.Equals(*updated_subframe_timings().back())); |
797 | 826 |
798 CheckNoErrorEvents(); | 827 CheckNoErrorEvents(); |
799 } | 828 } |
800 | 829 |
| 830 // We buffer cross-frame paint updates to account for paint timings from |
| 831 // different frames arriving out of order. |
| 832 TEST_F(MetricsWebContentsObserverTest, OutOfOrderCrossFrameTiming2) { |
| 833 // Dispatch a timing update for the main frame that includes a first |
| 834 // paint. This should be buffered, with the dispatch timer running. |
| 835 mojom::PageLoadTiming timing; |
| 836 PopulatePageLoadTiming(&timing); |
| 837 timing.paint_timing->first_paint = base::TimeDelta::FromMilliseconds(1000); |
| 838 content::WebContentsTester* web_contents_tester = |
| 839 content::WebContentsTester::For(web_contents()); |
| 840 web_contents_tester->NavigateAndCommit(GURL(kDefaultTestUrl)); |
| 841 SimulateTimingUpdateWithoutFiringDispatchTimer(timing, main_rfh()); |
| 842 |
| 843 EXPECT_TRUE(GetMostRecentTimer()->IsRunning()); |
| 844 ASSERT_EQ(0, CountUpdatedTimingReported()); |
| 845 |
| 846 content::RenderFrameHostTester* rfh_tester = |
| 847 content::RenderFrameHostTester::For(main_rfh()); |
| 848 |
| 849 // Dispatch a timing update for a child frame that includes a first paint. |
| 850 mojom::PageLoadTiming subframe_timing; |
| 851 PopulatePageLoadTiming(&subframe_timing); |
| 852 subframe_timing.paint_timing->first_paint = |
| 853 base::TimeDelta::FromMilliseconds(500); |
| 854 content::RenderFrameHost* subframe = rfh_tester->AppendChild("subframe"); |
| 855 content::RenderFrameHostTester* subframe_tester = |
| 856 content::RenderFrameHostTester::For(subframe); |
| 857 subframe_tester->SimulateNavigationStart(GURL(kDefaultTestUrl2)); |
| 858 subframe_tester->SimulateNavigationCommit(GURL(kDefaultTestUrl2)); |
| 859 SimulateTimingUpdateWithoutFiringDispatchTimer(subframe_timing, subframe); |
| 860 subframe_tester->SimulateNavigationStop(); |
| 861 |
| 862 histogram_tester_.ExpectTotalCount( |
| 863 page_load_metrics::internal::kHistogramOutOfOrderTiming, 1); |
| 864 |
| 865 EXPECT_TRUE(GetMostRecentTimer()->IsRunning()); |
| 866 ASSERT_EQ(0, CountUpdatedTimingReported()); |
| 867 |
| 868 // At this point, the timing update is buffered, waiting for the timer to |
| 869 // fire. |
| 870 GetMostRecentTimer()->Fire(); |
| 871 |
| 872 // Firing the timer should produce a timing update. The update should be a |
| 873 // merged view of the main frame timing, with a first paint timestamp from the |
| 874 // subframe. |
| 875 ASSERT_EQ(1, CountUpdatedTimingReported()); |
| 876 EXPECT_FALSE(timing.Equals(*updated_timings().back())); |
| 877 EXPECT_TRUE( |
| 878 updated_timings().back()->parse_timing->Equals(*timing.parse_timing)); |
| 879 EXPECT_TRUE(updated_timings().back()->document_timing->Equals( |
| 880 *timing.document_timing)); |
| 881 EXPECT_FALSE( |
| 882 updated_timings().back()->paint_timing->Equals(*timing.paint_timing)); |
| 883 EXPECT_TRUE(updated_timings().back()->paint_timing->first_paint); |
| 884 |
| 885 // The first paint value should be the min of all received first paints, which |
| 886 // in this case is the first paint from the subframe. Since it is offset by |
| 887 // the subframe's navigation start, the received value should be >= the first |
| 888 // paint value specified in the subframe. |
| 889 EXPECT_GE(updated_timings().back()->paint_timing->first_paint, |
| 890 subframe_timing.paint_timing->first_paint); |
| 891 EXPECT_LT(updated_timings().back()->paint_timing->first_paint, |
| 892 timing.paint_timing->first_paint); |
| 893 |
| 894 base::TimeDelta initial_first_paint = |
| 895 updated_timings().back()->paint_timing->first_paint.value(); |
| 896 |
| 897 // Dispatch a timing update for an additional child frame, with an earlier |
| 898 // first paint time. This should cause an immediate update, without a timer |
| 899 // delay. |
| 900 subframe_timing.paint_timing->first_paint = |
| 901 base::TimeDelta::FromMilliseconds(50); |
| 902 content::RenderFrameHost* subframe2 = rfh_tester->AppendChild("subframe"); |
| 903 content::RenderFrameHostTester* subframe2_tester = |
| 904 content::RenderFrameHostTester::For(subframe2); |
| 905 subframe2_tester->SimulateNavigationStart(GURL(kDefaultTestUrl2)); |
| 906 subframe2_tester->SimulateNavigationCommit(GURL(kDefaultTestUrl2)); |
| 907 SimulateTimingUpdateWithoutFiringDispatchTimer(subframe_timing, subframe2); |
| 908 subframe2_tester->SimulateNavigationStop(); |
| 909 |
| 910 base::TimeDelta updated_first_paint = |
| 911 updated_timings().back()->paint_timing->first_paint.value(); |
| 912 |
| 913 EXPECT_FALSE(GetMostRecentTimer()->IsRunning()); |
| 914 ASSERT_EQ(2, CountUpdatedTimingReported()); |
| 915 EXPECT_LT(updated_first_paint, initial_first_paint); |
| 916 |
| 917 histogram_tester_.ExpectTotalCount( |
| 918 page_load_metrics::internal::kHistogramOutOfOrderTimingBuffered, 1); |
| 919 histogram_tester_.ExpectBucketCount( |
| 920 page_load_metrics::internal::kHistogramOutOfOrderTimingBuffered, |
| 921 (initial_first_paint - updated_first_paint).InMilliseconds(), 1); |
| 922 |
| 923 CheckNoErrorEvents(); |
| 924 } |
| 925 |
| 926 TEST_F(MetricsWebContentsObserverTest, DispatchDelayedMetricsOnPageClose) { |
| 927 mojom::PageLoadTiming timing; |
| 928 PopulatePageLoadTiming(&timing); |
| 929 timing.paint_timing->first_paint = base::TimeDelta::FromMilliseconds(1000); |
| 930 content::WebContentsTester* web_contents_tester = |
| 931 content::WebContentsTester::For(web_contents()); |
| 932 web_contents_tester->NavigateAndCommit(GURL(kDefaultTestUrl)); |
| 933 SimulateTimingUpdateWithoutFiringDispatchTimer(timing, main_rfh()); |
| 934 |
| 935 EXPECT_TRUE(GetMostRecentTimer()->IsRunning()); |
| 936 ASSERT_EQ(0, CountUpdatedTimingReported()); |
| 937 ASSERT_EQ(0, CountCompleteTimingReported()); |
| 938 |
| 939 // Navigate to a new page. This should force dispatch of the buffered timing |
| 940 // update. |
| 941 NavigateToUntrackedUrl(); |
| 942 |
| 943 ASSERT_EQ(1, CountUpdatedTimingReported()); |
| 944 ASSERT_EQ(1, CountCompleteTimingReported()); |
| 945 EXPECT_TRUE(timing.Equals(*updated_timings().back())); |
| 946 EXPECT_TRUE(timing.Equals(*complete_timings().back())); |
| 947 |
| 948 CheckNoErrorEvents(); |
| 949 } |
| 950 |
801 } // namespace page_load_metrics | 951 } // namespace page_load_metrics |
OLD | NEW |