bluetooth: Add histograms and logging for getPrimaryService()

content/browser/bluetooth/bluetooth_dispatcher_host.cc

 // Copyright 2014 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.
 
 // NETWORK_ERROR Note:
 // When a device can't be found in the BluetoothAdapter, that generally
 // indicates that it's gone out of range. We reject with a NetworkError in that
 // case.
 // https://webbluetoothchrome.github.io/web-bluetooth/#dom-bluetoothdevice-connectgatt
 
@@ skipping 93 matching lines @@
   std::set<BluetoothUUID> union_of_services(optional_services.begin(),
                                             optional_services.end());
 
   for (const content::BluetoothScanFilter& filter : filters)
     union_of_services.insert(filter.services.begin(), filter.services.end());
 
   UMA_HISTOGRAM_COUNTS_100("Bluetooth.Web.RequestDevice.UnionOfServices.Count",
                            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,
   UNKNOWN,
   IN_PROGRESS,
   FAILED,
   AUTH_FAILED,
   AUTH_CANCELED,
   AUTH_REJECTED,
   AUTH_TIMEOUT,
@@ skipping 344 matching lines @@
                  device_instance_id, start_time));
 }
 
 void BluetoothDispatcherHost::OnGetPrimaryService(
     int thread_id,
     int request_id,
     const std::string& device_instance_id,
     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
   // TODO(ortuno): Check if service_uuid is in "allowed services"
   // https://crbug.com/493460
   // For now just wait a fixed time and call OnServiceDiscovered.
   // TODO(ortuno): Use callback once it's implemented http://crbug.com/484504
   BrowserThread::PostDelayedTask(
       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_));
 }
 
 void BluetoothDispatcherHost::OnGetCharacteristic(
     int thread_id,
     int request_id,
     const std::string& service_instance_id,
     const std::string& characteristic_uuid) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
   RecordWebBluetoothFunctionCall(UMAWebBluetoothFunction::GET_CHARACTERISTIC);
@@ skipping 286 matching lines @@
   RecordConnectGATTTimeFailed(base::TimeTicks::Now() - start_time);
   // RecordConnectGATTOutcome is called by TranslateConnectError.
   Send(new BluetoothMsg_ConnectGATTError(thread_id, request_id,
                                          TranslateConnectError(error_code)));
 }
 
 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;
   }
   for (BluetoothGattService* service : device->GetGattServices()) {
     if (service->GetUUID().canonical_value() == service_uuid) {
       // TODO(ortuno): Use generated instance ID instead.
       // https://crbug.com/495379
       const std::string& service_identifier = service->GetIdentifier();
       auto insert_result = service_to_device_.insert(
           make_pair(service_identifier, device_instance_id));
 
       // If a value is already in map, DCHECK it's valid.
       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));
 }
 
 void BluetoothDispatcherHost::OnCharacteristicValueRead(
     int thread_id,
     int request_id,
     const std::vector<uint8>& value) {
   Send(new BluetoothMsg_ReadCharacteristicValueSuccess(thread_id, request_id,
                                                        value));
@@ skipping 14 matching lines @@
 
 void BluetoothDispatcherHost::OnWriteValueFailed(
     int thread_id,
     int request_id,
     device::BluetoothGattService::GattErrorCode error_code) {
   Send(new BluetoothMsg_WriteCharacteristicValueError(
       thread_id, request_id, TranslateGATTError(error_code)));
 }
 
 }  // namespace content