ServiceWorker: Add UMA to measure execution times of oninstall/onfetch

BUG=407997
TEST=N/A

Review URL: https://codereview.chromium.org/604193002

Cr-Commit-Position: refs/heads/master@{#297352}

content/renderer/service_worker/service_worker_script_context.cc

@@ -4,10 +4,9 @@
 
 #include "content/renderer/service_worker/service_worker_script_context.h"
 
-#include <map>
-
 #include "base/debug/trace_event.h"
 #include "base/logging.h"
+#include "base/metrics/histogram.h"
 #include "content/child/thread_safe_sender.h"
 #include "content/child/webmessageportchannel_impl.h"
 #include "content/common/service_worker/service_worker_messages.h"
@@ -73,6 +72,11 @@ void ServiceWorkerScriptContext::OnMessageReceived(
 void ServiceWorkerScriptContext::DidHandleActivateEvent(
     int request_id,
     blink::WebServiceWorkerEventResult result) {
+  UMA_HISTOGRAM_TIMES(
+      "ServiceWorker.ActivateEventExecutionTime",
+      base::TimeTicks::Now() - activate_start_timings_[request_id]);
+  activate_start_timings_.erase(request_id);
+
   Send(new ServiceWorkerHostMsg_ActivateEventFinished(
       GetRoutingID(), request_id, result));
 }
@@ -80,6 +84,11 @@ void ServiceWorkerScriptContext::DidHandleActivateEvent(
 void ServiceWorkerScriptContext::DidHandleInstallEvent(
     int request_id,
     blink::WebServiceWorkerEventResult result) {
+  UMA_HISTOGRAM_TIMES(
+      "ServiceWorker.InstallEventExecutionTime",
+      base::TimeTicks::Now() - install_start_timings_[request_id]);
+  install_start_timings_.erase(request_id);
+
   Send(new ServiceWorkerHostMsg_InstallEventFinished(
       GetRoutingID(), request_id, result));
 }
@@ -88,6 +97,11 @@ void ServiceWorkerScriptContext::DidHandleFetchEvent(
     int request_id,
     ServiceWorkerFetchEventResult result,
     const ServiceWorkerResponse& response) {
+  UMA_HISTOGRAM_TIMES(
+      "ServiceWorker.FetchEventExecutionTime",
+      base::TimeTicks::Now() - fetch_start_timings_[request_id]);
+  fetch_start_timings_.erase(request_id);
+
   Send(new ServiceWorkerHostMsg_FetchEventFinished(
       GetRoutingID(), request_id, result, response));
 }
@@ -131,6 +145,7 @@ int ServiceWorkerScriptContext::GetRoutingID() const {
 void ServiceWorkerScriptContext::OnActivateEvent(int request_id) {
   TRACE_EVENT0("ServiceWorker",
                "ServiceWorkerScriptContext::OnActivateEvent");
+  activate_start_timings_[request_id] = base::TimeTicks::Now();
   proxy_->dispatchActivateEvent(request_id);
 }
 
@@ -138,6 +153,7 @@ void ServiceWorkerScriptContext::OnInstallEvent(int request_id,
                                                 int active_version_id) {
   TRACE_EVENT0("ServiceWorker",
                "ServiceWorkerScriptContext::OnInstallEvent");
+  install_start_timings_[request_id] = base::TimeTicks::Now();
   proxy_->dispatchInstallEvent(request_id);
 }
 
@@ -162,6 +178,7 @@ void ServiceWorkerScriptContext::OnFetchEvent(
   webRequest.setReferrer(blink::WebString::fromUTF8(request.referrer.spec()),
                          blink::WebReferrerPolicyDefault);
   webRequest.setIsReload(request.is_reload);
+  fetch_start_timings_[request_id] = base::TimeTicks::Now();
   proxy_->dispatchFetchEvent(request_id, webRequest);
 }
 

content/renderer/service_worker/service_worker_script_context.h

@@ -5,6 +5,7 @@
 #ifndef CONTENT_RENDERER_SERVICE_WORKER_SERVICE_WORKER_SCRIPT_CONTEXT_H_
 #define CONTENT_RENDERER_SERVICE_WORKER_SERVICE_WORKER_SCRIPT_CONTEXT_H_
 
+#include <map>
 #include <string>
 #include <vector>
 
@@ -12,6 +13,7 @@
 #include "base/id_map.h"
 #include "base/memory/scoped_ptr.h"
 #include "base/strings/string16.h"
+#include "base/time/time.h"
 #include "content/child/webmessageportchannel_impl.h"
 #include "content/common/service_worker/service_worker_types.h"
 #include "content/renderer/service_worker/service_worker_cache_storage_dispatcher.h"
@@ -102,6 +104,11 @@ class ServiceWorkerScriptContext {
   // Pending callbacks for GetClientDocuments().
   ClientsCallbacksMap pending_clients_callbacks_;
 
+  // Capture timestamps for UMA
+  std::map<int, base::TimeTicks> activate_start_timings_;
+  std::map<int, base::TimeTicks> fetch_start_timings_;
+  std::map<int, base::TimeTicks> install_start_timings_;
+
   DISALLOW_COPY_AND_ASSIGN(ServiceWorkerScriptContext);
 };
 

tools/metrics/histograms/histograms.xml

@@ -29444,6 +29444,11 @@ Therefore, the affected-histogram name has to have at least one dot in it.
   </summary>
 </histogram>
 
+<histogram name="ServiceWorker.ActivateEventExecutionTime" units="millisecond">
+  <owner>shimazu@chromium.org</owner>
+  <summary>Execution time of ServiceWorkerGlobalScope.onactivate.</summary>
+</histogram>
+
 <histogram name="ServiceWorker.Database.OpenResult"
     enum="ServiceWorkerDatabaseStatus">
   <owner>nhiroki@chromium.org</owner>
@@ -29489,6 +29494,16 @@ Therefore, the affected-histogram name has to have at least one dot in it.
   </summary>
 </histogram>
 
+<histogram name="ServiceWorker.FetchEventExecutionTime" units="millisecond">
+  <owner>shimazu@chromium.org</owner>
+  <summary>Execution time of ServiceWorkerGlobalScope.onfetch.</summary>
+</histogram>
+
+<histogram name="ServiceWorker.InstallEventExecutionTime" units="millisecond">
+  <owner>shimazu@chromium.org</owner>
+  <summary>Execution time of ServiceWorkerGlobalScope.oninstall.</summary>
+</histogram>
+
 <histogram name="ServiceWorker.ScriptSize" units="bytes">
   <owner>ksakamoto@chromium.org</owner>
   <summary>