Add ServiceWorker.TimeBetweenEvents UMA

This will help decide how quickly to kill service workers after they
finished handling available events.

BUG=519956

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

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

5 files changed, 71 insertions, 16 deletions

diff --git a/content/browser/service_worker/service_worker_metrics.cc b/content/browser/service_worker/service_worker_metrics.cc
index 65429b0..edd3616 100644
--- a/content/browser/service_worker/service_worker_metrics.cc
+++ b/content/browser/service_worker/service_worker_metrics.cc
@@ -37,12 +37,6 @@ ServiceWorkerMetrics::Site SiteFromURL(const GURL& gurl) {
   return ServiceWorkerMetrics::Site::OTHER;
 }
 
-bool ShouldExcludeForHistogram(const GURL& scope) {
-  // Exclude NTP scope from UMA for now as it tends to dominate the stats
-  // and makes the results largely skewed.
-  return SiteFromURL(scope) == ServiceWorkerMetrics::Site::NEW_TAB_PAGE;
-}
-
 enum EventHandledRatioType {
   EVENT_HANDLED_NONE,
   EVENT_HANDLED_SOME,
@@ -52,6 +46,14 @@ enum EventHandledRatioType {
 
 }  // namespace
 
+bool ServiceWorkerMetrics::ShouldExcludeSiteFromHistogram(Site site) {
+  return site == ServiceWorkerMetrics::Site::NEW_TAB_PAGE;
+}
+
+bool ServiceWorkerMetrics::ShouldExcludeURLFromHistogram(const GURL& url) {
+  return ShouldExcludeSiteFromHistogram(SiteFromURL(url));
+}
+
 void ServiceWorkerMetrics::CountInitDiskCacheResult(bool result) {
   UMA_HISTOGRAM_BOOLEAN("ServiceWorker.DiskCache.InitResult", result);
 }
@@ -114,8 +116,7 @@ void ServiceWorkerMetrics::CountControlledPageLoad(const GURL& url) {
   UMA_HISTOGRAM_ENUMERATION("ServiceWorker.PageLoad", static_cast<int>(site),
                             static_cast<int>(Site::NUM_TYPES));
 
-  // Don't record NTP on RAPPOR since it would dominate the data.
-  if (site == Site::NEW_TAB_PAGE)
+  if (ShouldExcludeSiteFromHistogram(site))
     return;
   BrowserThread::PostTask(BrowserThread::UI, FROM_HERE,
                           base::Bind(&RecordURLMetricOnUI, url));
@@ -162,11 +163,10 @@ void ServiceWorkerMetrics::RecordInstallEventStatus(
                             SERVICE_WORKER_ERROR_MAX_VALUE);
 }
 
-void ServiceWorkerMetrics::RecordEventHandledRatio(const GURL& scope,
-                                                   EventType event,
+void ServiceWorkerMetrics::RecordEventHandledRatio(EventType event,
                                                    size_t handled_events,
                                                    size_t fired_events) {
-  if (!fired_events || ShouldExcludeForHistogram(scope))
+  if (!fired_events)
     return;
   EventHandledRatioType type = EVENT_HANDLED_SOME;
   if (fired_events == handled_events)
@@ -239,4 +239,9 @@ void ServiceWorkerMetrics::RecordFallbackedRequestMode(FetchRequestMode mode) {
                             mode, FETCH_REQUEST_MODE_LAST + 1);
 }
 
+void ServiceWorkerMetrics::RecordTimeBetweenEvents(
+    const base::TimeDelta& time) {
+  UMA_HISTOGRAM_MEDIUM_TIMES("ServiceWorker.TimeBetweenEvents", time);
+}
+
 }  // namespace content
diff --git a/content/browser/service_worker/service_worker_metrics.h b/content/browser/service_worker/service_worker_metrics.h
index 0c996fe..1e6f32f 100644
--- a/content/browser/service_worker/service_worker_metrics.h
+++ b/content/browser/service_worker/service_worker_metrics.h
@@ -86,6 +86,12 @@ class ServiceWorkerMetrics {
   // Used for UMA. Append only.
   enum class Site { OTHER, NEW_TAB_PAGE, NUM_TYPES };
 
+  // Excludes NTP scope from UMA for now as it tends to dominate the stats and
+  // makes the results largely skewed. Some metrics don't follow this policy
+  // and hence don't call this function.
+  static bool ShouldExcludeSiteFromHistogram(Site site);
+  static bool ShouldExcludeURLFromHistogram(const GURL& url);
+
   // Used for ServiceWorkerDiskCache.
   static void CountInitDiskCacheResult(bool result);
   static void CountReadResponseResult(ReadResponseResult result);
@@ -126,8 +132,7 @@ class ServiceWorkerMetrics {
 
   // Records how much of dispatched events are handled while a Service
   // Worker is awake (i.e. after it is woken up until it gets stopped).
-  static void RecordEventHandledRatio(const GURL& scope,
-                                      EventType event,
+  static void RecordEventHandledRatio(EventType event,
                                       size_t handled_events,
                                       size_t fired_events);
 
@@ -154,6 +159,11 @@ class ServiceWorkerMetrics {
   // Records the mode of request that was fallbacked to the network.
   static void RecordFallbackedRequestMode(FetchRequestMode mode);
 
+  // Called at the beginning of each ServiceWorkerVersion::Dispatch*Event
+  // function. Records the time elapsed since idle (generally the time since the
+  // previous event ended).
+  static void RecordTimeBetweenEvents(const base::TimeDelta& time);
+
  private:
   DISALLOW_IMPLICIT_CONSTRUCTORS(ServiceWorkerMetrics);
 };
diff --git a/content/browser/service_worker/service_worker_version.cc b/content/browser/service_worker/service_worker_version.cc
index d4cee37..f07a870 100644
--- a/content/browser/service_worker/service_worker_version.cc
+++ b/content/browser/service_worker/service_worker_version.cc
@@ -410,10 +410,11 @@ class ServiceWorkerVersion::Metrics {
   using EventType = ServiceWorkerMetrics::EventType;
   explicit Metrics(ServiceWorkerVersion* owner) : owner_(owner) {}
   ~Metrics() {
+    if (owner_->should_exclude_from_uma_)
+      return;
     for (const auto& ev : event_stats_) {
-      ServiceWorkerMetrics::RecordEventHandledRatio(owner_->scope(), ev.first,
-                                                    ev.second.handled_events,
-                                                    ev.second.fired_events);
+      ServiceWorkerMetrics::RecordEventHandledRatio(
+          ev.first, ev.second.handled_events, ev.second.fired_events);
     }
   }
 
@@ -537,6 +538,8 @@ ServiceWorkerVersion::ServiceWorkerVersion(
       context_(context),
       script_cache_map_(this, context),
       ping_controller_(new PingController(this)),
+      should_exclude_from_uma_(
+          ServiceWorkerMetrics::ShouldExcludeURLFromHistogram(scope_)),
       weak_factory_(this) {
   DCHECK(context_);
   DCHECK(registration);
@@ -705,6 +708,7 @@ void ServiceWorkerVersion::DispatchMessageEventInternal(
     const base::string16& message,
     const std::vector<TransferredMessagePort>& sent_message_ports,
     const StatusCallback& callback) {
+  OnBeginEvent();
   if (running_status() != RUNNING) {
     // Schedule calling this method after starting the worker.
     StartWorker(base::Bind(
@@ -732,6 +736,7 @@ void ServiceWorkerVersion::DispatchMessageEventInternal(
 
 void ServiceWorkerVersion::DispatchInstallEvent(
     const StatusCallback& callback) {
+  OnBeginEvent();
   DCHECK_EQ(INSTALLING, status()) << status();
 
   if (running_status() != RUNNING) {
@@ -750,6 +755,7 @@ void ServiceWorkerVersion::DispatchInstallEvent(
 
 void ServiceWorkerVersion::DispatchActivateEvent(
     const StatusCallback& callback) {
+  OnBeginEvent();
   DCHECK_EQ(ACTIVATING, status()) << status();
 
   if (running_status() != RUNNING) {
@@ -770,6 +776,7 @@ void ServiceWorkerVersion::DispatchFetchEvent(
     const ServiceWorkerFetchRequest& request,
     const base::Closure& prepare_callback,
     const FetchCallback& fetch_callback) {
+  OnBeginEvent();
   DCHECK_EQ(ACTIVATED, status()) << status();
 
   if (running_status() != RUNNING) {
@@ -800,6 +807,7 @@ void ServiceWorkerVersion::DispatchFetchEvent(
 
 void ServiceWorkerVersion::DispatchSyncEvent(SyncRegistrationPtr registration,
                                              const StatusCallback& callback) {
+  OnBeginEvent();
   DCHECK_EQ(ACTIVATED, status()) << status();
   if (running_status() != RUNNING) {
     // Schedule calling this method after starting the worker.
@@ -829,6 +837,7 @@ void ServiceWorkerVersion::DispatchNotificationClickEvent(
     int64_t persistent_notification_id,
     const PlatformNotificationData& notification_data,
     int action_index) {
+  OnBeginEvent();
   DCHECK_EQ(ACTIVATED, status()) << status();
   if (running_status() != RUNNING) {
     // Schedule calling this method after starting the worker.
@@ -855,6 +864,7 @@ void ServiceWorkerVersion::DispatchNotificationClickEvent(
 
 void ServiceWorkerVersion::DispatchPushEvent(const StatusCallback& callback,
                                              const std::string& data) {
+  OnBeginEvent();
   DCHECK_EQ(ACTIVATED, status()) << status();
   if (running_status() != RUNNING) {
     // Schedule calling this method after starting the worker.
@@ -880,6 +890,7 @@ void ServiceWorkerVersion::DispatchGeofencingEvent(
     blink::WebGeofencingEventType event_type,
     const std::string& region_id,
     const blink::WebCircularGeofencingRegion& region) {
+  OnBeginEvent();
   DCHECK_EQ(ACTIVATED, status()) << status();
 
   if (!base::CommandLine::ForCurrentProcess()->HasSwitch(
@@ -918,6 +929,7 @@ void ServiceWorkerVersion::DispatchServicePortConnectEvent(
     const GURL& target_url,
     const GURL& origin,
     int port_id) {
+  OnBeginEvent();
   DCHECK_EQ(ACTIVATED, status()) << status();
 
   if (!base::CommandLine::ForCurrentProcess()->HasSwitch(
@@ -958,6 +970,7 @@ void ServiceWorkerVersion::DispatchCrossOriginMessageEvent(
     const base::string16& message,
     const std::vector<TransferredMessagePort>& sent_message_ports,
     const StatusCallback& callback) {
+  OnBeginEvent();
   // Unlike in the case of DispatchMessageEvent, here the caller is assumed to
   // have already put all the sent message ports on hold. So no need to do that
   // here again.
@@ -1951,6 +1964,7 @@ void ServiceWorkerVersion::StartTimeoutTimer() {
     skip_recording_startup_time_ = false;
   }
 
+  // The worker is starting up and not yet idle.
   ClearTick(&idle_time_);
 
   // Ping will be activated in OnScriptLoaded.
@@ -1963,6 +1977,7 @@ void ServiceWorkerVersion::StartTimeoutTimer() {
 
 void ServiceWorkerVersion::StopTimeoutTimer() {
   timeout_timer_.Stop();
+  ClearTick(&idle_time_);
 
   // Trigger update if worker is stale.
   if (!in_dtor_ && !stale_time_.is_null()) {
@@ -2306,4 +2321,13 @@ void ServiceWorkerVersion::OnBackgroundSyncDispatcherConnectionError() {
   background_sync_dispatcher_.reset();
 }
 
+void ServiceWorkerVersion::OnBeginEvent() {
+  if (should_exclude_from_uma_ || running_status() != RUNNING ||
+      idle_time_.is_null()) {
+    return;
+  }
+  ServiceWorkerMetrics::RecordTimeBetweenEvents(base::TimeTicks::Now() -
+                                                idle_time_);
+}
+
 }  // namespace content
diff --git a/content/browser/service_worker/service_worker_version.h b/content/browser/service_worker/service_worker_version.h
index 7a7c38f..bf9ba27 100644
--- a/content/browser/service_worker/service_worker_version.h
+++ b/content/browser/service_worker/service_worker_version.h
@@ -552,6 +552,11 @@ class CONTENT_EXPORT ServiceWorkerVersion
   void OnServicePortDispatcherConnectionError();
   void OnBackgroundSyncDispatcherConnectionError();
 
+  // Called at the beginning of each Dispatch*Event function: records
+  // the time elapsed since idle (generally the time since the previous
+  // event ended).
+  void OnBeginEvent();
+
   const int64 version_id_;
   const int64 registration_id_;
   const GURL script_url_;
@@ -624,6 +629,7 @@ class CONTENT_EXPORT ServiceWorkerVersion
 
   scoped_ptr<PingController> ping_controller_;
   scoped_ptr<Metrics> metrics_;
+  const bool should_exclude_from_uma_ = false;
 
   base::WeakPtrFactory<ServiceWorkerVersion> weak_factory_;
 
diff --git a/tools/metrics/histograms/histograms.xml b/tools/metrics/histograms/histograms.xml
index 9b3bc08..9b3c6ce 100644
--- a/tools/metrics/histograms/histograms.xml
+++ b/tools/metrics/histograms/histograms.xml
@@ -39334,6 +39334,16 @@ http://cs/file:chrome/histograms.xml - but prefer this file for new entries.
   </summary>
 </histogram>
 
+<histogram name="ServiceWorker.TimeBetweenEvents" units="milliseconds">
+  <owner>falken@chromium.org</owner>
+  <summary>
+    Called at the beginning of each ServiceWorkerVersion::Dispatch*Event
+    function: the time elapsed since idle. Generally this is the time between
+    one event ending and one event starting, if the worker remained running in
+    the interim.
+  </summary>
+</histogram>
+
 <histogram name="ServiceWorker.UnhandledEventRatio" units="percent">
   <owner>kinuko@chromium.org</owner>
   <obsolete>