[Background Sync] Gather UMA data for Background Sync

content/browser/background_sync/background_sync_manager.cc

 // Copyright 2015 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/background_sync/background_sync_manager.h"
 
 #include "base/barrier_closure.h"
 #include "base/bind.h"
 #include "base/location.h"
 #include "base/single_thread_task_runner.h"
 #include "base/thread_task_runner_handle.h"
+#include "content/browser/background_sync/background_sync_metrics.h"
 #include "content/browser/background_sync/background_sync_network_observer.h"
 #include "content/browser/background_sync/background_sync_power_observer.h"
 #include "content/browser/background_sync/background_sync_registration_options.h"
 #include "content/browser/service_worker/service_worker_context_wrapper.h"
 #include "content/browser/service_worker/service_worker_storage.h"
 #include "content/public/browser/browser_thread.h"
 
 #if defined(OS_ANDROID)
 #include "content/browser/android/background_sync_launcher_android.h"
 #endif
@@ skipping 47 matching lines @@
     : value_(periodicity == SYNC_ONE_SHOT ? "o_" + tag : "p_" + tag) {
 }
 
 void BackgroundSyncManager::Register(
     int64 sw_registration_id,
     const BackgroundSyncRegistrationOptions& options,
     const StatusAndRegistrationCallback& callback) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
   if (disabled_) {
+    BackgroundSyncMetrics::CountRegistration(
+        options.periodicity, false,

[jkarlin, 2015/07/13 16:51:12]

Prefer an enum to a bool.

[iclelland, 2015/07/13 19:34:31]

Yes, generally. I hate to have to define the enum here, though, and import it in
background_sync_metrics.h. But it's worse to define it there, when I'd really
want it to be the return value for WouldFireRegistrationWithOptions.

+        BackgroundSyncMetrics::REGISTRATION_RESULT_FAILED);

[jkarlin, 2015/07/13 16:51:13]

RESULT_DISABLED instead of RESULT_FAILED. 

[iclelland, 2015/07/13 19:34:31]

I'll switch to ERROR_TYPE_STORAGE, to mirror ErrorType, as discussed in a later
comment.

     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE,
         base::Bind(callback, ERROR_TYPE_STORAGE, BackgroundSyncRegistration()));
     return;
   }
 
   op_scheduler_.ScheduleOperation(
       base::Bind(&BackgroundSyncManager::RegisterImpl,
                  weak_ptr_factory_.GetWeakPtr(), sw_registration_id, options,
                  MakeStatusAndRegistrationCompletion(callback)));
 }
 
 void BackgroundSyncManager::Unregister(
     int64 sw_registration_id,
     const std::string& sync_registration_tag,
     SyncPeriodicity periodicity,
     BackgroundSyncRegistration::RegistrationId sync_registration_id,
     const StatusCallback& callback) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
   if (disabled_) {
+    BackgroundSyncMetrics::CountUnregistration(periodicity, false);

[jkarlin, 2015/07/13 16:51:12]

Why a bool? Why not use the same enum as registration? That would tell us more
about what's going on.

[iclelland, 2015/07/13 19:34:31]

They both started as bool, but registration has different possibilities
(duplicate registration, e.g.), so I switched it. I'll switch unregister as
well, if that makes sense.

     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE, base::Bind(callback, ERROR_TYPE_STORAGE));
     return;
   }
 
   RegistrationKey registration_key(sync_registration_tag, periodicity);
 
   op_scheduler_.ScheduleOperation(base::Bind(
       &BackgroundSyncManager::UnregisterImpl, weak_ptr_factory_.GetWeakPtr(),
-      sw_registration_id, registration_key, sync_registration_id,
+      sw_registration_id, registration_key, sync_registration_id, periodicity,
       MakeStatusCompletion(callback)));
 }
 
 void BackgroundSyncManager::GetRegistration(
     int64 sw_registration_id,
     const std::string& sync_registration_tag,
     SyncPeriodicity periodicity,
     const StatusAndRegistrationCallback& callback) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
