bluetooth: Add histograms and logging for getPrimaryService()

content/browser/bluetooth/bluetooth_dispatcher_host.cc

Index: content/browser/bluetooth/bluetooth_dispatcher_host.cc
diff --git a/content/browser/bluetooth/bluetooth_dispatcher_host.cc b/content/browser/bluetooth/bluetooth_dispatcher_host.cc
index fc3c4665ec2fbe2150dd1e5aa1db14eb204fe0f8..a9c1264e186ac43922d3cf16212ccc0a86a3247f 100644
--- a/content/browser/bluetooth/bluetooth_dispatcher_host.cc
+++ b/content/browser/bluetooth/bluetooth_dispatcher_host.cc
@@ -111,6 +111,31 @@ void RecordUnionOfServices(
                            union_of_services.size());
 }
 
+enum class UMAGetPrimaryServiceOutcome {
+  SUCCESS,
+  NO_DEVICE,
+  NOT_FOUND,
+  // Note: Add new GetPrimaryService outcomes immediately above this line. Make
+  // sure to update the enum list in tools/metrics/histograms/histograms.xml
+  // accordingly.
+  COUNT
+};
+
+void RecordGetPrimaryServiceService(const BluetoothUUID& service) {
+  UMA_HISTOGRAM_SPARSE_SLOWLY("Bluetooth.Web.GetPrimaryService.Services",
+                              HashUUID(service));
+}
+
+void RecordGetPrimaryServiceOutcome(UMAGetPrimaryServiceOutcome outcome) {
+  UMA_HISTOGRAM_ENUMERATION(
+      "Bluetooth.Web.GetPrimaryService.Outcome", static_cast<int>(outcome),
+      static_cast<int>(UMAGetPrimaryServiceOutcome::COUNT));
+}
+
+void RecordGetPrimaryServiceTime(const base::TimeDelta& duration) {
+  UMA_HISTOGRAM_MEDIUM_TIMES("Bluetooth.Web.GetPrimaryService.Time", duration);

[Jeffrey Yasskin, 2015/08/12 17:00:04]

This is more the ServiceDiscoveryTime or the GetPrimaryService.DiscoveryTime
than the GetPrimaryService.Time, since it doesn't include any of the other work
in GetPrimaryService.

We should probably also avoid recording times when services are already
discovered.

[ortuno, 2015/08/12 18:18:05]

Histogram removed.

+}
+
 enum class UMAConnectGATTOutcome {
   SUCCESS,
   NO_DEVICE,
@@ -475,6 +500,8 @@ void BluetoothDispatcherHost::OnGetPrimaryService(
     const std::string& service_uuid) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
   RecordWebBluetoothFunctionCall(UMAWebBluetoothFunction::GET_PRIMARY_SERVICE);
+  RecordGetPrimaryServiceService(BluetoothUUID(service_uuid));
+  base::TimeTicks start_time = base::TimeTicks::Now();
 
   // TODO(ortuno): Check if device_instance_id is in "allowed devices"
   // https://crbug.com/493459
@@ -486,7 +513,7 @@ void BluetoothDispatcherHost::OnGetPrimaryService(
       BrowserThread::UI, FROM_HERE,
       base::Bind(&BluetoothDispatcherHost::OnServicesDiscovered,
                  weak_ptr_factory_.GetWeakPtr(), thread_id, request_id,
-                 device_instance_id, service_uuid),
+                 device_instance_id, service_uuid, start_time),

[Jeffrey Yasskin, 2015/08/12 17:00:04]

Right now, this isn't a useful time to record since it'll always be close to
current_delay_time_. I'm not sure of this, but maybe we should wait to record
the timing information until we're actually getting notified when discovery
finishes. That'll also make sure we measure the relevant things at that point.

[ortuno, 2015/08/12 18:18:05]

Histogram removed.

       base::TimeDelta::FromSeconds(current_delay_time_));
 }
 
@@ -793,11 +820,15 @@ void BluetoothDispatcherHost::OnServicesDiscovered(
     int thread_id,
     int request_id,
     const std::string& device_instance_id,
-    const std::string& service_uuid) {
+    const std::string& service_uuid,
+    base::TimeTicks start_time) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
+  RecordGetPrimaryServiceTime(base::TimeTicks::Now() - start_time);
 
   device::BluetoothDevice* device = adapter_->GetDevice(device_instance_id);
   if (device == nullptr) {  // See "NETWORK_ERROR Note" above.
+    RecordGetPrimaryServiceOutcome(UMAGetPrimaryServiceOutcome::NO_DEVICE);
+    VLOG(1) << "Bluetooth Device is no longer in range.";
     Send(new BluetoothMsg_GetPrimaryServiceError(
         thread_id, request_id, WebBluetoothError::DeviceNoLongerInRange));
     return;
@@ -814,11 +845,14 @@ void BluetoothDispatcherHost::OnServicesDiscovered(
       if (!insert_result.second)
         DCHECK(insert_result.first->second == device_instance_id);
 
+      RecordGetPrimaryServiceOutcome(UMAGetPrimaryServiceOutcome::SUCCESS);
       Send(new BluetoothMsg_GetPrimaryServiceSuccess(thread_id, request_id,
                                                      service_identifier));
       return;
     }
   }
+  RecordGetPrimaryServiceOutcome(UMAGetPrimaryServiceOutcome::NOT_FOUND);
+  VLOG(1) << "No GATT services with UUID: " << service_uuid;
   Send(new BluetoothMsg_GetPrimaryServiceError(
       thread_id, request_id, WebBluetoothError::ServiceNotFound));
 }