Introduce ServiceWorker.EventDispatchingDelay UMA

content/browser/service_worker/service_worker_version.cc

 // Copyright 2013 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_version.h"
 
 #include <stddef.h>
 
 #include <limits>
 #include <map>
@@ skipping 532 matching lines @@
   OnBeginEvent();
   DCHECK_EQ(EmbeddedWorkerStatus::RUNNING, running_status())
       << "Can only start a request with a running worker.";
   DCHECK(event_type == ServiceWorkerMetrics::EventType::INSTALL ||
          event_type == ServiceWorkerMetrics::EventType::ACTIVATE ||
          event_type == ServiceWorkerMetrics::EventType::MESSAGE ||
          status() == ACTIVATED)
       << "Event of type " << static_cast<int>(event_type)
       << " can only be dispatched to an active worker: " << status();
 
-  PendingRequest* request =
-      new PendingRequest(error_callback, base::TimeTicks::Now(), event_type);
+  PendingRequest* request = new PendingRequest(
+      error_callback, base::Time::Now(), base::TimeTicks::Now(), event_type);
   int request_id = pending_requests_.Add(request);
   TRACE_EVENT_ASYNC_BEGIN2("ServiceWorker", "ServiceWorkerVersion::Request",
                            request, "Request id", request_id, "Event type",
                            ServiceWorkerMetrics::EventTypeToString(event_type));
   base::TimeTicks expiration_time = base::TimeTicks::Now() + timeout;
   timeout_queue_.push(
       RequestInfo(request_id, event_type, expiration_time, timeout_behavior));
   return request_id;
 }
 
-bool ServiceWorkerVersion::FinishRequest(int request_id, bool was_handled) {
+bool ServiceWorkerVersion::FinishRequest(int request_id,
+                                         bool was_handled,
+                                         base::Time dispatch_event_time) {
   PendingRequest* request = pending_requests_.Lookup(request_id);
   if (!request)
     return false;
   // TODO(kinuko): Record other event statuses too.
   metrics_->RecordEventHandledStatus(request->event_type, was_handled);
   ServiceWorkerMetrics::RecordEventDuration(
-      request->event_type, base::TimeTicks::Now() - request->start_time,
+      request->event_type, base::TimeTicks::Now() - request->start_time_ticks,
       was_handled);
+  ServiceWorkerMetrics::RecordEventDispatchingDelay(
+      request->event_type, dispatch_event_time - request->start_time,
+      site_for_uma());
 
   RestartTick(&idle_time_);
   TRACE_EVENT_ASYNC_END1("ServiceWorker", "ServiceWorkerVersion::Request",
                          request, "Handled", was_handled);
   pending_requests_.Remove(request_id);
   if (!HasWork())
     FOR_EACH_OBSERVER(Listener, listeners_, OnNoWork(this));
 
   return true;
 }
@@ skipping 176 matching lines @@
 ServiceWorkerVersion::RequestInfo::~RequestInfo() {
 }
 
 bool ServiceWorkerVersion::RequestInfo::operator>(
     const RequestInfo& other) const {
   return expiration > other.expiration;
 }
 
 ServiceWorkerVersion::PendingRequest::PendingRequest(
     const StatusCallback& callback,
-    const base::TimeTicks& time,
+    base::Time time,
+    const base::TimeTicks& time_ticks,
     ServiceWorkerMetrics::EventType event_type)
-    : error_callback(callback), start_time(time), event_type(event_type) {}
+    : error_callback(callback),
+      start_time(time),
+      start_time_ticks(time_ticks),
+      event_type(event_type) {}
 
 ServiceWorkerVersion::PendingRequest::~PendingRequest() {}
 
 ServiceWorkerVersion::BaseMojoServiceWrapper::BaseMojoServiceWrapper(
     ServiceWorkerVersion* worker,
     const char* service_name)
     : worker_(worker), service_name_(service_name) {}
 
 ServiceWorkerVersion::BaseMojoServiceWrapper::~BaseMojoServiceWrapper() {
   IDMap<PendingRequest, IDMapOwnPointer>::iterator iter(
@@ skipping 201 matching lines @@
       running_status() != EmbeddedWorkerStatus::RUNNING) {
     return;
   }
 
   embedded_worker_->SendMessage(
       ServiceWorkerMsg_DidGetClients(request_id, *clients));
 }
 
 void ServiceWorkerVersion::OnSimpleEventResponse(
     int request_id,
-    blink::WebServiceWorkerEventResult result) {
+    blink::WebServiceWorkerEventResult result,
+    base::Time dispatch_event_time) {
   // Copy error callback before calling FinishRequest.
   PendingRequest* request = pending_requests_.Lookup(request_id);
   DCHECK(request) << "Invalid request id";
   StatusCallback callback = request->error_callback;
 
   FinishRequest(request_id,
-                result == blink::WebServiceWorkerEventResultCompleted);
+                result == blink::WebServiceWorkerEventResultCompleted,
+                dispatch_event_time);
 
   ServiceWorkerStatusCode status = SERVICE_WORKER_OK;
   if (result == blink::WebServiceWorkerEventResultRejected)
     status = SERVICE_WORKER_ERROR_EVENT_WAITUNTIL_REJECTED;
   callback.Run(status);
 }
 
 void ServiceWorkerVersion::OnOpenWindow(int request_id, GURL url) {
   // Just abort if we are shutting down.
   if (!context_)
@@ skipping 766 matching lines @@
   ServiceWorkerMetrics::RecordTimeBetweenEvents(base::TimeTicks::Now() -
                                                 idle_time_);
 }
 
 void ServiceWorkerVersion::FinishStartWorker(ServiceWorkerStatusCode status) {
   start_worker_first_purpose_ = base::nullopt;
   RunCallbacks(this, &start_callbacks_, status);
 }
 
 }  // namespace content