Use start timing recorded in the renderer for fetchStart

Currently, a fetch event for navigation can be dispatched without
waiting for an ACK message of StartWorker. That resulted in recording
the time for PerformanceResourceTiming#fetchStart and requestStart
before the worker becomes ready to get a fetch event.

This CL changes the time used for them. Before this CL, these time were
recorded when the worker becomes ready and just before sending a message
to fire a FetchEvent. After this CL, fetchStart and requestStart uses
the time when the fetch event is actually dispatched on the worker
thread.

As a result, we can measure the time spent for starting the worker
thread by fetchStart - workerStart.

Explainer: https://docs.google.com/document/d/1m3Mnuq7N9pLzFC8vu19ngxzUU1n3Lt_phzyK3u_UQ6M/edit?usp=sharing

Bug: 1128786
Change-Id: I9e2277d546b07dff99341b8fa37f2b71139c8392
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2413651
Commit-Queue: Makoto Shimazu <shimazu@chromium.org>
Reviewed-by: Matt Falkenhagen <falken@chromium.org>
Cr-Commit-Position: refs/heads/master@{#809740}

content/browser/service_worker/service_worker_main_resource_loader.cc

@@ -246,13 +246,6 @@ void ServiceWorkerMainResourceLoader::DidPrepareFetchEvent(
       "initial_worker_status",
       EmbeddedWorkerInstance::StatusToString(initial_worker_status));
 
-  // At this point a service worker is running and the fetch event is about
-  // to dispatch. Record some load timings.
-  base::TimeTicks now = base::TimeTicks::Now();
-  response_head_->load_timing.service_worker_ready_time = now;
-  response_head_->load_timing.send_start = now;
-  response_head_->load_timing.send_end = now;
-
   devtools_attached_ = version->embedded_worker()->devtools_attached();
 }
 
@@ -296,6 +289,21 @@ void ServiceWorkerMainResourceLoader::DidDispatchFetchEvent(
     return;
   }
 
+  // Record the timing of when the fetch event is dispatched on the worker
+  // thread. This is used for PerformanceResourceTiming#fetchStart and
+  // PerformanceResourceTiming#requestStart, but it's still under spec
+  // discussion.
+  // See https://github.com/w3c/resource-timing/issues/119 for more details.
+  // Exposed as PerformanceResourceTiming#fetchStart.
+  response_head_->load_timing.service_worker_ready_time =
+      fetch_event_timing_->dispatch_event_time;
+  // Exposed as PerformanceResourceTiming#requestStart.
+  response_head_->load_timing.send_start =
+      fetch_event_timing_->dispatch_event_time;
+  // Recorded for the DevTools.
+  response_head_->load_timing.send_end =
+      fetch_event_timing_->dispatch_event_time;
+
   if (fetch_result ==
       ServiceWorkerFetchDispatcher::FetchEventResult::kShouldFallback) {
     TransitionToStatus(Status::kCompleted);

content/browser/service_worker/service_worker_main_resource_loader_unittest.cc

@@ -105,11 +105,19 @@ class FetchEventServiceWorker : public FakeServiceWorker {
  public:
   FetchEventServiceWorker(
       EmbeddedWorkerTestHelper* helper,
-      FakeEmbeddedWorkerInstanceClient* embedded_worker_instance_client)
+      FakeEmbeddedWorkerInstanceClient* embedded_worker_instance_client,
+      BrowserTaskEnvironment* task_environment)
       : FakeServiceWorker(helper),
+        task_environment_(task_environment),
         embedded_worker_instance_client_(embedded_worker_instance_client) {}
   ~FetchEventServiceWorker() override = default;
 
+  // Tells this worker to dispatch a fetch event 1s after the fetch event is
+  // received.
+  void DispatchAfter1sDelay() {
+    response_mode_ = ResponseMode::kDispatchAfter1sDelay;
+  }
+
   // Tells this worker to respond to fetch events with the specified blob.
   void RespondWithBlob(blink::mojom::SerializedBlobPtr blob) {
     response_mode_ = ResponseMode::kBlob;
@@ -243,6 +251,12 @@ class FetchEventServiceWorker : public FakeServiceWorker {
             std::move(params), response_callback.Unbind(),
             std::move(finish_callback));
         break;
+      case ResponseMode::kDispatchAfter1sDelay:
+        task_environment_->AdvanceClock(base::TimeDelta::FromSeconds(1));
+        FakeServiceWorker::DispatchFetchEventForMainResource(
+            std::move(params), response_callback.Unbind(),
+            std::move(finish_callback));
+        break;
       case ResponseMode::kBlob:
         response_callback->OnResponse(
             OkResponse(std::move(blob_body_), response_source_, response_time_,
@@ -320,6 +334,7 @@ class FetchEventServiceWorker : public FakeServiceWorker {
  private:
   enum class ResponseMode {
     kDefault,
+    kDispatchAfter1sDelay,
     kBlob,
     kStream,
     kFallbackResponse,
@@ -331,6 +346,8 @@ class FetchEventServiceWorker : public FakeServiceWorker {
     kHeaders
   };
 
+  BrowserTaskEnvironment* const task_environment_;
+
   ResponseMode response_mode_ = ResponseMode::kDefault;
   scoped_refptr<network::ResourceRequestBody> request_body_;
 
@@ -391,7 +408,8 @@ const char kHistogramMainResourceFetchEvent[] =
 class ServiceWorkerMainResourceLoaderTest : public testing::Test {
  public:
   ServiceWorkerMainResourceLoaderTest()
-      : task_environment_(BrowserTaskEnvironment::IO_MAINLOOP) {}
+      : task_environment_(BrowserTaskEnvironment::IO_MAINLOOP,
+                          base::test::TaskEnvironment::TimeSource::MOCK_TIME) {}
   ~ServiceWorkerMainResourceLoaderTest() override = default;
 
   void SetUp() override {
@@ -433,7 +451,7 @@ class ServiceWorkerMainResourceLoaderTest : public testing::Test {
             helper_.get());
     service_worker_ =
         helper_->AddNewPendingServiceWorker<FetchEventServiceWorker>(
-            helper_.get(), client);
+            helper_.get(), client, &task_environment_);
 
     // Wait for main script response is set to |version| because
     // ServiceWorkerMainResourceLoader needs the main script response to
@@ -1057,5 +1075,27 @@ TEST_F(ServiceWorkerMainResourceLoaderTest, CancelNavigationDuringFetchEvent) {
   EXPECT_EQ(net::ERR_ABORTED, client_.completion_status().error_code);
 }
 
+TEST_F(ServiceWorkerMainResourceLoaderTest, TimingInfo) {
+  service_worker_->DispatchAfter1sDelay();
+
+  // Perform the request.
+  StartRequest(CreateRequest());
+  client_.RunUntilComplete();
+
+  // The response header's timing is recorded appropriately.
+  auto& info = client_.response_head();
+  EXPECT_EQ(200, info->headers->response_code());
+  ExpectResponseInfo(*info, *CreateResponseInfoFromServiceWorker());
+  EXPECT_EQ(base::TimeDelta::FromSeconds(1),
+            info->load_timing.service_worker_ready_time -
+                info->load_timing.service_worker_start_time);
+  EXPECT_EQ(base::TimeDelta::FromSeconds(1),
+            info->load_timing.service_worker_fetch_start -
+                info->load_timing.service_worker_start_time);
+  EXPECT_EQ(base::TimeDelta::FromSeconds(1),
+            info->load_timing.service_worker_respond_with_settled -
+                info->load_timing.service_worker_start_time);
+}
+
 }  // namespace service_worker_main_resource_loader_unittest
 }  // namespace content