scanner example 10 (C++/Java): Add more detailed PERFormance numbersv2.1.4

Comparing native and java performance numbers:
- similar results

- java seems to be less responsive, esp for CONNECT

- CONNECT performance in general seems to vary a lot
  and brings down overal performance

Native:
==========
dbt10-native-01.log:PERF: adapter-init -> FOUND__-0  292 ms
dbt10-native-01.log:PERF: adapter-init -> CONNECTED-0  2489 ms
dbt10-native-01.log:PERF: GATT primary-services completed
dbt10-native-01.log:PERF:  adapter-init to processing-start 2499 ms,
dbt10-native-01.log:PERF:  get-gatt-services 1117 ms,
dbt10-native-01.log:PERF:  discovered to gatt-complete 1127 ms (connect 10 ms),
dbt10-native-01.log:PERF:  adapter-init to gatt-complete 3616 ms

dbt10-native-02.log:PERF: adapter-init -> FOUND__-0  317 ms
dbt10-native-02.log:PERF: adapter-init -> CONNECTED-0  572 ms
dbt10-native-02.log:PERF: GATT primary-services completed
dbt10-native-02.log:PERF:  adapter-init to processing-start 577 ms,
dbt10-native-02.log:PERF:  get-gatt-services 1108 ms,
dbt10-native-02.log:PERF:  discovered to gatt-complete 1113 ms (connect 5 ms),
dbt10-native-02.log:PERF:  adapter-init to gatt-complete 1685 ms

dbt10-native-03.log:PERF: adapter-init -> CONNECTED-0  1865 ms
dbt10-native-03.log:PERF: GATT primary-services completed
dbt10-native-03.log:PERF:  adapter-init to processing-start 1872 ms,
dbt10-native-03.log:PERF:  get-gatt-services 1502 ms,
dbt10-native-03.log:PERF:  discovered to gatt-complete 1510 ms (connect 8 ms),
dbt10-native-03.log:PERF:  adapter-init to gatt-complete 3374 ms

dbt10-native-04.log:PERF: adapter-init -> FOUND__-0  459 ms
dbt10-native-04.log:PERF: adapter-init -> CONNECTED-0  715 ms
dbt10-native-04.log:PERF: GATT primary-services completed
dbt10-native-04.log:PERF:  adapter-init to processing-start 727 ms,
dbt10-native-04.log:PERF:  get-gatt-services 1108 ms,
dbt10-native-04.log:PERF:  discovered to gatt-complete 1120 ms (connect 12 ms),
dbt10-native-04.log:PERF:  adapter-init to gatt-complete 1835 ms

Java:
==========

dbt10-java-01.log:PERF: adapter-init -> FOUND__-0 1866 ms
dbt10-java-01.log:PERF: adapter-init -> CONNECTED-0 2343 ms
dbt10-java-01.log:PERF: GATT primary-services completed
dbt10-java-01.log:PERF:  adapter-init to processing-start 2352 ms,
dbt10-java-01.log:PERF:  get-gatt-services 1118 ms,
dbt10-java-01.log:PERF:  discovered to gatt-complete 1128 ms (connect 10 ms),
dbt10-java-01.log:PERF:  adapter-init to gatt-complete 3470 ms

dbt10-java-02.log:PERF: adapter-init -> FOUND__-0 1046 ms
dbt10-java-02.log:PERF: adapter-init -> CONNECTED-0 1299 ms
dbt10-java-02.log:PERF: GATT primary-services completed
dbt10-java-02.log:PERF:  adapter-init to processing-start 1310 ms,
dbt10-java-02.log:PERF:  get-gatt-services 1119 ms,
dbt10-java-02.log:PERF:  discovered to gatt-complete 1135 ms (connect 16 ms),
dbt10-java-02.log:PERF:  adapter-init to gatt-complete 2429 ms

dbt10-java-03.log:PERF: adapter-init -> FOUND__-0 1626 ms
dbt10-java-03.log:PERF: adapter-init -> CONNECTED-0 1870 ms
dbt10-java-03.log:PERF: GATT primary-services completed
dbt10-java-03.log:PERF:  adapter-init to processing-start 1883 ms,
dbt10-java-03.log:PERF:  get-gatt-services 1132 ms,
dbt10-java-03.log:PERF:  discovered to gatt-complete 1147 ms (connect 15 ms),
dbt10-java-03.log:PERF:  adapter-init to gatt-complete 3015 ms

dbt10-java-04.log:PERF: adapter-init -> FOUND__-0 189 ms
dbt10-java-04.log:PERF: adapter-init -> CONNECTED-0 441 ms
dbt10-java-04.log:PERF: GATT primary-services completed
dbt10-java-04.log:PERF:  adapter-init to processing-start 454 ms,
dbt10-java-04.log:PERF:  get-gatt-services 1131 ms,
dbt10-java-04.log:PERF:  discovered to gatt-complete 1145 ms (connect 14 ms),
dbt10-java-04.log:PERF:  adapter-init to gatt-complete 1585 ms

2 files changed, 31 insertions, 11 deletions

