Allow ServiceWorker events to have custom durations

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 <algorithm>
 #include <map>
 #include <string>
 
@@ skipping 311 matching lines @@
 }
 
 void ClearTick(base::TimeTicks* time) {
   *time = base::TimeTicks();
 }
 
 void RestartTick(base::TimeTicks* time) {
   *time = base::TimeTicks().Now();
 }
 
+bool RequestExpired(const base::TimeTicks& expiration) {
+  if (expiration.is_null())
+    return false;
+  return base::TimeTicks().Now() >= expiration;
+}
+
 base::TimeDelta GetTickDuration(const base::TimeTicks& time) {
   if (time.is_null())
     return base::TimeDelta();
   return base::TimeTicks().Now() - time;
 }
 
 void OnGetWindowClientsFromUI(
     // The tuple contains process_id, frame_id, client_uuid.
     const std::vector<base::Tuple<int, int, std::string>>& clients_info,
     const GURL& script_url,
@@ skipping 454 matching lines @@
     fetch_requests_.Remove(request_id);
     RunSoon(base::Bind(&RunErrorFetchCallback,
                        fetch_callback,
                        SERVICE_WORKER_ERROR_FAILED));
   }
 }
 
 void ServiceWorkerVersion::DispatchSyncEvent(
     BackgroundSyncRegistrationHandle::HandleId handle_id,
     BackgroundSyncEventLastChance last_chance,
+    base::TimeTicks expiration,
     const StatusCallback& callback) {
   OnBeginEvent();
   DCHECK_EQ(ACTIVATED, status()) << status();
   if (running_status() != RUNNING) {
     // Schedule calling this method after starting the worker.
     StartWorker(base::Bind(
         &RunTaskAfterStartWorker, weak_factory_.GetWeakPtr(), callback,
         base::Bind(&self::DispatchSyncEvent, weak_factory_.GetWeakPtr(),
-                   handle_id, last_chance, callback)));
+                   handle_id, last_chance, expiration, callback)));

[falken, 2015/12/17 13:54:32]

This means the expiration includes the time to start the worker, which can be a
few seconds in some cases (max before start worker expires is 10 seconds). If
you wanted to not include it, you could instead pass the duration for the sync
event, and compute expiration = Now() + duration after this if statement. The
other request timeouts work that way.

[jkarlin, 2015/12/17 15:01:54]

Good idea. Done.

     return;
   }
 
-  int request_id = AddRequest(callback, &sync_requests_, REQUEST_SYNC);
+  int request_id = AddRequestWithExpiration(callback, &sync_requests_,
+                                            REQUEST_SYNC, expiration);
   if (!background_sync_dispatcher_) {
     embedded_worker_->GetServiceRegistry()->ConnectToRemoteService(
         mojo::GetProxy(&background_sync_dispatcher_));
     background_sync_dispatcher_.set_connection_error_handler(base::Bind(
         &ServiceWorkerVersion::OnBackgroundSyncDispatcherConnectionError,
         weak_factory_.GetWeakPtr()));
   }
 
   background_sync_dispatcher_->Sync(
       handle_id, last_chance,
@@ skipping 243 matching lines @@
   if (attached) {
     // TODO(falken): Canceling the timeouts when debugging could cause
     // heisenbugs; we should instead run them as normal show an educational
     // message in DevTools when they occur. crbug.com/470419
 
     // Don't record the startup time metric once DevTools is attached.
     ClearTick(&start_time_);
     skip_recording_startup_time_ = true;
 
     // Cancel request timeouts.
-    SetAllRequestTimes(base::TimeTicks());
+    SetAllRequestExpirations(base::TimeTicks());
     return;
   }
   if (!start_callbacks_.empty()) {
     // Reactivate the timer for start timeout.
     DCHECK(timeout_timer_.IsRunning());
     DCHECK(running_status() == STARTING || running_status() == STOPPING)
         << running_status();
     RestartTick(&start_time_);
   }
 
-  // Reactivate request timeouts.
-  SetAllRequestTimes(base::TimeTicks::Now());
+  // Reactivate request timeouts, setting them all to the same expiration time.
+  SetAllRequestExpirations(

[falken, 2015/12/17 13:54:32]

So this means the sync event's expiration is not honored if devtools is attached
and detached, right? That's probably fine.

[jkarlin, 2015/12/17 15:01:54]

Ack.

+      base::TimeTicks::Now() +
+      base::TimeDelta::FromMinutes(kRequestTimeoutMinutes));
 }
 
 void ServiceWorkerVersion::SetMainScriptHttpResponseInfo(
     const net::HttpResponseInfo& http_info) {
   main_script_http_info_.reset(new net::HttpResponseInfo(http_info));
   FOR_EACH_OBSERVER(Listener, listeners_,
                     OnMainScriptHttpResponseInfoSet(this));
 }
 
 void ServiceWorkerVersion::SimulatePingTimeoutForTesting() {
   ping_controller_->SimulateTimeoutForTesting();
 }
 
 const net::HttpResponseInfo*
 ServiceWorkerVersion::GetMainScriptHttpResponseInfo() {
   return main_script_http_info_.get();
 }
 
