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"
 #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;
+
 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 208 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() &&
+      (base::TimeTicks::Now() - start_timing_) >
+          base::TimeDelta::FromSeconds(5)) {
+    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();

[kinuko, 2015/03/02 03:19:33]

when we come here running_status() == STOPPED should be always true?

[falken, 2015/03/02 04:19:17]

Not necessarily, you could call StopWorker(); StartWorker(); so running_status
is STOPPING.

We shouldn't have status STARTING though I think.

       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();
 }
 
 void ServiceWorkerVersion::SetMainScriptHttpResponseInfo(
     const net::HttpResponseInfo& http_info) {
@@ skipping 69 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 463 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_.Reset();

[kinuko, 2015/03/02 03:19:33]

Hm, why do we reset but not stop the timer here?

[falken, 2015/03/02 04:19:16]

Changed to stop here and restart the timer in SetDevToolsAttached.

+    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",
+                               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