diff --git a/examples/direct_bt_scanner10/dbt_scanner10.cpp b/examples/direct_bt_scanner10/dbt_scanner10.cpp
index 9f6fd235..049662b1 100644
--- a/examples/direct_bt_scanner10/dbt_scanner10.cpp
+++ b/examples/direct_bt_scanner10/dbt_scanner10.cpp
@@ -128,6 +128,10 @@ class MyAdapterStatusListener : public AdapterStatusListener {
             ) )
         {
             fprintf(stderr, "****** FOUND__-0: Connecting %s\n", device->toString(true).c_str());
+            {
+                const uint64_t td = getCurrentMilliseconds() - timestamp_t0; // adapter-init -> now
+                fprintf(stderr, "PERF: adapter-init -> FOUND__-0  %" PRIu64 " ms\n", td);
+            }
             std::thread dc(::connectDiscoveredDevice, device);
             dc.detach();
         } else {
@@ -151,6 +155,10 @@ class MyAdapterStatusListener : public AdapterStatusListener {
             ) )
         {
             fprintf(stderr, "****** CONNECTED-0: Processing %s\n", device->toString(true).c_str());
+            {
+                const uint64_t td = getCurrentMilliseconds() - timestamp_t0; // adapter-init -> now
+                fprintf(stderr, "PERF: adapter-init -> CONNECTED-0  %" PRIu64 " ms\n", td);
+            }
             addToDevicesProcessing(device->getAddress());
             std::thread dc(::processConnectedDevice, device);
             dc.detach();
@@ -240,15 +248,17 @@ static void processConnectedDevice(std::shared_ptr<DBTDevice> device) {
 
         const uint64_t t5 = getCurrentMilliseconds();
         {
-            const uint64_t td15 = t5 - t1; // connected -> gatt-complete
+            const uint64_t td01 = t1 - timestamp_t0; // adapter-init -> processing-start
+            const uint64_t td15 = t5 - t1; // get-gatt-services
             const uint64_t tdc5 = t5 - device->getLastDiscoveryTimestamp(); // discovered to gatt-complete
             const uint64_t td05 = t5 - timestamp_t0; // adapter-init -> gatt-complete
             fprintf(stderr, "\n\n\n");
-            fprintf(stderr, "GATT primary-services completed\n");
-            fprintf(stderr, "  connected to gatt-complete %" PRIu64 " ms,\n"
-                            "  discovered to gatt-complete %" PRIu64 " ms (connect %" PRIu64 " ms),\n"
-                            "  adapter-init to gatt-complete %" PRIu64 " ms\n\n",
-                            td15, tdc5, (tdc5 - td15), td05);
+            fprintf(stderr, "PERF: GATT primary-services completed\n");
+            fprintf(stderr, "PERF:  adapter-init to processing-start %" PRIu64 " ms,\n"
+                            "PERF:  get-gatt-services %" PRIu64 " ms,\n"
+                            "PERF:  discovered to gatt-complete %" PRIu64 " ms (connect %" PRIu64 " ms),\n"
+                            "PERF:  adapter-init to gatt-complete %" PRIu64 " ms\n\n",
+                            td01, td15, tdc5, (tdc5 - td15), td05);
         }
         std::shared_ptr<GenericAccess> ga = device->getGATTGenericAccess();
         if( nullptr != ga ) {
diff --git a/examples/java/ScannerTinyB10.java b/examples/java/ScannerTinyB10.java
index b11dc2fe..35bac862 100644
--- a/examples/java/ScannerTinyB10.java
+++ b/examples/java/ScannerTinyB10.java
@@ -101,6 +101,10 @@ public class ScannerTinyB10 {
                 ) )
             {
                 System.err.println("****** FOUND__-0: Connecting "+device.toString());
+                {
+                    final long td = BluetoothUtils.getCurrentMilliseconds() - timestamp_t0; // adapter-init -> now
+                    System.err.println("PERF: adapter-init -> FOUND__-0 " + td + " ms");
+                }
                 final Thread deviceConnectTask = new Thread( new Runnable() {
                     @Override
                     public void run() {
@@ -129,6 +133,10 @@ public class ScannerTinyB10 {
                 ) )
             {
                 System.err.println("****** CONNECTED-0: Processing "+device.toString());
+                {
+                    final long td = BluetoothUtils.getCurrentMilliseconds() - timestamp_t0; // adapter-init -> now
+                    System.err.println("PERF: adapter-init -> CONNECTED-0 " + td + " ms");
+                }
                 final Thread deviceProcessingTask = new Thread( new Runnable() {
                     @Override
                     public void run() {
@@ -197,14 +205,16 @@ public class ScannerTinyB10 {
             }
             final long t5 = BluetoothUtils.getCurrentMilliseconds();
             {
-                final long td15 = t5 - t1; // connected -> gatt-complete
+                final long td01 = t1 - timestamp_t0; // adapter-init -> processing-start
+                final long td15 = t5 - t1; // get-gatt-services
                 final long tdc5 = t5 - device.getLastDiscoveryTimestamp(); // discovered to gatt-complete
                 final long td05 = t5 - timestamp_t0; // adapter-init -> gatt-complete
                 System.err.println(System.lineSeparator()+System.lineSeparator());
-                System.err.println("GATT primary-services completed\n");
-                System.err.println("  connected to gatt-complete " + td15 + " ms,"+System.lineSeparator()+
-                                   "  discovered to gatt-complete " + tdc5 + " ms (connect " + (tdc5 - td15) + " ms),"+System.lineSeparator()+
-                                   "  adapter-init to gatt-complete " + td05 + " ms"+System.lineSeparator());
+                System.err.println("PERF: GATT primary-services completed\n");
+                System.err.println("PERF:  adapter-init to processing-start " + td01 + " ms,"+System.lineSeparator()+
+                                   "PERF:  get-gatt-services " + td15 + " ms,"+System.lineSeparator()+
+                                   "PERF:  discovered to gatt-complete " + tdc5 + " ms (connect " + (tdc5 - td15) + " ms),"+System.lineSeparator()+
+                                   "PERF:  adapter-init to gatt-complete " + td05 + " ms"+System.lineSeparator());
             }
             final boolean addedCharacteristicListenerRes =
               BluetoothGattService.addCharacteristicListenerToAll(device, primServices, myCharacteristicListener);