@@ skipping 165 matching lines @@
                                                 base::Bind(callback));
 }
 
 void BackgroundSyncManager::RegisterImpl(
     int64 sw_registration_id,
     const BackgroundSyncRegistrationOptions& options,
     const StatusAndRegistrationCallback& callback) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
   if (disabled_) {
+    BackgroundSyncMetrics::CountRegistration(
+        options.periodicity, false,
+        BackgroundSyncMetrics::REGISTRATION_RESULT_FAILED);
     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE,
         base::Bind(callback, ERROR_TYPE_STORAGE, BackgroundSyncRegistration()));
     return;
   }
 
+  // For UMA, determine here whether the sync could fire immediately
+  bool registrationCouldFire = WouldFireRegistrationWithOptions(options);

[jkarlin, 2015/07/13 16:51:13]

registration_could_fire

[iclelland, 2015/07/13 19:34:31]

Done.

+
   const BackgroundSyncRegistration* existing_registration =
       LookupRegistration(sw_registration_id, RegistrationKey(options));
   if (existing_registration &&
       existing_registration->options()->Equals(options)) {
+    // Record the duplicated registration
+    BackgroundSyncMetrics::CountRegistration(
+        existing_registration->options()->periodicity, registrationCouldFire,
+        BackgroundSyncMetrics::REGISTRATION_RESULT_DUPLICATE);
+
     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE, base::Bind(callback, ERROR_TYPE_OK, *existing_registration));
     return;
   }
 
   BackgroundSyncRegistration new_registration;
   *new_registration.options() = options;
 
   BackgroundSyncRegistrations* registrations =
       &sw_to_registrations_map_[sw_registration_id];
   new_registration.set_id(registrations->next_id++);
 
   ServiceWorkerRegistration* sw_registration =
       service_worker_context_->GetLiveRegistration(sw_registration_id);
   if (!sw_registration || !sw_registration->active_version()) {
+    BackgroundSyncMetrics::CountRegistration(
+        options.periodicity, registrationCouldFire,
+        BackgroundSyncMetrics::REGISTRATION_RESULT_FAILED);
     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE, base::Bind(callback, ERROR_TYPE_NO_SERVICE_WORKER,
                               BackgroundSyncRegistration()));
     return;
   }
 
   AddRegistrationToMap(sw_registration_id,
                        sw_registration->pattern().GetOrigin(),
                        new_registration);
 
@@ skipping 115 matching lines @@
                      kBackgroundSyncUserDataKey, serialized, callback);
 }
 
 void BackgroundSyncManager::RegisterDidStore(
     int64 sw_registration_id,
     const BackgroundSyncRegistration& new_registration,
     const StatusAndRegistrationCallback& callback,
     ServiceWorkerStatusCode status) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
+  // For UMA, determine here whether the sync could fire immediately
+  bool registrationCouldFire =

[jkarlin, 2015/07/13 16:51:13]

registration_could_fire

[iclelland, 2015/07/13 19:34:31]

Done.

+      WouldFireRegistrationWithOptions(*new_registration.options());
+
   if (status == SERVICE_WORKER_ERROR_NOT_FOUND) {
-    // The registration is gone.
+    // The service worker registration is gone.
+    BackgroundSyncMetrics::CountRegistration(
+        new_registration.options()->periodicity, registrationCouldFire,
+        BackgroundSyncMetrics::REGISTRATION_RESULT_FAILED);
     sw_to_registrations_map_.erase(sw_registration_id);
     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE,
         base::Bind(callback, ERROR_TYPE_STORAGE, BackgroundSyncRegistration()));
     return;
   }
 
   if (status != SERVICE_WORKER_OK) {
     LOG(ERROR) << "BackgroundSync failed to store registration due to backend "
                   "failure.";
+    BackgroundSyncMetrics::CountRegistration(
+        new_registration.options()->periodicity, registrationCouldFire,
+        BackgroundSyncMetrics::REGISTRATION_RESULT_FAILED);
     DisableAndClearManager(
         base::Bind(callback, ERROR_TYPE_STORAGE, BackgroundSyncRegistration()));
     return;
   }
 
