Service Worker: Coalesce the start worker timer into the timeout timer.

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_macros.h"
 #include "base/stl_util.h"
@@ skipping 41 matching lines @@
 const int kUpdateDelaySeconds = 1;
 
 // Timeout for waiting for a response to a ping.
 const int kPingTimeoutSeconds = 30;
 
 // 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 kDestructedStartingWorkerTimeoutThresholdSeconds = 5;  // 5 secs.

[nhiroki, 2015/03/10 00:37:10]

nit: This comment "// 5 secs." would be pointless because the const name
explains it.

[falken, 2015/03/10 06:56:36]

Done.

 
 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 227 matching lines @@
     ServiceWorkerRegistration* registration,
     const GURL& script_url,
     int64 version_id,
     base::WeakPtr<ServiceWorkerContextCore> context)
     : version_id_(version_id),
       registration_id_(kInvalidServiceWorkerVersionId),
       script_url_(script_url),
       status_(NEW),
       context_(context),
       script_cache_map_(this, context),
-      ping_timed_out_(false),
+      ping_state_(PING_NOT_STARTED),
       is_doomed_(false),
       skip_waiting_(false),
       weak_factory_(this) {
   DCHECK(context_);
   DCHECK(registration);
   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() &&
-      GetTickDuration(start_timing_) >
-          base::TimeDelta::FromSeconds(
-              kDestructedStartingWorkerTimeoutThresholdSeconds)) {
+  if (GetTickDuration(start_time_) >
+      base::TimeDelta::FromSeconds(
+          kDestructedStartingWorkerTimeoutThresholdSeconds)) {
+    DCHECK(timeout_timer_.IsRunning());
+    DCHECK(!embedded_worker_->devtools_attached());
     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) {
@@ skipping 44 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();
+      if (!timeout_timer_.IsRunning())
+        StartTimeoutTimer();
       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::OnStartSentAndScriptEvaluated,
                        weak_factory_.GetWeakPtr()));
       }
       return;
