Service Worker: Add metrics and timeout for starting a Service Worker.

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 "base/command_line.h"
 #include "base/memory/ref_counted.h"
+#include "base/metrics/histogram.h"

[rkaplow, 2015/03/03 15:58:41]

histogram_macros.h

[falken, 2015/03/04 04:16:34]

Done.

 #include "base/stl_util.h"
 #include "base/strings/string16.h"
 #include "base/strings/utf_string_conversions.h"
 #include "base/time/time.h"
 #include "content/browser/message_port_message_filter.h"
 #include "content/browser/message_port_service.h"
 #include "content/browser/service_worker/embedded_worker_instance.h"
 #include "content/browser/service_worker/embedded_worker_registry.h"
 #include "content/browser/service_worker/service_worker_context_core.h"
 #include "content/browser/service_worker/service_worker_context_wrapper.h"
@@ skipping 10 matching lines @@
 #include "content/public/browser/web_contents_observer.h"
 #include "content/public/common/child_process_host.h"
 #include "content/public/common/content_client.h"
 #include "content/public/common/content_switches.h"
 #include "content/public/common/result_codes.h"
 #include "net/http/http_response_info.h"
 
 namespace content {
 
 typedef ServiceWorkerVersion::StatusCallback StatusCallback;
-typedef ServiceWorkerVersion::MessageCallback MessageCallback;
 
 class ServiceWorkerVersion::GetClientDocumentsCallback
     : public base::RefCounted<GetClientDocumentsCallback> {
  public:
   GetClientDocumentsCallback(int request_id,
                              ServiceWorkerVersion* version)
       : request_id_(request_id),
         version_(version) {
     DCHECK(version_);
   }
@@ skipping 34 matching lines @@
 
 // Default delay for scheduled update.
 const int kUpdateDelaySeconds = 1;
 
 // Delay between sending pings to the worker.
 const int kPingIntervalTime = 10;  // 10 secs.
 
 // Timeout for waiting for a response to a ping.
 const int kPingTimeoutTime = 30;  // 30 secs.
 
+// Timeout for the worker to start.
+const int kStartWorkerTimeoutMinutes = 5;
+
+// If the SW was destructed while starting up, how many seconds it
+// had to start up for this to be considered a timeout occurrence.
+const int kDestructedStartingWorkerTimeoutThreshold = 5;  // 5 secs.

[rkaplow, 2015/03/03 15:58:41]

add Sec in const name?

[falken, 2015/03/04 04:16:34]

Done. I feel like there's a more pithy name possible... oh well.

+
 const char kClaimClientsStateErrorMesage[] =
     "Only the active worker can claim clients.";
 
 const char kClaimClientsShutdownErrorMesage[] =
     "Failed to claim clients due to Service Worker system shutdown.";
 
 void RunSoon(const base::Closure& callback) {
   if (!callback.is_null())
     base::MessageLoop::current()->PostTask(FROM_HERE, callback);
 }
@@ skipping 196 matching lines @@
   if (registration) {
     registration_id_ = registration->id();
     scope_ = registration->pattern();
   }
   context_->AddLiveVersion(this);
   embedded_worker_ = context_->embedded_worker_registry()->CreateWorker();
   embedded_worker_->AddListener(this);
 }
 
 ServiceWorkerVersion::~ServiceWorkerVersion() {
+  // The user may have closed the tab waiting for SW to start up.
+  if (start_worker_timeout_timer_.IsRunning() && !start_timing_.is_null()) {
+    if ((base::TimeTicks::Now() - start_timing_) >
+        base::TimeDelta::FromSeconds(
+            kDestructedStartingWorkerTimeoutThreshold)) {
+      RecordStartWorkerResult(SERVICE_WORKER_ERROR_TIMEOUT);
+    }
+  }
+
   embedded_worker_->RemoveListener(this);
   if (context_)
     context_->RemoveLiveVersion(version_id_);
   // EmbeddedWorker's dtor sends StopWorker if it's still running.
 }
 
 void ServiceWorkerVersion::SetStatus(Status status) {
   if (status_ == status)
     return;
 
@@ skipping 41 matching lines @@
     RunSoon(base::Bind(callback, SERVICE_WORKER_ERROR_START_WORKER_FAILED));
     return;
   }
   switch (running_status()) {
     case RUNNING:
       RunSoon(base::Bind(callback, SERVICE_WORKER_OK));
       return;
     case STOPPING:
     case STOPPED:
     case STARTING:
+      if (!start_worker_timeout_timer_.IsRunning())
+        ScheduleStartWorkerTimeout();
       start_callbacks_.push_back(callback);
       if (running_status() == STOPPED) {
         DCHECK(!cache_listener_.get());
         cache_listener_.reset(new ServiceWorkerCacheListener(this, context_));
         embedded_worker_->Start(
-            version_id_,
-            scope_,
-            script_url_,
-            pause_after_download,
-            base::Bind(&ServiceWorkerVersion::OnStartMessageSent,
+            version_id_, scope_, script_url_, pause_after_download,
+            base::Bind(&ServiceWorkerVersion::OnStartSentAndScriptEvaluated,
                        weak_factory_.GetWeakPtr()));
       }
       return;
   }
 }
 
 void ServiceWorkerVersion::StopWorker(const StatusCallback& callback) {
   if (running_status() == STOPPED) {
     RunSoon(base::Bind(callback, SERVICE_WORKER_OK));
     return;
@@ skipping 388 matching lines @@
 void ServiceWorkerVersion::Doom() {
   if (is_doomed_)
     return;
   is_doomed_ = true;
   if (!HasControllee())
     DoomInternal();
 }
 
 void ServiceWorkerVersion::SetDevToolsAttached(bool attached) {
   embedded_worker()->set_devtools_attached(attached);
-  if (attached)
+  if (attached) {
+    // Set to null time so we don't record the startup time metric.
+    start_timing_ = base::TimeTicks();
     return;
+  }
   // If devtools is detached try scheduling the timers for stopping the worker
   // now.
   if (!stop_worker_timer_.IsRunning())
     ScheduleStopWorker();
   if (!ping_worker_timer_.IsRunning())
     StartPingWorker();
+  if (!start_worker_timeout_timer_.IsRunning() && !start_callbacks_.empty())
+    ScheduleStartWorkerTimeout();
 }
 
 void ServiceWorkerVersion::SetMainScriptHttpResponseInfo(
     const net::HttpResponseInfo& http_info) {
   main_script_http_info_.reset(new net::HttpResponseInfo(http_info));
 }
 
 const net::HttpResponseInfo*
 ServiceWorkerVersion::GetMainScriptHttpResponseInfo() {
   return main_script_http_info_.get();
@@ skipping 63 matching lines @@
 
   FOR_EACH_OBSERVER(Listener, listeners_, OnWorkerStopped(this));
 
   // There should be no more communication from/to a stopped worker. Deleting
   // the listener prevents any pending completion callbacks from causing
   // messages to be sent to the stopped worker.
   cache_listener_.reset();
 
   // Restart worker if we have any start callbacks and the worker isn't doomed.
   if (should_restart) {
+    start_worker_timeout_timer_.Reset();
     cache_listener_.reset(new ServiceWorkerCacheListener(this, context_));
     embedded_worker_->Start(
         version_id_, scope_, script_url_, false /* pause_after_download */,
-        base::Bind(&ServiceWorkerVersion::OnStartMessageSent,
+        base::Bind(&ServiceWorkerVersion::OnStartSentAndScriptEvaluated,
                    weak_factory_.GetWeakPtr()));
   }
 }
 
 void ServiceWorkerVersion::OnReportException(
     const base::string16& error_message,
     int line_number,
     int column_number,
     const GURL& source_url) {
   FOR_EACH_OBSERVER(
@@ skipping 52 matching lines @@
     IPC_MESSAGE_HANDLER(ServiceWorkerHostMsg_SkipWaiting,
                         OnSkipWaiting)
     IPC_MESSAGE_HANDLER(ServiceWorkerHostMsg_ClaimClients,
                         OnClaimClients)
     IPC_MESSAGE_HANDLER(ServiceWorkerHostMsg_Pong, OnPongFromWorker)
     IPC_MESSAGE_UNHANDLED(handled = false)
   IPC_END_MESSAGE_MAP()
   return handled;
 }
 
-void ServiceWorkerVersion::OnStartMessageSent(
+void ServiceWorkerVersion::OnStartSentAndScriptEvaluated(
     ServiceWorkerStatusCode status) {
   if (status != SERVICE_WORKER_OK)
     RunCallbacks(this, &start_callbacks_, status);
 }
 
 void ServiceWorkerVersion::DispatchInstallEventAfterStartWorker(
     int active_version_id,
     const StatusCallback& callback) {
   DCHECK_EQ(RUNNING, running_status())
       << "Worker stopped too soon after it was started.";
@@ skipping 481 matching lines @@
                            base::TimeDelta::FromSeconds(kPingIntervalTime),
                            base::Bind(&ServiceWorkerVersion::PingWorker,
                                       weak_factory_.GetWeakPtr()));
 }
 
 void ServiceWorkerVersion::OnPingTimeout() {
   if (running_status() != STARTING && running_status() != RUNNING)
     return;
   ping_timed_out_ = true;
   // TODO(falken): Show a message to the developer that the SW was stopped due
-  // to timeout (crbug.com/457968).
+  // to timeout (crbug.com/457968). Also, change the error code to
+  // SERVICE_WORKER_ERROR_TIMEOUT.
   StopWorkerIfIdle();
 }
 
 void ServiceWorkerVersion::ScheduleStopWorker() {
   if (running_status() != RUNNING)
     return;
   stop_worker_timer_.Stop();
   stop_worker_timer_.Start(
       FROM_HERE, base::TimeDelta::FromSeconds(
           is_doomed_ ? kStopDoomedWorkerDelay : kStopWorkerDelay),
@@ skipping 23 matching lines @@
     !install_callbacks_.IsEmpty() ||
     !fetch_callbacks_.IsEmpty() ||
     !sync_callbacks_.IsEmpty() ||
     !notification_click_callbacks_.IsEmpty() ||
     !push_callbacks_.IsEmpty() ||
     !geofencing_callbacks_.IsEmpty() ||
     !cross_origin_connect_callbacks_.IsEmpty() ||
     !streaming_url_request_jobs_.empty();
 }
 
+void ServiceWorkerVersion::ScheduleStartWorkerTimeout() {
+  DCHECK(!start_worker_timeout_timer_.IsRunning());
+  start_timing_ = embedded_worker_->devtools_attached()
+                      ? base::TimeTicks()
+                      : base::TimeTicks::Now();
+  start_callbacks_.push_back(
+      base::Bind(&ServiceWorkerVersion::RecordStartWorkerResult,
+                 weak_factory_.GetWeakPtr()));
+  start_worker_timeout_timer_.Start(
+      FROM_HERE, base::TimeDelta::FromMinutes(kStartWorkerTimeoutMinutes),
+      base::Bind(&ServiceWorkerVersion::OnStartWorkerTimeout,
+                 weak_factory_.GetWeakPtr()));
+}
+
+void ServiceWorkerVersion::OnStartWorkerTimeout() {
+  DCHECK(running_status() == STARTING || running_status() == STOPPING)
+      << running_status();
+
+  if (embedded_worker_->devtools_attached()) {
+    start_worker_timeout_timer_.Stop();
+    return;
+  }
+
+  scoped_refptr<ServiceWorkerVersion> protect(this);
+  RunCallbacks(this, &start_callbacks_, SERVICE_WORKER_ERROR_TIMEOUT);
+  if (running_status() == STARTING)
+    embedded_worker_->Stop();
+}
+
+void ServiceWorkerVersion::RecordStartWorkerResult(
+    ServiceWorkerStatusCode status) {
+  start_worker_timeout_timer_.Stop();
+
+  UMA_HISTOGRAM_ENUMERATION("ServiceWorkerVersion.StartWorkerStatus", status,
+                            SERVICE_WORKER_ERROR_MAX_VALUE);
+  if (status == SERVICE_WORKER_OK && !start_timing_.is_null()) {
+    UMA_HISTOGRAM_MEDIUM_TIMES("ServiceWorkerVersion.StartWorkerTime",

[rkaplow, 2015/03/03 15:58:41]

this histogram will measure up to 3minutes. Considering your timeout is set to 5
minutes, do you expect a lot of entries to exceed 3min?
I would say if you think >=~1% of values would exceed 3 minutes, then I would
use a longer scope. Otherwise this is ok.

[falken, 2015/03/03 16:23:58]

No, I expect it to be very rare that a SW takes 3+ minutes to successfully start
up.

... but I'm curious, is the scope something that is adjustable later? Also what
if the histogram enum values change (like if starting phases are added or
removed)?

[rkaplow, 2015/03/03 16:30:15]

Then looks good.
The scope is not really adjustable later, as if you naively increased it without
changing the name of the histogram, the resulting data would be very messy, as
it would be getting from two different data sources (with different bucket
ranges).
Which isn't to say there's nothing to do. You would just add a second histogram
called  ServiceWorkerVersion.StartWorkerTimeLong, and eventually you would
obsolete the old one. This is totally fine and happens not infrequently. It is
nice to not have to bother with that and get it right the first time, though.

No issue with adding new enum entries. You wouldn't really ever remove the old
one since very old clients may still report them.

+                               base::TimeTicks::Now() - start_timing_);
+  }
+
+  if (status != SERVICE_WORKER_ERROR_TIMEOUT)
+    return;
+  EmbeddedWorkerInstance::StartingPhase phase =
+      EmbeddedWorkerInstance::NOT_STARTING;
+  EmbeddedWorkerInstance::Status running_status = embedded_worker_->status();
+  std::string message = "ServiceWorker startup timed out. ";
+  if (running_status != EmbeddedWorkerInstance::STARTING) {
+    message.append("The worker had unexpected status: ");
+    message.append(EmbeddedWorkerInstance::StatusToString(running_status));
+  } else {
+    phase = embedded_worker_->starting_phase();
+    message.append("The worker was in startup phase: ");
+    message.append(EmbeddedWorkerInstance::StartingPhaseToString(phase));
+  }
+  message.append(".");
+  OnReportException(base::UTF8ToUTF16(message), -1, -1, GURL());
+  DVLOG(1) << message;
+  UMA_HISTOGRAM_ENUMERATION("ServiceWorkerVersion.StartWorkerTimeoutPhase",
+                            phase,
+                            EmbeddedWorkerInstance::STARTING_PHASE_MAX_VALUE);
+}
+
 void ServiceWorkerVersion::DoomInternal() {
   DCHECK(is_doomed_);
   DCHECK(!HasControllee());
   SetStatus(REDUNDANT);
   StopWorkerIfIdle();
   if (!context_)
     return;
   std::vector<ServiceWorkerDatabase::ResourceRecord> resources;
   script_cache_map_.GetResources(&resources);
   context_->storage()->PurgeResources(resources);
 }
 
 template <typename IDMAP>
 void ServiceWorkerVersion::RemoveCallbackAndStopIfDoomed(
     IDMAP* callbacks,
     int request_id) {
   callbacks->Remove(request_id);
   if (is_doomed_) {
     // The stop should be already scheduled, but try to stop immediately, in
     // order to release worker resources soon.
     StopWorkerIfIdle();
   }
 }
 
 }  // namespace content