-ServiceWorkerVersion::RequestInfo::RequestInfo(int id,
-                                               RequestType type,
-                                               const base::TimeTicks& now)
-    : id(id), type(type), time(now) {
+ServiceWorkerVersion::RequestInfo::RequestInfo(
+    int id,
+    RequestType type,
+    const base::TimeTicks& expiration)
+    : id(id), type(type), expiration(expiration) {}
+
+ServiceWorkerVersion::RequestInfo::~RequestInfo() {
 }
 
-ServiceWorkerVersion::RequestInfo::~RequestInfo() {
+bool ServiceWorkerVersion::RequestInfo::operator>(
+    const RequestInfo& other) const {
+  return expiration > other.expiration;
 }
 
 template <typename CallbackType>
 ServiceWorkerVersion::PendingRequest<CallbackType>::PendingRequest(
     const CallbackType& callback,
     const base::TimeTicks& time)
     : callback(callback), start_time(time) {
 }
 
 template <typename CallbackType>
@@ skipping 296 matching lines @@
 }
 
 void ServiceWorkerVersion::OnSyncEventFinished(
     int request_id,
     ServiceWorkerEventStatus status) {
   TRACE_EVENT1("ServiceWorker",
                "ServiceWorkerVersion::OnSyncEventFinished",
                "Request id", request_id);
   PendingRequest<StatusCallback>* request = sync_requests_.Lookup(request_id);
   if (!request) {
-    NOTREACHED() << "Got unexpected message: " << request_id;
+    // Assume the request timed out.
     return;
   }
 
   scoped_refptr<ServiceWorkerVersion> protect(this);
   request->callback.Run(mojo::ConvertTo<ServiceWorkerStatusCode>(status));
   RemoveCallbackAndStopIfRedundant(&sync_requests_, request_id);
 }
 
 void ServiceWorkerVersion::OnNotificationClickEventFinished(
     int request_id) {
@@ skipping 665 matching lines @@
   if (GetTickDuration(start_time_) > start_limit) {
     DCHECK(running_status() == STARTING || running_status() == STOPPING)
         << running_status();
     scoped_refptr<ServiceWorkerVersion> protect(this);
     RunCallbacks(this, &start_callbacks_, SERVICE_WORKER_ERROR_TIMEOUT);
     if (running_status() == STARTING)
       embedded_worker_->Stop();
     return;
   }
 
-  // Requests have not finished within a certain period.
-  bool request_timed_out = false;
+  // Requests have not finished before their expiration.
+  bool stop_for_timeout = false;
   while (!requests_.empty()) {
-    RequestInfo info = requests_.front();
-    if (GetTickDuration(info.time) <
-        base::TimeDelta::FromMinutes(kRequestTimeoutMinutes))
+    RequestInfo info = requests_.top();
+    if (!RequestExpired(info.expiration))
       break;
     if (MaybeTimeOutRequest(info)) {
-      request_timed_out = true;
+      stop_for_timeout = stop_for_timeout || ShouldStopIfRequestTimesOut(info);
       UMA_HISTOGRAM_ENUMERATION("ServiceWorker.RequestTimeouts.Count",
                                 info.type, NUM_REQUEST_TYPES);

[falken, 2015/12/17 13:54:32]

Do you have/want UMA to track how frequent the sync event times out? This just
records the raw number of timeouts. For fetch/push we can compare with UMA
FetchEvent.*.Status, PushEvent.Time to see the frequency (kind of convoluted).

[jkarlin, 2015/12/17 15:01:54]

Added BackgroundSyncEvent.Time.

     }
     requests_.pop();
   }
-  if (request_timed_out && running_status() != STOPPING)
+  if (stop_for_timeout && running_status() != STOPPING)
     embedded_worker_->Stop();
 
   // For the timeouts below, there are no callbacks to timeout so there is
   // nothing more to do if the worker is already stopping.
   if (running_status() == STOPPING)
     return;
 
   // The worker has been idle for longer than a certain period.
   if (GetTickDuration(idle_time_) >
       base::TimeDelta::FromSeconds(kIdleWorkerTimeoutSeconds)) {
@@ skipping 86 matching lines @@
     // order to release worker resources soon.
     StopWorkerIfIdle();
   }
 }
 
 template <typename CallbackType>
 int ServiceWorkerVersion::AddRequest(
     const CallbackType& callback,
     IDMap<PendingRequest<CallbackType>, IDMapOwnPointer>* callback_map,
     RequestType request_type) {
-  base::TimeTicks now = base::TimeTicks::Now();
-  int request_id =
-      callback_map->Add(new PendingRequest<CallbackType>(callback, now));
-  requests_.push(RequestInfo(request_id, request_type, now));
+  base::TimeTicks expiration_time =
+      base::TimeTicks::Now() +
+      base::TimeDelta::FromMinutes(kRequestTimeoutMinutes);
+  return AddRequestWithExpiration(callback, callback_map, request_type,
+                                  expiration_time);
+}
+
+template <typename CallbackType>
+int ServiceWorkerVersion::AddRequestWithExpiration(
+    const CallbackType& callback,
+    IDMap<PendingRequest<CallbackType>, IDMapOwnPointer>* callback_map,
+    RequestType request_type,
+    base::TimeTicks expiration) {
+  int request_id = callback_map->Add(
+      new PendingRequest<CallbackType>(callback, base::TimeTicks::Now()));
+  requests_.push(RequestInfo(request_id, request_type, expiration));
   return request_id;
 }
 
 bool ServiceWorkerVersion::MaybeTimeOutRequest(const RequestInfo& info) {
   switch (info.type) {
     case REQUEST_ACTIVATE:
       return RunIDMapCallback(&activate_requests_, info.id,
                               SERVICE_WORKER_ERROR_TIMEOUT);
     case REQUEST_INSTALL:
       return RunIDMapCallback(&install_requests_, info.id,
@@ skipping 20 matching lines @@
                               SERVICE_WORKER_ERROR_TIMEOUT,
                               false /* accept_connection */, base::string16(),
                               base::string16());
     case NUM_REQUEST_TYPES:
       break;
   }
   NOTREACHED() << "Got unexpected request type: " << info.type;
   return false;
 }
 
-void ServiceWorkerVersion::SetAllRequestTimes(const base::TimeTicks& ticks) {
-  std::queue<RequestInfo> new_requests;
+bool ServiceWorkerVersion::ShouldStopIfRequestTimesOut(
+    const RequestInfo& info) {
+  // Note, returning true for a type means that the On*EventFinished should not

[falken, 2015/12/17 13:54:32]

returning false?

[jkarlin, 2015/12/17 15:01:54]

Thanks. Done.

+  // call NOTREACHED if it can't find the matching request, it may have simply
+  // timed out.
+  switch (info.type) {
+    case REQUEST_SYNC:
+      return false;
+    case REQUEST_ACTIVATE:
+    case REQUEST_INSTALL:
+    case REQUEST_FETCH:
+    case REQUEST_NOTIFICATION_CLICK:
+    case REQUEST_PUSH:
+    case REQUEST_GEOFENCING:
+    case REQUEST_SERVICE_PORT_CONNECT:
+    case NUM_REQUEST_TYPES:
+      return true;
+  }
+  NOTREACHED() << "Got unexpected request type: " << info.type;
+  return false;
+}
+
+void ServiceWorkerVersion::SetAllRequestExpirations(
+    const base::TimeTicks& expiration) {
+  RequestInfoPriorityQueue new_requests;
   while (!requests_.empty()) {
-    RequestInfo info = requests_.front();
-    info.time = ticks;
+    RequestInfo info = requests_.top();
+    info.expiration = expiration;
     new_requests.push(info);
     requests_.pop();
   }
   requests_ = new_requests;
 }
 
 ServiceWorkerStatusCode ServiceWorkerVersion::DeduceStartWorkerFailureReason(
     ServiceWorkerStatusCode default_code) {
   if (ping_controller_->IsTimedOut())
     return SERVICE_WORKER_ERROR_TIMEOUT;
@@ skipping 124 matching lines @@
 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