+  BackgroundSyncMetrics::CountRegistration(
+      new_registration.options()->periodicity, registrationCouldFire,
+      BackgroundSyncMetrics::REGISTRATION_RESULT_SUCCEEDED);
   FireReadyEvents();
   base::ThreadTaskRunnerHandle::Get()->PostTask(
       FROM_HERE, base::Bind(callback, ERROR_TYPE_OK, new_registration));
 }
 
 void BackgroundSyncManager::RemoveRegistrationFromMap(
     int64 sw_registration_id,
     const RegistrationKey& registration_key) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
   DCHECK(LookupRegistration(sw_registration_id, registration_key));
@@ skipping 46 matching lines @@
     const ServiceWorkerVersion::StatusCallback& callback) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
   active_version->DispatchSyncEvent(callback);
 }
 
 void BackgroundSyncManager::UnregisterImpl(
     int64 sw_registration_id,
     const RegistrationKey& registration_key,
     BackgroundSyncRegistration::RegistrationId sync_registration_id,
+    SyncPeriodicity periodicity,
     const StatusCallback& callback) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
   if (disabled_) {
+    BackgroundSyncMetrics::CountUnregistration(periodicity, false);
     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE, base::Bind(callback, ERROR_TYPE_STORAGE));
     return;
   }
 
   const BackgroundSyncRegistration* existing_registration =
       LookupRegistration(sw_registration_id, registration_key);
   if (!existing_registration ||
       existing_registration->id() != sync_registration_id) {
+    BackgroundSyncMetrics::CountUnregistration(periodicity, false);
     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE, base::Bind(callback, ERROR_TYPE_NOT_FOUND));
     return;
   }
 
   RemoveRegistrationFromMap(sw_registration_id, registration_key);
 
-  StoreRegistrations(
-      sw_registration_id,
-      base::Bind(&BackgroundSyncManager::UnregisterDidStore,
-                 weak_ptr_factory_.GetWeakPtr(), sw_registration_id, callback));
+  StoreRegistrations(sw_registration_id,
+                     base::Bind(&BackgroundSyncManager::UnregisterDidStore,
+                                weak_ptr_factory_.GetWeakPtr(),
+                                sw_registration_id, periodicity, callback));
 }
 
-void BackgroundSyncManager::UnregisterDidStore(
-    int64 sw_registration_id,
-    const StatusCallback& callback,
-    ServiceWorkerStatusCode status) {
+void BackgroundSyncManager::UnregisterDidStore(int64 sw_registration_id,
+                                               SyncPeriodicity periodicity,
+                                               const StatusCallback& callback,
+                                               ServiceWorkerStatusCode status) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
   if (status == SERVICE_WORKER_ERROR_NOT_FOUND) {
     // ServiceWorker was unregistered.
+    BackgroundSyncMetrics::CountUnregistration(periodicity, false);
     sw_to_registrations_map_.erase(sw_registration_id);
     base::ThreadTaskRunnerHandle::Get()->PostTask(
         FROM_HERE, base::Bind(callback, ERROR_TYPE_STORAGE));
     return;
   }
 
   if (status != SERVICE_WORKER_OK) {
     LOG(ERROR) << "BackgroundSync failed to unregister due to backend failure.";
+    BackgroundSyncMetrics::CountUnregistration(periodicity, false);
     DisableAndClearManager(base::Bind(callback, ERROR_TYPE_STORAGE));
     return;
   }
 
+  BackgroundSyncMetrics::CountUnregistration(periodicity, true);
   base::ThreadTaskRunnerHandle::Get()->PostTask(
       FROM_HERE, base::Bind(callback, ERROR_TYPE_OK));
 }
 
 void BackgroundSyncManager::GetRegistrationImpl(
     int64 sw_registration_id,
     const RegistrationKey& registration_key,
     const StatusAndRegistrationCallback& callback) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
