[Not for review] record detailed time breakdown of SW related requests.

content/browser/service_worker/service_worker_fetch_dispatcher.cc

 // Copyright 2014 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 "content/browser/service_worker/service_worker_fetch_dispatcher.h"
 
 #include <string>
 #include <utility>
 
 #include "base/bind.h"
 #include "base/memory/ptr_util.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/time/time.h"
 #include "base/trace_event/trace_event.h"
 #include "content/browser/devtools/service_worker_devtools_agent_host.h"
 #include "content/browser/devtools/service_worker_devtools_manager.h"
 #include "content/browser/loader/resource_dispatcher_host_impl.h"
 #include "content/browser/loader/resource_request_info_impl.h"
 #include "content/browser/loader/resource_requester_info.h"
 #include "content/browser/loader/url_loader_factory_impl.h"
 #include "content/browser/service_worker/embedded_worker_status.h"
 #include "content/browser/service_worker/service_worker_metrics.h"
@@ skipping 251 matching lines @@
 // ServiceWorkerFetchDispatcher has been destroyed.
 class ServiceWorkerFetchDispatcher::ResponseCallback {
  public:
   ResponseCallback(base::WeakPtr<ServiceWorkerFetchDispatcher> fetch_dispatcher,
                    ServiceWorkerVersion* version)
       : fetch_dispatcher_(fetch_dispatcher), version_(version) {}
 
   void Run(int request_id,
            ServiceWorkerFetchEventResult fetch_result,
            const ServiceWorkerResponse& response,
-           base::Time dispatch_event_time) {
+           base::Time dispatch_event_time,
+           base::TimeTicks response_time) {
     const bool handled =
         (fetch_result == SERVICE_WORKER_FETCH_EVENT_RESULT_RESPONSE);
     if (!version_->FinishRequest(request_id, handled, dispatch_event_time))
       NOTREACHED() << "Should only receive one reply per event";
 
     // |fetch_dispatcher| is null if the URLRequest was killed.
     if (fetch_dispatcher_)
-      fetch_dispatcher_->DidFinish(request_id, fetch_result, response);
+      fetch_dispatcher_->DidFinish(request_id, fetch_result, response,
+                                   response_time);
   }
 
  private:
   base::WeakPtr<ServiceWorkerFetchDispatcher> fetch_dispatcher_;
   // Owns |this|.
   ServiceWorkerVersion* version_;
 
   DISALLOW_COPY_AND_ASSIGN(ResponseCallback);
 };
 
@@ skipping 109 matching lines @@
   DidFail(status);
 }
 
 void ServiceWorkerFetchDispatcher::DispatchFetchEvent() {
   DCHECK_EQ(EmbeddedWorkerStatus::RUNNING, version_->running_status())
       << "Worker stopped too soon after it was started.";
 
   DCHECK(!prepare_callback_.is_null());
   base::Closure prepare_callback = prepare_callback_;
   prepare_callback.Run();
+  worker_ready_time_ = base::TimeTicks::Now();
 
   net_log_.BeginEvent(net::NetLogEventType::SERVICE_WORKER_FETCH_EVENT);
   int fetch_event_id;
   int event_finish_id;
   if (timeout_) {
     fetch_event_id = version_->StartRequestWithCustomTimeout(
         GetEventType(),
         base::Bind(&ServiceWorkerFetchDispatcher::DidFailToDispatch,
                    weak_factory_.GetWeakPtr()),
         *timeout_, ServiceWorkerVersion::CONTINUE_ON_TIMEOUT);
@@ skipping 27 matching lines @@
   }
 
   // |event_dispatcher| is owned by |version_|. So it is safe to pass the
   // unretained raw pointer of |version_| to OnFetchEventFinished callback.
   // Pass |url_loader_assets_| to the callback to keep the URL loader related
   // assets alive while the FetchEvent is ongoing in the service worker.
   version_->event_dispatcher()->DispatchFetchEvent(
       fetch_event_id, *request_, std::move(preload_handle_),
       base::Bind(&ServiceWorkerFetchDispatcher::OnFetchEventFinished,
                  base::Unretained(version_.get()), event_finish_id,
-                 url_loader_assets_));
+                 url_loader_assets_, renderer_request_time_,
+                 handler_creation_time_, job_creation_time_, worker_start_time_,
+                 worker_ready_time_));
 }
 
 void ServiceWorkerFetchDispatcher::DidFailToDispatch(
     ServiceWorkerStatusCode status) {
   EndNetLogEventWithServiceWorkerStatus(
       net_log_, net::NetLogEventType::SERVICE_WORKER_FETCH_EVENT, status);
   DidFail(status);
 }
 
 void ServiceWorkerFetchDispatcher::DidFail(ServiceWorkerStatusCode status) {
   DCHECK_NE(SERVICE_WORKER_OK, status);
   Complete(status, SERVICE_WORKER_FETCH_EVENT_RESULT_FALLBACK,
            ServiceWorkerResponse());
 }
 
 void ServiceWorkerFetchDispatcher::DidFinish(
     int request_id,
     ServiceWorkerFetchEventResult fetch_result,
-    const ServiceWorkerResponse& response) {
+    const ServiceWorkerResponse& response,
+    base::TimeTicks response_time) {
+  base::TimeTicks now(base::TimeTicks::Now());
+  UMA_HISTOGRAM_TIMES("SWF.D1.Response.WorkerToBrowser", now - response_time);
+
   net_log_.EndEvent(net::NetLogEventType::SERVICE_WORKER_FETCH_EVENT);
   Complete(SERVICE_WORKER_OK, fetch_result, response);
 }
 
 void ServiceWorkerFetchDispatcher::Complete(
     ServiceWorkerStatusCode status,
     ServiceWorkerFetchEventResult fetch_result,
     const ServiceWorkerResponse& response) {
   DCHECK(!fetch_callback_.is_null());
 
@@ skipping 113 matching lines @@
   if (request_->fetch_type == ServiceWorkerFetchType::FOREIGN_FETCH)
     return ServiceWorkerMetrics::EventType::FOREIGN_FETCH;
   return ResourceTypeToEventType(resource_type_);
 }
 
 // static
 void ServiceWorkerFetchDispatcher::OnFetchEventFinished(
     ServiceWorkerVersion* version,
     int event_finish_id,
     scoped_refptr<URLLoaderAssets> url_loader_assets,
+    base::TimeTicks renderer_request_time,
+    base::TimeTicks handler_creation_time,
+    base::TimeTicks job_creation_time,
+    base::TimeTicks worker_start_time,
+    base::TimeTicks worker_ready_time,
+    base::TimeTicks dispatch_event_time_ticks,
     ServiceWorkerStatusCode status,
     base::Time dispatch_event_time) {
+  UMA_HISTOGRAM_TIMES("SWF.A1.Request.RendererMainToBrowser",
+                      handler_creation_time - renderer_request_time);
+  UMA_HISTOGRAM_TIMES("SWF.A2.Request.JobCreated",
+                      job_creation_time - handler_creation_time);
+  UMA_HISTOGRAM_TIMES("SWF.A3.Request.WorkerFound",
+                      worker_start_time - job_creation_time);
+  UMA_HISTOGRAM_TIMES("SWF.A4.Request.WorkerReady",
+                      worker_ready_time - worker_start_time);
+  UMA_HISTOGRAM_TIMES("SWF.A5.Request.BrowserToWorker",
+                      dispatch_event_time_ticks - worker_ready_time);
   version->FinishRequest(event_finish_id, status != SERVICE_WORKER_ERROR_ABORT,
                          dispatch_event_time);
 }
 
 }  // namespace content