From: Ajay Panicker Date: Fri, 15 Jan 2016 01:59:10 +0000 (-0800) Subject: Add extra logging for BLE scans X-Git-Tag: android-7.1.2_r17~195^2~1^2~4^2 X-Git-Url: http://git.osdn.net/view?a=commitdiff_plain;h=9fa95f7c39df16aa059391a637b4469f97e7d987;p=android-x86%2Fpackages-apps-Bluetooth.git Add extra logging for BLE scans Added logging for application name, number of scans, and scan times for each application that uses gatt scanning. Example output: GATT Client Map Entries: 1 Application Name: com.broadcom.app.leexplorer (Registered) LE scans (started/stopped) : 4 / 4 Scan time in ms (min/max/avg) : 6 / 7321 / 2744 Time since last scan ended in ms : 3522 Last 4 scans in ms (oldest first): 763 6 7321 2887 Application ID : 5 UUID : f69badb3-212b-40b5-b5b3-3bf9214310f9 Connections: 1 5: 6B:1F:6C:45:3D:DC Bug: 26463429 Change-Id: I52376541a5b5874d0e40978990149a1283fd9c6a --- diff --git a/src/com/android/bluetooth/gatt/ContextMap.java b/src/com/android/bluetooth/gatt/ContextMap.java index f492237b..7bb5bc37 100644 --- a/src/com/android/bluetooth/gatt/ContextMap.java +++ b/src/com/android/bluetooth/gatt/ContextMap.java @@ -15,6 +15,8 @@ */ package com.android.bluetooth.gatt; +import android.content.Context; +import android.os.Binder; import android.os.IBinder; import android.os.IBinder.DeathRecipient; import android.os.IInterface; @@ -23,6 +25,7 @@ import android.util.Log; import java.util.ArrayList; import java.util.HashSet; import java.util.Iterator; +import java.util.LinkedList; import java.util.List; import java.util.NoSuchElementException; import java.util.Set; @@ -39,6 +42,46 @@ import java.util.Map; private static final String TAG = GattServiceConfig.TAG_PREFIX + "ContextMap"; /** + * ScanStats class helps keep track of information about scans + * on a per application basis. + */ + class ScanStats { + static final int NUM_SCAN_DURATIONS_KEPT = 5; + + int scansStarted = 0; + int scansStopped = 0; + boolean isScanning = false; + boolean isRegistered = false; + long minScanTime = Long.MAX_VALUE; + long maxScanTime = 0; + long totalScanTime = 0; + List lastScans = new ArrayList(NUM_SCAN_DURATIONS_KEPT + 1); + long startTime = 0; + long stopTime = 0; + + void startScan() { + this.scansStarted++; + isScanning = true; + startTime = System.currentTimeMillis(); + } + + void stopScan() { + this.scansStopped++; + isScanning = false; + stopTime = System.currentTimeMillis(); + long currTime = stopTime - startTime; + + minScanTime = Math.min(currTime, minScanTime); + maxScanTime = Math.max(currTime, maxScanTime); + totalScanTime += currTime; + lastScans.add(currTime); + if (lastScans.size() > NUM_SCAN_DURATIONS_KEPT) { + lastScans.remove(0); + } + } + } + + /** * Connection class helps map connection IDs to device addresses. */ class Connection { @@ -63,6 +106,9 @@ import java.util.Map; /** The id of the application */ int id; + /** The package name of the application */ + String name; + /** Application callbacks */ T callback; @@ -78,9 +124,10 @@ import java.util.Map; /** * Creates a new app context. */ - App(UUID uuid, T callback) { + App(UUID uuid, T callback, String name) { this.uuid = uuid; this.callback = callback; + this.name = name; } /** @@ -123,15 +170,30 @@ import java.util.Map; /** Our internal application list */ List mApps = new ArrayList(); + /** Internal map to keep track of logging information by app name */ + HashMap mScanStats = new HashMap(); + /** Internal list of connected devices **/ Set mConnections = new HashSet(); /** * Add an entry to the application context list. */ - void add(UUID uuid, T callback) { + void add(UUID uuid, T callback, Context context) { + String appName = context.getPackageManager().getNameForUid( + Binder.getCallingUid()); + if (appName == null) { + // Assign an app name if one isn't found + appName = "Unknown App (UID: " + Binder.getCallingUid() + ")"; + } synchronized (mApps) { - mApps.add(new App(uuid, callback)); + mApps.add(new App(uuid, callback, appName)); + ScanStats scanStats = mScanStats.get(appName); + if (scanStats == null) { + scanStats = new ScanStats(); + mScanStats.put(appName, scanStats); + } + scanStats.isRegistered = true; } } @@ -141,10 +203,11 @@ import java.util.Map; void remove(UUID uuid) { synchronized (mApps) { Iterator i = mApps.iterator(); - while(i.hasNext()) { + while (i.hasNext()) { App entry = i.next(); if (entry.uuid.equals(uuid)) { entry.unlinkToDeath(); + mScanStats.get(entry.name).isRegistered = false; i.remove(); break; } @@ -158,10 +221,11 @@ import java.util.Map; void remove(int id) { synchronized (mApps) { Iterator i = mApps.iterator(); - while(i.hasNext()) { + while (i.hasNext()) { App entry = i.next(); if (entry.id == id) { entry.unlinkToDeath(); + mScanStats.get(entry.name).isRegistered = false; i.remove(); break; } @@ -187,7 +251,7 @@ import java.util.Map; void removeConnection(int id, int connId) { synchronized (mConnections) { Iterator i = mConnections.iterator(); - while(i.hasNext()) { + while (i.hasNext()) { Connection connection = i.next(); if (connection.connId == connId) { i.remove(); @@ -202,7 +266,7 @@ import java.util.Map; */ App getById(int id) { Iterator i = mApps.iterator(); - while(i.hasNext()) { + while (i.hasNext()) { App entry = i.next(); if (entry.id == id) return entry; } @@ -215,7 +279,7 @@ import java.util.Map; */ App getByUuid(UUID uuid) { Iterator i = mApps.iterator(); - while(i.hasNext()) { + while (i.hasNext()) { App entry = i.next(); if (entry.uuid.equals(uuid)) return entry; } @@ -224,12 +288,36 @@ import java.util.Map; } /** + * Get an application context by the calling Apps name. + */ + App getByName(String name) { + Iterator i = mApps.iterator(); + while (i.hasNext()) { + App entry = i.next(); + if (entry.name.equals(name)) return entry; + } + Log.e(TAG, "Context not found for name " + name); + return null; + } + + /** + * Get Logging info by ID + */ + ScanStats getScanStatsById(int id) { + App temp = getById(id); + if (temp != null) { + return mScanStats.get(temp.name); + } + return null; + } + + /** * Get the device addresses for all connected devices */ Set getConnectedDevices() { Set addresses = new HashSet(); Iterator i = mConnections.iterator(); - while(i.hasNext()) { + while (i.hasNext()) { Connection connection = i.next(); addresses.add(connection.address); } @@ -241,7 +329,7 @@ import java.util.Map; */ App getByConnId(int connId) { Iterator ii = mConnections.iterator(); - while(ii.hasNext()) { + while (ii.hasNext()) { Connection connection = ii.next(); if (connection.connId == connId){ return getById(connection.appId); @@ -258,7 +346,7 @@ import java.util.Map; if (entry == null) return null; Iterator i = mConnections.iterator(); - while(i.hasNext()) { + while (i.hasNext()) { Connection connection = i.next(); if (connection.address.equals(address) && connection.appId == id) return connection.connId; @@ -271,7 +359,7 @@ import java.util.Map; */ String addressByConnId(int connId) { Iterator i = mConnections.iterator(); - while(i.hasNext()) { + while (i.hasNext()) { Connection connection = i.next(); if (connection.connId == connId) return connection.address; } @@ -281,7 +369,7 @@ import java.util.Map; List getConnectionByApp(int appId) { List currentConnections = new ArrayList(); Iterator i = mConnections.iterator(); - while(i.hasNext()) { + while (i.hasNext()) { Connection connection = i.next(); if (connection.appId == appId) currentConnections.add(connection); @@ -295,7 +383,7 @@ import java.util.Map; void clear() { synchronized (mApps) { Iterator i = mApps.iterator(); - while(i.hasNext()) { + while (i.hasNext()) { App entry = i.next(); entry.unlinkToDeath(); i.remove(); @@ -322,22 +410,86 @@ import java.util.Map; * Logs debug information. */ void dump(StringBuilder sb) { - sb.append(" Entries: " + mApps.size() + "\n"); + long currTime = System.currentTimeMillis(); - Iterator i = mApps.iterator(); - while(i.hasNext()) { - App entry = i.next(); - List connections = getConnectionByApp(entry.id); + sb.append(" Entries: " + mScanStats.size() + "\n\n"); + + Iterator> i = mScanStats.entrySet().iterator(); + while (i.hasNext()) { + Map.Entry entry = i.next(); - sb.append("\n Application Id: " + entry.id + "\n"); - sb.append(" UUID: " + entry.uuid + "\n"); - sb.append(" Connections: " + connections.size() + "\n"); + String name = entry.getKey(); + ScanStats scanStats = entry.getValue(); - Iterator ii = connections.iterator(); - while(ii.hasNext()) { - Connection connection = ii.next(); - sb.append(" " + connection.connId + ": " + connection.address + "\n"); + long maxScanTime = scanStats.maxScanTime; + long minScanTime = scanStats.minScanTime; + long currScanTime = 0; + + if (scanStats.isScanning) { + currScanTime = currTime - scanStats.startTime; + minScanTime = Math.min(currScanTime, minScanTime); + maxScanTime = Math.max(currScanTime, maxScanTime); + } + + if (minScanTime == Long.MAX_VALUE) { + minScanTime = 0; + } + + long lastScan = 0; + if (scanStats.stopTime != 0) { + lastScan = currTime - scanStats.stopTime; + } + + long avgScanTime = 0; + if (scanStats.scansStarted > 0) { + avgScanTime = (scanStats.totalScanTime + currScanTime) / + scanStats.scansStarted; + } + + sb.append(" Application Name: " + name); + if (scanStats.isRegistered) sb.append(" (Registered)"); + sb.append("\n"); + + sb.append(" LE scans (started/stopped) : " + + scanStats.scansStarted + " / " + + scanStats.scansStopped + "\n"); + sb.append(" Scan time in ms (min/max/avg) : " + + minScanTime + " / " + + maxScanTime + " / " + + avgScanTime + "\n"); + + sb.append(" Time since last scan ended in ms : " + lastScan + "\n"); + + sb.append(" Last " + scanStats.lastScans.size() + + " scans in ms (oldest first): "); + for (Long time : scanStats.lastScans) { + sb.append(time + " "); + } + sb.append("\n"); + + if (scanStats.isRegistered) { + App appEntry = getByName(name); + sb.append(" Application ID : " + + appEntry.id + "\n"); + sb.append(" UUID : " + + appEntry.uuid + "\n"); + + if (scanStats.isScanning) { + sb.append(" Current scan duration : " + + currScanTime + "\n"); + } + + List connections = getConnectionByApp(appEntry.id); + sb.append(" Connections: " + connections.size() + "\n"); + + Iterator ii = connections.iterator(); + while(ii.hasNext()) { + Connection connection = ii.next(); + sb.append(" " + connection.connId + ": " + + connection.address + "\n"); + } } + sb.append("\n"); } } } diff --git a/src/com/android/bluetooth/gatt/GattService.java b/src/com/android/bluetooth/gatt/GattService.java index 29159354..36acae56 100644 --- a/src/com/android/bluetooth/gatt/GattService.java +++ b/src/com/android/bluetooth/gatt/GattService.java @@ -1389,6 +1389,7 @@ public class GattService extends ProfileService { scanClient.hasPeersMacAddressPermission = Utils.checkCallerHasPeersMacAddressPermission( this); scanClient.legacyForegroundApp = Utils.isLegacyForegroundApp(this, callingPackage); + mClientMap.getScanStatsById(appIf).startScan(); mScanManager.startScan(scanClient); } @@ -1403,6 +1404,7 @@ public class GattService extends ProfileService { int scanQueueSize = mScanManager.getBatchScanQueue().size() + mScanManager.getRegularScanQueue().size(); if (DBG) Log.d(TAG, "stopScan() - queue size =" + scanQueueSize); + mClientMap.getScanStatsById(client.clientIf).stopScan(); mScanManager.stopScan(client); } @@ -1431,7 +1433,7 @@ public class GattService extends ProfileService { enforceCallingOrSelfPermission(BLUETOOTH_PERM, "Need BLUETOOTH permission"); if (DBG) Log.d(TAG, "registerClient() - UUID=" + uuid); - mClientMap.add(uuid, callback); + mClientMap.add(uuid, callback, this); gattClientRegisterAppNative(uuid.getLeastSignificantBits(), uuid.getMostSignificantBits()); } @@ -1969,7 +1971,7 @@ public class GattService extends ProfileService { enforceCallingOrSelfPermission(BLUETOOTH_PERM, "Need BLUETOOTH permission"); if (DBG) Log.d(TAG, "registerServer() - UUID=" + uuid); - mServerMap.add(uuid, callback); + mServerMap.add(uuid, callback, this); gattServerRegisterAppNative(uuid.getLeastSignificantBits(), uuid.getMostSignificantBits()); }