@@ skipping 41 matching lines @@
           tag_and_registration.second;
       if (registration.options()->periodicity == periodicity)
         out_registrations.push_back(registration);
     }
   }
 
   base::ThreadTaskRunnerHandle::Get()->PostTask(
       FROM_HERE, base::Bind(callback, ERROR_TYPE_OK, out_registrations));
 }
 
+bool BackgroundSyncManager::WouldFireRegistrationWithOptions(

[jkarlin, 2015/07/13 16:51:12]

Why this function? Why not just call IsRegistrationReadyToFire for the UMA
check?

[iclelland, 2015/07/13 19:34:31]

IsRegistrationReadyToFire takes a Registration object, and I wanted to call this
early in the Register() method, when all we have is an options object. That way,
even if we bail early, we can still report whether the registration *could* have
fired, as far as the developer was concerned.
I thought it made sense to factor out the "are these options satisfied right
now" check, and leave the sync-lifecycle (PENDING vs FIRING, etc) checks to the
method that is actually checking registered syncs.

[jkarlin, 2015/07/14 15:54:10]

Okay. Can you rename to AreOptionConditionsMet?

[iclelland, 2015/07/15 14:22:25]

Done.

+    const BackgroundSyncRegistrationOptions& options) {
+  DCHECK_CURRENTLY_ON(BrowserThread::IO);
+  return network_observer_->NetworkSufficient(options.network_state) &&
+         power_observer_->PowerSufficient(options.power_state);
+}
+
 bool BackgroundSyncManager::IsRegistrationReadyToFire(
     const BackgroundSyncRegistration& registration) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
   // TODO(jkarlin): Add support for firing periodic registrations.
   if (registration.options()->periodicity == SYNC_PERIODIC)
     return false;
 
   if (registration.sync_state() != SYNC_STATE_PENDING)
     return false;
 
   DCHECK_EQ(SYNC_ONE_SHOT, registration.options()->periodicity);
 
-  return network_observer_->NetworkSufficient(
-             registration.options()->network_state) &&
-         power_observer_->PowerSufficient(registration.options()->power_state);
+  return WouldFireRegistrationWithOptions(*registration.options());
 }
 
 void BackgroundSyncManager::SchedulePendingRegistrations() {
 #if defined(OS_ANDROID)
   bool keep_browser_alive_for_one_shot = false;
 
   for (const auto& sw_id_and_registrations : sw_to_registrations_map_) {
     for (const auto& key_and_registration :
          sw_id_and_registrations.second.registration_map) {
       const BackgroundSyncRegistration& registration =
@@ skipping 52 matching lines @@
         sw_id_and_keys_to_fire.push_back(
             std::make_pair(service_worker_id, key_and_registration.first));
         // The state change is not saved to persistent storage because
         // if the sync event is killed mid-sync then it should return to
         // SYNC_STATE_PENDING.
         registration->set_sync_state(SYNC_STATE_FIRING);
       }
     }
   }
 
+  base::TimeTicks start_time = base::TimeTicks::Now();
+
   // Fire the sync event of the ready registrations and run |callback| once
   // they're all done.
-  base::Closure barrier_closure =
-      base::BarrierClosure(sw_id_and_keys_to_fire.size(), base::Bind(callback));
+  base::Closure barrier_closure = base::BarrierClosure(
+      sw_id_and_keys_to_fire.size(),
+      base::Bind(&OnAllSyncEventsCompleted, start_time, callback));

[jkarlin, 2015/07/13 16:51:13]

OnAllSyncEventsCompleted doesn't get called when you think it does. This barrier
is complete once all of the service worker versions have called DispatchSync. It
doesn't wait for them to complete.

[iclelland, 2015/07/15 14:22:24]

