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::TimeDelta max_duration,
     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, max_duration, callback)));
     return;
   }
 
-  int request_id = AddRequest(callback, &sync_requests_, REQUEST_SYNC);
+  int request_id =
+      AddRequestWithExpiration(callback, &sync_requests_, REQUEST_SYNC,
+                               base::TimeTicks::Now() + max_duration);
   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(
+      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;
   }
 
+  UMA_HISTOGRAM_MEDIUM_TIMES("ServiceWorker.BackgroundSyncEvent.Time",
+                             base::TimeTicks::Now() - request->start_time);
+
   scoped_refptr<ServiceWorkerVersion> protect(this);
   request->callback.Run(mojo::ConvertTo<ServiceWorkerStatusCode>(status));
   RemoveCallbackAndStopIfRedundant(&sync_requests_, request_id);
 }
 
 void ServiceWorkerVersion::OnNotificationClickEventFinished(
     int request_id) {
   TRACE_EVENT1("ServiceWorker",
                "ServiceWorkerVersion::OnNotificationClickEventFinished",
                "Request id", request_id);
@@ skipping 662 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);
     }
     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 false for a type means that the On*EventFinished should not
+  // 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:

[falken, 2015/12/18 01:28:47]

nit: NUM_REQUEST_TYPES being passed is a bug, should hit the NOTREACHED()
instead

[jkarlin, 2015/12/18 12:28:30]

Done.

+      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