Add timing histograms to subresource loading plm observer

Records the query response latency for cookie and history.

Bug: 995437
Change-Id: I902a503963a27c33f18034c7c490ad238594097c
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1870112
Commit-Queue: Robert Ogden <robertogden@chromium.org>
Reviewed-by: Tarun Bansal <tbansal@chromium.org>
Reviewed-by: Ryan Sturm <ryansturm@chromium.org>
Cr-Commit-Position: refs/heads/master@{#707667}

chrome/browser/page_load_metrics/observers/subresource_loading_page_load_metrics_observer.cc

@@ -92,7 +92,7 @@ SubresourceLoadingPageLoadMetricsObserver::OnCommit(
         navigation_start_ /* end_time */,
         base::BindOnce(
             &SubresourceLoadingPageLoadMetricsObserver::OnOriginLastVisitResult,
-            weak_factory_.GetWeakPtr()),
+            weak_factory_.GetWeakPtr(), base::Time::Now()),
         &task_tracker_);
   }
 
@@ -100,7 +100,10 @@ SubresourceLoadingPageLoadMetricsObserver::OnCommit(
 }
 
 void SubresourceLoadingPageLoadMetricsObserver::OnOriginLastVisitResult(
+    base::Time query_start_time,
     history::HistoryLastVisitToHostResult result) {
+  history_query_times_.push_back(base::Time::Now() - query_start_time);
+
   if (!result.success)
     return;
 
@@ -129,12 +132,14 @@ void SubresourceLoadingPageLoadMetricsObserver::CheckForCookiesOnURL(
   partition->GetCookieManagerForBrowserProcess()->GetCookieList(
       url, net::CookieOptions::MakeAllInclusive(),
       base::BindOnce(&SubresourceLoadingPageLoadMetricsObserver::OnCookieResult,
-                     weak_factory_.GetWeakPtr()));
+                     weak_factory_.GetWeakPtr(), base::Time::Now()));
 }
 
 void SubresourceLoadingPageLoadMetricsObserver::OnCookieResult(
+    base::Time query_start_time,
     const net::CookieStatusList& cookies,
     const net::CookieStatusList& excluded_cookies) {
+  cookie_query_times_.push_back(base::Time::Now() - query_start_time);
   mainframe_had_cookies_ =
       mainframe_had_cookies_.value_or(false) || !cookies.empty();
 }
@@ -170,6 +175,17 @@ void SubresourceLoadingPageLoadMetricsObserver::RecordMetrics() {
 
   task_tracker_.TryCancelAll();
 
+  for (base::TimeDelta cookie_query_time : cookie_query_times_) {
+    UMA_HISTOGRAM_TIMES("PageLoad.Clients.SubresourceLoading.CookiesQueryTime",
+                        cookie_query_time);
+  }
+  cookie_query_times_.clear();
+  for (base::TimeDelta history_query_time : history_query_times_) {
+    UMA_HISTOGRAM_TIMES("PageLoad.Clients.SubresourceLoading.HistoryQueryTime",
+                        history_query_time);
+  }
+  history_query_times_.clear();
+
   // TODO(crbug.com/995437): Add UKM for data saver users once all metrics
   // are in place.
 

chrome/browser/page_load_metrics/observers/subresource_loading_page_load_metrics_observer.h

@@ -6,6 +6,7 @@
 #define CHROME_BROWSER_PAGE_LOAD_METRICS_OBSERVERS_SUBRESOURCE_LOADING_PAGE_LOAD_METRICS_OBSERVER_H_
 
 #include <stdint.h>
+#include <vector>
 
 #include "base/macros.h"
 #include "base/memory/weak_ptr.h"
@@ -33,7 +34,8 @@ class SubresourceLoadingPageLoadMetricsObserver
  protected:
   // Used as a callback for history service query results. Protected for
   // testing.
-  void OnOriginLastVisitResult(history::HistoryLastVisitToHostResult result);
+  void OnOriginLastVisitResult(base::Time query_start_time,
+                               history::HistoryLastVisitToHostResult result);
 
  private:
   void RecordMetrics();
@@ -46,7 +48,8 @@ class SubresourceLoadingPageLoadMetricsObserver
                             const GURL& url);
 
   // Used as a callback for the cookie manager query.