@@ skipping 375 matching lines @@
     return;
   is_doomed_ = true;
   if (!HasControllee())
     DoomInternal();
 }
 
 void ServiceWorkerVersion::SetDevToolsAttached(bool attached) {
   embedded_worker()->set_devtools_attached(attached);
   if (attached) {
     // Set to null time so we don't record the startup time metric.
-    ClearTick(&start_timing_);
+    ClearTick(&start_time_);
     return;
   }
-  // If devtools is detached try scheduling the timers for stopping the worker
-  // now.
   if (!timeout_timer_.IsRunning())
     StartTimeoutTimer();
-  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();
 }
 
 void ServiceWorkerVersion::OnScriptLoaded() {
   DCHECK_EQ(STARTING, running_status());
-  StartTimeoutTimer();
+  ping_state_ = PING_STARTED;

[kinuko, 2015/03/09 09:30:40]

nit: This line (or enum name) may look a bit cryptic as people would expect line
1484 to be the point when we start pinging.

[falken, 2015/03/09 10:10:55]

Agreed. I renamed the enums and added a comment.

 }
 
 void ServiceWorkerVersion::OnStarted() {
   DCHECK_EQ(RUNNING, running_status());
   DCHECK(cache_listener_.get());
   RestartTick(&idle_time_);
 
   // Fire all start callbacks.
   scoped_refptr<ServiceWorkerVersion> protect(this);
   RunCallbacks(this, &start_callbacks_, SERVICE_WORKER_OK);
   FOR_EACH_OBSERVER(Listener, listeners_, OnWorkerStarted(this));
 }
 
 void ServiceWorkerVersion::OnStopped(
     EmbeddedWorkerInstance::Status old_status) {
   DCHECK_EQ(STOPPED, running_status());
   scoped_refptr<ServiceWorkerVersion> protect(this);
 
   bool should_restart = !is_doomed() && !start_callbacks_.empty() &&
                         (old_status != EmbeddedWorkerInstance::STARTING);
 
   StopTimeoutTimer();
-  if (ping_timed_out_)
+  if (ping_state_ == PING_TIMED_OUT)
     should_restart = false;
 
   // Fire all stop callbacks.
   RunCallbacks(this, &stop_callbacks_, SERVICE_WORKER_OK);
 
   if (!should_restart) {
     // Let all start callbacks fail.
     RunCallbacks(this, &start_callbacks_,
                  SERVICE_WORKER_ERROR_START_WORKER_FAILED);
   }
@@ skipping 25 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();
+    if (embedded_worker_->devtools_attached())
+      ClearTick(&start_time_);
+    else
+      RestartTick(&start_time_);
     cache_listener_.reset(new ServiceWorkerCacheListener(this, context_));
     embedded_worker_->Start(
         version_id_, scope_, script_url_, false /* pause_after_download */,
         base::Bind(&ServiceWorkerVersion::OnStartSentAndScriptEvaluated,
                    weak_factory_.GetWeakPtr()));
   }
 }
 
 void ServiceWorkerVersion::OnReportException(
     const base::string16& error_message,
@@ skipping 524 matching lines @@
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
   if (running_status() != RUNNING)
     return;
 
   embedded_worker_->SendMessage(
       ServiceWorkerMsg_DidGetClients(request_id, clients));
 }
 
 void ServiceWorkerVersion::StartTimeoutTimer() {
   DCHECK(!timeout_timer_.IsRunning());
+
+  if (embedded_worker_->devtools_attached())
+    ClearTick(&start_time_);
+  else
+    RestartTick(&start_time_);
+  start_callbacks_.push_back(
+      base::Bind(&ServiceWorkerVersion::RecordStartWorkerResult,
+                 weak_factory_.GetWeakPtr()));
+
   ClearTick(&idle_time_);
   ClearTick(&ping_time_);
-  ping_timed_out_ = false;
+  ping_state_ = PING_NOT_STARTED;
+
   timeout_timer_.Start(FROM_HERE,
                        base::TimeDelta::FromSeconds(kTimeoutTimerDelaySeconds),
                        this, &ServiceWorkerVersion::OnTimeoutTimer);
 }
 
 void ServiceWorkerVersion::StopTimeoutTimer() {
   timeout_timer_.Stop();
 }
 
 void ServiceWorkerVersion::OnTimeoutTimer() {
+  DCHECK(running_status() == STARTING || running_status() == RUNNING ||
+         running_status() == STOPPING)
+      << running_status();
+
+  if (GetTickDuration(start_time_) >

[kinuko, 2015/03/09 09:30:40]

nit: Could we have one-line comments for each of these timeouts, e.g. 'starting
a worker hasn't finished within a certain period', 'the worker has been in idle
for longer than a certain period', 'the worker hasn't responded to our ping
within a certain period' etc.

[falken, 2015/03/09 10:10:55]

Done.

+      base::TimeDelta::FromMinutes(kStartWorkerTimeoutMinutes)) {
+    DCHECK_NE(RUNNING, running_status());
+    scoped_refptr<ServiceWorkerVersion> protect(this);
+    RunCallbacks(this, &start_callbacks_, SERVICE_WORKER_ERROR_TIMEOUT);
+    if (running_status() == STARTING)
+      embedded_worker_->Stop();
+    StopTimeoutTimer();
+    return;
+  }
+
   if (running_status() == STOPPING)
     return;

[kinuko, 2015/03/09 09:30:40]

nit: could this check be done before we check start_time?

[falken, 2015/03/09 10:10:55]

Thanks for pointing this out. The start_time timeout is different from the
others: it doesn't just stop the worker but also invokes start callbacks with
ERROR_TIMEOUT. This means StartWorker(); StopWorker(); will be able to fail
callbacks even if we got stuck at some point.

But there's a bug with the current patch: if ping_time expires happens before
start_time, it's possible that start callbacks will never be invoked with
ERROR_TIMEOUT.

I think I have to redesign this so the timeout timer continues running even
after one thing times out.

[falken, 2015/03/10 06:56:36]

Updated this... the timeout timer now continues until the worker is actually
stopped.

-  DCHECK(running_status() == STARTING || running_status() == RUNNING);
+
   if (GetTickDuration(idle_time_) >
       base::TimeDelta::FromSeconds(kIdleWorkerTimeoutSeconds)) {
     StopWorkerIfIdle();
     StopTimeoutTimer();
     return;
   }
   if (GetTickDuration(ping_time_) >
       base::TimeDelta::FromSeconds(kPingTimeoutSeconds)) {
     OnPingTimeout();
     StopTimeoutTimer();
     return;
   }
 
-  if (ping_time_.is_null())
+  if (ping_state_ == PING_STARTED && ping_time_.is_null())
     PingWorker();
 }
 
 void ServiceWorkerVersion::PingWorker() {
   DCHECK(running_status() == STARTING || running_status() == RUNNING);
+  DCHECK_EQ(PING_STARTED, ping_state_);
   ServiceWorkerStatusCode status =
       embedded_worker_->SendMessage(ServiceWorkerMsg_Ping());
   if (status != SERVICE_WORKER_OK) {
     // TODO(falken): Maybe try resending Ping a few times first?
-    ping_timed_out_ =  true;
+    ping_state_ = PING_TIMED_OUT;
     StopWorkerIfIdle();
     return;
   }
   RestartTick(&ping_time_);
 }
 
 void ServiceWorkerVersion::OnPingTimeout() {
   DCHECK(running_status() == STARTING || running_status() == RUNNING);
-  ping_timed_out_ = true;
+  ping_state_ = PING_TIMED_OUT;
   // TODO(falken): Show a message to the developer that the SW was stopped due
   // to timeout (crbug.com/457968). Also, change the error code to
   // SERVICE_WORKER_ERROR_TIMEOUT.
   StopWorkerIfIdle();
 }
 
 void ServiceWorkerVersion::StopWorkerIfIdle() {
-  if (HasInflightRequests() && !ping_timed_out_)
+  if (HasInflightRequests() && ping_state_ != PING_TIMED_OUT)
     return;
   if (running_status() == STOPPED || running_status() == STOPPING ||
       !stop_callbacks_.empty()) {
     return;
   }
 
   // TODO(falken): We may need to handle StopIfIdle failure and
   // forcibly fail pending callbacks so no one is stuck waiting
   // for the worker.
   embedded_worker_->StopIfIdle();
 }
 
 bool ServiceWorkerVersion::HasInflightRequests() const {
   return
     !activate_callbacks_.IsEmpty() ||
     !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("ServiceWorker.StartWorker.Status", status,
                             SERVICE_WORKER_ERROR_MAX_VALUE);
-  if (status == SERVICE_WORKER_OK && !start_timing_.is_null()) {
+  if (status == SERVICE_WORKER_OK && !start_time_.is_null()) {
     UMA_HISTOGRAM_MEDIUM_TIMES("ServiceWorker.StartWorker.Time",
-                               GetTickDuration(start_timing_));
+                               GetTickDuration(start_time_));
   }
 
+  ClearTick(&start_time_);
   if (status != SERVICE_WORKER_ERROR_TIMEOUT)
     return;
   EmbeddedWorkerInstance::StartingPhase phase =
       EmbeddedWorkerInstance::NOT_STARTING;
   EmbeddedWorkerInstance::Status running_status = embedded_worker_->status();
   // Build an artifical JavaScript exception to show in the ServiceWorker
   // log for developers; it's not user-facing so it's not a localized resource.
   std::string message = "ServiceWorker startup timed out. ";
   if (running_status != EmbeddedWorkerInstance::STARTING) {
     message.append("The worker had unexpected status: ");
@@ skipping 29 matching lines @@
     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