Add ServiceWorker.LookupRegistration.Time

This metric is to measure the time spent for looking up a matching registration.
Perhaps this is mostly measuring the time for disk access to read registration
info. We want to analyze this to see if putting registration in memory could
improve performance.

Bug: 953598
Change-Id: Icef0444ccec3ae3701073ff96afb0d8b3769e6f8
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1583177
Commit-Queue: Makoto Shimazu <shimazu@chromium.org>
Reviewed-by: Jesse Doherty <jwd@chromium.org>
Reviewed-by: Kenichi Ishibashi <bashi@chromium.org>
Cr-Commit-Position: refs/heads/master@{#657590}

content/browser/service_worker/service_worker_controllee_request_handler.cc

@@ -253,6 +253,7 @@ void ServiceWorkerControlleeRequestHandler::PrepareForMainResource(
 
   stripped_url_ = net::SimplifyUrlForRequest(url);
   provider_host_->UpdateUrls(stripped_url_, site_for_cookies);
+  registration_lookup_start_time_ = base::TimeTicks::Now();
   context_->storage()->FindRegistrationForDocument(
       stripped_url_, base::BindOnce(&ServiceWorkerControlleeRequestHandler::
                                         DidLookupRegistrationForMainResource,
@@ -270,6 +271,9 @@ void ServiceWorkerControlleeRequestHandler::
   if (!loader())
     return;
 
+  ServiceWorkerMetrics::RecordLookupRegistrationTime(
+      status, base::TimeTicks::Now() - registration_lookup_start_time_);
+
   if (status != blink::ServiceWorkerStatusCode::kOk) {
     loader()->FallbackToNetwork();
     TRACE_EVENT_ASYNC_END1(

content/browser/service_worker/service_worker_controllee_request_handler.h

@@ -135,6 +135,7 @@ class CONTENT_EXPORT ServiceWorkerControlleeRequestHandler final
   ResourceContext* resource_context_;
   GURL stripped_url_;
   bool force_update_started_;
+  base::TimeTicks registration_lookup_start_time_;
 
   base::WeakPtrFactory<ServiceWorkerControlleeRequestHandler> weak_factory_;
 

content/browser/service_worker/service_worker_controllee_request_handler_unittest.cc

@@ -12,6 +12,7 @@
 #include "base/files/scoped_temp_dir.h"
 #include "base/logging.h"
 #include "base/run_loop.h"
+#include "base/test/metrics/histogram_tester.h"
 #include "base/test/scoped_feature_list.h"
 #include "components/offline_pages/buildflags/buildflags.h"
 #include "content/browser/service_worker/embedded_worker_test_helper.h"
@@ -162,6 +163,91 @@ class ServiceWorkerTestContentBrowserClient : public TestContentBrowserClient {
   }
 };
 
+TEST_F(ServiceWorkerControlleeRequestHandlerTest, Basic) {
+  base::HistogramTester histogram_tester;
+
+  // Prepare a valid version and registration.
+  version_->set_fetch_handler_existence(
+      ServiceWorkerVersion::FetchHandlerExistence::EXISTS);
+  version_->SetStatus(ServiceWorkerVersion::ACTIVATED);
+  registration_->SetActiveVersion(version_);
+  {
+    base::RunLoop loop;
+    context()->storage()->StoreRegistration(
+        registration_.get(), version_.get(),
+        base::BindOnce(
+            [](base::OnceClosure closure,
+               blink::ServiceWorkerStatusCode status) {
+              ASSERT_EQ(blink::ServiceWorkerStatusCode::kOk, status);
+              std::move(closure).Run();
+            },
+            loop.QuitClosure()));
+    loop.Run();
+  }
+
+  histogram_tester.ExpectTotalCount(
+      "ServiceWorker.LookupRegistration.MainResource.Time.Exists", 0);
+
+  // Conduct a main resource load.
+  ServiceWorkerRequestTestResources test_resources(
+      this, GURL("https://host/scope/doc"), ResourceType::kMainFrame);
+  ServiceWorkerNavigationLoader* loader = test_resources.MaybeCreateLoader();
+
+  EXPECT_FALSE(loader->ShouldFallbackToNetwork());
+  EXPECT_FALSE(loader->ShouldForwardToServiceWorker());
+  EXPECT_FALSE(version_->HasControllee());
+
+  base::RunLoop().RunUntilIdle();
+
+  EXPECT_FALSE(loader->ShouldFallbackToNetwork());
+  EXPECT_TRUE(loader->ShouldForwardToServiceWorker());
+  EXPECT_TRUE(version_->HasControllee());
+  histogram_tester.ExpectTotalCount(
+      "ServiceWorker.LookupRegistration.MainResource.Time.Exists", 1);
+
+  test_resources.ResetHandler();
+}
+
+TEST_F(ServiceWorkerControlleeRequestHandlerTest, DoesNotExist) {
+  base::HistogramTester histogram_tester;
+  histogram_tester.ExpectTotalCount(
+      "ServiceWorker.LookupRegistration.MainResource.Time.DoesNotExist", 0);
+
+  // No version and registration exists in the scope.
+
+  // Conduct a main resource load.
+  ServiceWorkerRequestTestResources test_resources(
+      this, GURL("https://host/scope/doc"), ResourceType::kMainFrame);
+  ServiceWorkerNavigationLoader* loader = test_resources.MaybeCreateLoader();
+  EXPECT_FALSE(loader);
+
+  histogram_tester.ExpectTotalCount(
+      "ServiceWorker.LookupRegistration.MainResource.Time.DoesNotExist", 1);
+
+  test_resources.ResetHandler();
+}
+
+TEST_F(ServiceWorkerControlleeRequestHandlerTest, Error) {
+  base::HistogramTester histogram_tester;
+
+  // Disabling the storage makes looking up the registration return an error.
+  context()->storage()->Disable();
+
+  histogram_tester.ExpectTotalCount(
+      "ServiceWorker.LookupRegistration.MainResource.Time.Error", 0);
+
+  // Conduct a main resource load.
+  ServiceWorkerRequestTestResources test_resources(
+      this, GURL("https://host/scope/doc"), ResourceType::kMainFrame);
+  ServiceWorkerNavigationLoader* loader = test_resources.MaybeCreateLoader();
+  EXPECT_FALSE(loader);
+
+  histogram_tester.ExpectTotalCount(
+      "ServiceWorker.LookupRegistration.MainResource.Time.Error", 1);
+
+  test_resources.ResetHandler();
+}
+
 TEST_F(ServiceWorkerControlleeRequestHandlerTest, DisallowServiceWorker) {
   ServiceWorkerTestContentBrowserClient test_browser_client;
   ContentBrowserClient* old_browser_client =

content/browser/service_worker/service_worker_metrics.cc

@@ -811,4 +811,20 @@ void ServiceWorkerMetrics::RecordRegisteredOriginCount(size_t origin_count) {
   UMA_HISTOGRAM_COUNTS_1M("ServiceWorker.RegisteredOriginCount", origin_count);
 }
 
+void ServiceWorkerMetrics::RecordLookupRegistrationTime(
+    blink::ServiceWorkerStatusCode status,
+    base::TimeDelta duration) {
+  if (status == blink::ServiceWorkerStatusCode::kOk) {
+    UMA_HISTOGRAM_TIMES(
+        "ServiceWorker.LookupRegistration.MainResource.Time.Exists", duration);
+  } else if (status == blink::ServiceWorkerStatusCode::kErrorNotFound) {
+    UMA_HISTOGRAM_TIMES(
+        "ServiceWorker.LookupRegistration.MainResource.Time.DoesNotExist",
+        duration);
+  } else {
+    UMA_HISTOGRAM_TIMES(
+        "ServiceWorker.LookupRegistration.MainResource.Time.Error", duration);
+  }
+}
+
 }  // namespace content

content/browser/service_worker/service_worker_metrics.h

@@ -427,6 +427,15 @@ class ServiceWorkerMetrics {
   // Records the number of origins with a registered service worker.
   static void RecordRegisteredOriginCount(size_t origin_count);
 
+  // Records the duration of looking up an existing registration.
+  // |status| is the result of lookup. The records for the cases where
+  // the registration is found (kOk), not found (kErrorNotFound), or an error
+  // happens (other errors) are saved separately into a relevant suffixed
+  // histogram.
+  static void RecordLookupRegistrationTime(
+      blink::ServiceWorkerStatusCode status,
+      base::TimeDelta duration);
+
  private:
   DISALLOW_IMPLICIT_CONSTRUCTORS(ServiceWorkerMetrics);
 };

tools/metrics/histograms/histograms.xml

@@ -113112,6 +113112,21 @@ uploading your change for review.
   </summary>
 </histogram>
 
+<histogram name="ServiceWorker.LookupRegistration.MainResource.Time" units="ms"
+    expires_after="2021-10-31">
+  <owner>shimazu@chromium.org</owner>
+  <owner>chrome-worker@google.com</owner>
+  <summary>
+    The time taken from (a) a resource loading request is routed to service
+    worker path, to (b) existance of a registered service worker is looked up.
+    This metric only cares about looking up a registration for navigation. This
+    doesn't include look-ups for updating a service worker.
+
+    Please refer to the suffixed histograms for each of the cases where a
+    registration is found, not found, and an error happens.
+  </summary>
+</histogram>
+
 <histogram name="ServiceWorker.MainFramePageLoad" enum="ServiceWorkerSite">
   <owner>horo@chromium.org</owner>
   <summary>
@@ -155471,6 +155486,14 @@ should be kept until we use this API.  -->
   <affected-histogram name="ServiceWorker.StartWorker.AfterFailureStreak"/>
 </histogram_suffixes>
 
+<histogram_suffixes name="ServiceWorker.LookupRegistrationResult" separator=".">
+  <suffix name="DoesNotExist" label="The registration doesn't exist."/>
+  <suffix name="Error" label="Failed to look up the registration."/>
+  <suffix name="Exists" label="The registration exists."/>
+  <affected-histogram
+      name="ServiceWorker.LookupRegistration.MainResource.Time"/>
+</histogram_suffixes>
+
 <histogram_suffixes name="ServiceWorker.NavigationHint" separator=".">
   <obsolete>
     This experiment was turned down, see https://crbug.com/616502.