Thanks for catching that -- I've added a second barrier now, so one is called
when all events have fired, and the other when all events have completed. That
second one now calls OnAllSyncEventsCompleted, as intended.

 
   for (const auto& sw_id_and_key : sw_id_and_keys_to_fire) {
     int64 service_worker_id = sw_id_and_key.first;
     const BackgroundSyncRegistration* registration =
         LookupRegistration(service_worker_id, sw_id_and_key.second);
 
     service_worker_context_->FindRegistrationForId(
         service_worker_id, sw_to_registrations_map_[service_worker_id].origin,
         base::Bind(&BackgroundSyncManager::FireReadyEventsDidFindRegistration,
                    weak_ptr_factory_.GetWeakPtr(), sw_id_and_key.second,
@@ skipping 13 matching lines @@
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
   if (service_worker_status != SERVICE_WORKER_OK) {
     base::ThreadTaskRunnerHandle::Get()->PostTask(FROM_HERE,
                                                   base::Bind(callback));
     return;
   }
 
   FireOneShotSync(
       service_worker_registration->active_version(),
       base::Bind(&BackgroundSyncManager::EventComplete,

[jkarlin, 2015/07/13 16:51:12]

To record the time of all of the syncs, you'll want to create a barrier in this
function and pass it to EventComplete and then to EventCompleteImpl to run.

[iclelland, 2015/07/13 19:34:31]

Thanks -- You were right, above, about being mistaken about when the first
barrier would fire. I'll move it here, and gather stats at that point.

                  weak_ptr_factory_.GetWeakPtr(), service_worker_registration,
                  service_worker_registration->id(), registration_key,
                  registration_id));
 
   base::ThreadTaskRunnerHandle::Get()->PostTask(FROM_HERE,
                                                 base::Bind(callback));
 }
 
 // |service_worker_registration| is just to keep the registration alive
 // while the event is firing.
@@ skipping 29 matching lines @@
   }
 
   BackgroundSyncRegistration* registration =
       LookupRegistration(service_worker_id, key);
   if (!registration || registration->id() != sync_registration_id) {
     base::ThreadTaskRunnerHandle::Get()->PostTask(FROM_HERE,
                                                   base::Bind(callback));
     return;
   }
 
+  // The event ran to completion, we should count it, no matter what happens
+  // from here.
+  BackgroundSyncMetrics::RecordEventResult(registration->options()->periodicity,
+                                           status_code == SERVICE_WORKER_OK);
+
   if (registration->options()->periodicity == SYNC_ONE_SHOT) {
     if (status_code != SERVICE_WORKER_OK) {
       // TODO(jkarlin) Fire the sync event on the next page load controlled by
       // this registration. (crbug.com/479665)
       registration->set_sync_state(SYNC_STATE_FAILED);
     } else {
       registration = nullptr;
       RemoveRegistrationFromMap(service_worker_id, key);
     }
   } else {
@@ skipping 25 matching lines @@
     LOG(ERROR) << "BackgroundSync failed to store registration due to backend "
                   "failure.";
     DisableAndClearManager(base::Bind(callback));
     return;
   }
 
   base::ThreadTaskRunnerHandle::Get()->PostTask(FROM_HERE,
                                                 base::Bind(callback));
 }
 
+// static
+void BackgroundSyncManager::OnAllSyncEventsCompleted(
+    const base::TimeTicks& start_time,
+    const base::Closure& callback) {
+  // Record the combined time taken by all sync events and run |callback|.
+  BackgroundSyncMetrics::RecordSyncEventHandlingTime(base::TimeTicks::Now() -
+                                                     start_time);
+  callback.Run();
+}
+
 void BackgroundSyncManager::OnRegistrationDeletedImpl(
     int64 registration_id,
     const base::Closure& callback) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
   // The backend (ServiceWorkerStorage) will delete the data, so just delete the
   // memory representation here.
   sw_to_registrations_map_.erase(registration_id);
   base::ThreadTaskRunnerHandle::Get()->PostTask(FROM_HERE,
                                                 base::Bind(callback));
@@ skipping 62 matching lines @@
 BackgroundSyncManager::MakeStatusCompletion(const StatusCallback& callback) {
   DCHECK_CURRENTLY_ON(BrowserThread::IO);
 
   return base::Bind(
       &BackgroundSyncManager::CompleteOperationCallback<StatusCallback,
                                                         ErrorType>,
       weak_ptr_factory_.GetWeakPtr(), callback);
 }
 
 }  // namespace content