-  void OnCookieResult(const net::CookieStatusList& cookies,
+  void OnCookieResult(base::Time query_start_time,
+                      const net::CookieStatusList& cookies,
                       const net::CookieStatusList& excluded_cookies);
 
   // page_load_metrics::PageLoadMetricsObserver:
@@ -75,6 +78,13 @@ class SubresourceLoadingPageLoadMetricsObserver
   size_t loaded_css_js_from_cache_before_fcp_ = 0;
   size_t loaded_css_js_from_network_before_fcp_ = 0;
 
+  // These vectors hold the durations that queries to the cookie manager and
+  // history service took, respectively. Since we only want to record these when
+  // we also record the query results, the query times are stashed here until
+  // |RecordMetrics()| is called.
+  std::vector<base::TimeDelta> cookie_query_times_;
+  std::vector<base::TimeDelta> history_query_times_;
+
   // The minimum number of days since the last visit, as reported by
   // HistoryService, to any origin in the redirect chain. Set to -1 if there is
   // a response from the history service but was no previous visit.

chrome/browser/page_load_metrics/observers/subresource_loading_page_load_metrics_observer_browsertest.cc

@@ -60,6 +60,8 @@ IN_PROC_BROWSER_TEST_F(SubresourceLoadingPageLoadMetricsObserverBrowserTest,
       "PageLoad.Clients.SubresourceLoading.HasPreviousVisitToOrigin", false, 1);
   histogram_tester.ExpectTotalCount(
       "PageLoad.Clients.SubresourceLoading.DaysSinceLastVisitToOrigin", 0);
+  histogram_tester.ExpectTotalCount(
+      "PageLoad.Clients.SubresourceLoading.HistoryQueryTime", 1);
 
   // Revisit and expect a 0 days-ago entry.
   NavigateToPath("/index.html");
@@ -70,6 +72,8 @@ IN_PROC_BROWSER_TEST_F(SubresourceLoadingPageLoadMetricsObserverBrowserTest,
       "PageLoad.Clients.SubresourceLoading.HasPreviousVisitToOrigin", false, 1);
   histogram_tester.ExpectUniqueSample(
       "PageLoad.Clients.SubresourceLoading.DaysSinceLastVisitToOrigin", 0, 1);
+  histogram_tester.ExpectTotalCount(
+      "PageLoad.Clients.SubresourceLoading.HistoryQueryTime", 2);
 }
 
 IN_PROC_BROWSER_TEST_F(SubresourceLoadingPageLoadMetricsObserverBrowserTest,
@@ -80,6 +84,8 @@ IN_PROC_BROWSER_TEST_F(SubresourceLoadingPageLoadMetricsObserverBrowserTest,
 
   histogram_tester.ExpectUniqueSample(
       "PageLoad.Clients.SubresourceLoading.MainFrameHadCookies", false, 1);
+  histogram_tester.ExpectTotalCount(
+      "PageLoad.Clients.SubresourceLoading.CookiesQueryTime", 1);
 }
 
 IN_PROC_BROWSER_TEST_F(SubresourceLoadingPageLoadMetricsObserverBrowserTest,
@@ -94,6 +100,8 @@ IN_PROC_BROWSER_TEST_F(SubresourceLoadingPageLoadMetricsObserverBrowserTest,
   // From the first page load.
   histogram_tester.ExpectBucketCount(
       "PageLoad.Clients.SubresourceLoading.MainFrameHadCookies", false, 1);
+  histogram_tester.ExpectTotalCount(
+      "PageLoad.Clients.SubresourceLoading.CookiesQueryTime", 2);
 }
 
 IN_PROC_BROWSER_TEST_F(SubresourceLoadingPageLoadMetricsObserverBrowserTest,
@@ -108,4 +116,29 @@ IN_PROC_BROWSER_TEST_F(SubresourceLoadingPageLoadMetricsObserverBrowserTest,
   // From the first page load.
   histogram_tester.ExpectBucketCount(
       "PageLoad.Clients.SubresourceLoading.MainFrameHadCookies", false, 1);
+  histogram_tester.ExpectTotalCount(
+      "PageLoad.Clients.SubresourceLoading.CookiesQueryTime", 3);
+}
+
+IN_PROC_BROWSER_TEST_F(SubresourceLoadingPageLoadMetricsObserverBrowserTest,
+                       RecordNothingOnUntrackedPage) {
+  base::HistogramTester histogram_tester;
+
+  NavigateAway();
+  NavigateAway();
+
+  histogram_tester.ExpectTotalCount(
+      "PageLoad.Clients.SubresourceLoading.CookiesQueryTime", 0);
+  histogram_tester.ExpectTotalCount(
+      "PageLoad.Clients.SubresourceLoading.DaysSinceLastVisitToOrigin", 0);
+  histogram_tester.ExpectTotalCount(
+      "PageLoad.Clients.SubresourceLoading.HasPreviousVisitToOrigin", 0);
+  histogram_tester.ExpectTotalCount(
+      "PageLoad.Clients.SubresourceLoading.HistoryQueryTime", 0);
+  histogram_tester.ExpectTotalCount(
+      "PageLoad.Clients.SubresourceLoading.LoadedCSSJSBeforeFCP.Cached", 0);
+  histogram_tester.ExpectTotalCount(
+      "PageLoad.Clients.SubresourceLoading.LoadedCSSJSBeforeFCP.Noncached", 0);
+  histogram_tester.ExpectTotalCount(
+      "PageLoad.Clients.SubresourceLoading.MainFrameHadCookies", 0);
 }

chrome/browser/page_load_metrics/observers/subresource_loading_page_load_metrics_observer_unittest.cc

@@ -32,7 +32,7 @@ class TestSubresourceLoadingPageLoadMetricsObserver
  public:
   void CallOnOriginLastVisitResult(
       history::HistoryLastVisitToHostResult result) {
-    OnOriginLastVisitResult(result);
+    OnOriginLastVisitResult(base::Time::Now(), result);
   }
 };
 
@@ -349,6 +349,8 @@ TEST_F(SubresourceLoadingPageLoadMetricsObserverTest, LastVisitToHost_None) {
 
   tester()->NavigateToUntrackedUrl();
 
+  tester()->histogram_tester().ExpectTotalCount(
+      "PageLoad.Clients.SubresourceLoading.HistoryQueryTime", 0);
   tester()->histogram_tester().ExpectTotalCount(
       "PageLoad.Clients.SubresourceLoading.HasPreviousVisitToOrigin", 0);
   tester()->histogram_tester().ExpectTotalCount(
@@ -361,6 +363,8 @@ TEST_F(SubresourceLoadingPageLoadMetricsObserverTest, LastVisitToHost_Fail) {
       {false /* success */, base::Time()});
   tester()->NavigateToUntrackedUrl();
 
+  tester()->histogram_tester().ExpectTotalCount(
+      "PageLoad.Clients.SubresourceLoading.HistoryQueryTime", 1);
   tester()->histogram_tester().ExpectTotalCount(
       "PageLoad.Clients.SubresourceLoading.HasPreviousVisitToOrigin", 0);
   tester()->histogram_tester().ExpectTotalCount(
@@ -374,6 +378,8 @@ TEST_F(SubresourceLoadingPageLoadMetricsObserverTest,
       {true /* success */, base::Time()});
   tester()->NavigateToUntrackedUrl();
 
+  tester()->histogram_tester().ExpectTotalCount(
+      "PageLoad.Clients.SubresourceLoading.HistoryQueryTime", 1);
   tester()->histogram_tester().ExpectUniqueSample(
       "PageLoad.Clients.SubresourceLoading.HasPreviousVisitToOrigin", false, 1);
   tester()->histogram_tester().ExpectTotalCount(
@@ -387,6 +393,8 @@ TEST_F(SubresourceLoadingPageLoadMetricsObserverTest, LastVisitToHost_Today) {
 
   tester()->NavigateToUntrackedUrl();
 
+  tester()->histogram_tester().ExpectTotalCount(
+      "PageLoad.Clients.SubresourceLoading.HistoryQueryTime", 1);
   tester()->histogram_tester().ExpectUniqueSample(
       "PageLoad.Clients.SubresourceLoading.HasPreviousVisitToOrigin", true, 1);
   tester()->histogram_tester().ExpectUniqueSample(
@@ -401,6 +409,8 @@ TEST_F(SubresourceLoadingPageLoadMetricsObserverTest,
 
   tester()->NavigateToUntrackedUrl();
 
+  tester()->histogram_tester().ExpectTotalCount(
+      "PageLoad.Clients.SubresourceLoading.HistoryQueryTime", 1);
   tester()->histogram_tester().ExpectUniqueSample(
       "PageLoad.Clients.SubresourceLoading.HasPreviousVisitToOrigin", true, 1);
   tester()->histogram_tester().ExpectUniqueSample(
@@ -414,6 +424,8 @@ TEST_F(SubresourceLoadingPageLoadMetricsObserverTest, HadCookies_None) {
 
   tester()->NavigateToUntrackedUrl();
 
+  tester()->histogram_tester().ExpectTotalCount(
+      "PageLoad.Clients.SubresourceLoading.CookiesQueryTime", 0);
   tester()->histogram_tester().ExpectTotalCount(
       "PageLoad.Clients.SubresourceLoading.MainFrameHadCookies", 0);
 }

tools/metrics/histograms/histograms.xml

@@ -98825,6 +98825,16 @@ uploading your change for review.
   </summary>
 </histogram>
 
+<histogram name="PageLoad.Clients.SubresourceLoading.CookiesQueryTime"
+    units="ms" expires_after="M90">
+  <owner>robertogden@chromium.org</owner>
+  <owner>tbansal@chromium.org</owner>
+  <summary>
+    How long the query to the cookie manager took to complete. Recorded on every
+    query response.
+  </summary>
+</histogram>
+
 <histogram
     name="PageLoad.Clients.SubresourceLoading.DaysSinceLastVisitToOrigin"
     units="days" expires_after="M90">
@@ -98850,6 +98860,16 @@ uploading your change for review.
   </summary>
 </histogram>
 
+<histogram name="PageLoad.Clients.SubresourceLoading.HistoryQueryTime"
+    units="ms" expires_after="M90">
+  <owner>robertogden@chromium.org</owner>
+  <owner>tbansal@chromium.org</owner>
+  <summary>
+    How long the query to the history service took to complete. Recorded on
+    every query response.
+  </summary>
+</histogram>
+
 <histogram
     name="PageLoad.Clients.SubresourceLoading.LoadedCSSJSBeforeFCP.Cached"
     units="count of subresources" expires_after="M90">