Bug 42048 - Bluetooth LE OnCharacteristicChanged high CPU usage, constant GC triggering
Summary: Bluetooth LE OnCharacteristicChanged high CPU usage, constant GC triggering
Status: RESOLVED ANSWERED
Alias: None
Product: Android
Classification: Xamarin
Component: General (show other bugs)
Version: 6.0.1 (C6SR1)
Hardware: PC Windows
: --- normal
Target Milestone: ---
Assignee: Jonathan Pryor
URL:
Depends on:
Blocks:
 
Reported: 2016-06-21 20:03 UTC by John Chiodini
Modified: 2017-10-04 15:18 UTC (History)
2 users (show)

See Also:
Tags: BLE threadpool
Is this bug a regression?: ---
Last known good build:


Attachments
DDMS CPU usage (49.25 KB, image/png)
2016-06-21 20:03 UTC, John Chiodini
Details
Trace of Native Android App Threads (2.90 MB, application/zip)
2016-06-22 20:11 UTC, John Chiodini
Details
Trace of Xamarin Forms App Threads (2.91 MB, application/zip)
2016-06-22 20:12 UTC, John Chiodini
Details
BLE project testing functionality (217.39 KB, application/x-rar)
2016-06-30 19:12 UTC, John Chiodini
Details

Description John Chiodini 2016-06-21 20:03:45 UTC
Created attachment 16428 [details]
DDMS CPU usage

Hi There,

I have been implementing an application which streams data from a BLE device. For some background, this device sends out data over the connection interval of 11.25ms. I am currently developing on a Nexus 9 Tablet running Marshmallow.

Connecting to the devices, and R/W of characteristics seems to work well. The problem occurs once I begin subscribing to the characteristic Notification, triggering the BluetoothGattCallback.OnCharacteristicChanged() callback. My app immediately jumps up from 4% to 15% CPU. 

Taking the current byte value from the callback using the characteristic.GetValue() method takes even longer, bumping CPU up to 30%. Looking at DDMS, it looks like OnCharacteristicChanged() starts taking tons of CPU time. Additionally, GC starts running constantly,

I have implemented this in Android studio, with a total CPU usage of <5%, with the OnCharaceristicChanged() callback taking up much less CPU time. It seems to me that either there is some issue with the threadpool allocations for the CharacteristicChanged callback, or some other issue in the Android.Bluetooth implementation.

Thanks

06-17 10:53:08.577 D/Mono    ( 6303): GC_OLD_BRIDGE num-objects 1   num_hash_entries 1 sccs size 1 init 0.00ms df1 0.01ms sort 0.04ms dfs2 0.00ms setup-cb 0.00ms free-data 0.00ms links 0/0/0/0 dfs passes 0/0

06-17 10:53:08.578 D/Mono    ( 6303): GC_MINOR: (Nursery full) pause 3.49ms, total 3.75ms, bridge 0.00ms promoted 0K major 3248K los 251K

06-17 10:53:09.771 D/Mono    ( 6303): GC_OLD_BRIDGE num-objects 1 num_hash_entries 1 sccs size 1 init 0.00ms df1 0.01ms sort 0.04ms dfs2 0.00ms setup-cb 0.00ms free-data 0.00ms links 0/0/0/0 dfs passes 0/0

06-17 10:53:09.771 D/Mono    ( 6303): GC_MINOR: (Nursery full) pause 4.45ms, total 5.95ms, bridge 0.00ms promoted 0K major 3248K los 251K

06-17 10:53:10.954 D/Mono    ( 6303): GC_OLD_BRIDGE num-objects 1 num_hash_entries 1 sccs size 1 init 0.00ms df1 0.01ms sort 0.04ms dfs2 0.00ms setup-cb 0.00ms free-data 0.00ms links 0/0/0/0 dfs passes 0/0

06-17 10:53:10.954 D/Mono    ( 6303): GC_MINOR: (Nursery full) pause 2.96ms, total 3.32ms, bridge 0.00ms promoted 0K major 3248K los 251K

06-17 10:53:12.160 D/Mono    ( 6303): GC_OLD_BRIDGE num-objects 1 num_hash_entries 1 sccs size 1 init 0.00ms df1 0.01ms sort 0.04ms dfs2 0.00ms setup-cb 0.00ms free-data 0.00ms links 0/0/0/0 dfs passes 0/0

06-17 10:53:12.160 D/Mono    ( 6303): GC_MINOR: (Nursery full) pause 4.35ms, total 4.97ms, bridge 0.00ms promoted 0K major 3248K los 251K

06-17 10:53:13.351 D/Mono    ( 6303): GC_OLD_BRIDGE num-objects 1 num_hash_entries 1 sccs size 1 init 0.00ms df1 0.01ms sort 0.04ms dfs2 0.00ms setup-cb 0.00ms free-data 0.00ms links 0/0/0/0 dfs passes 0/0

06-17 10:53:13.352 D/Mono    ( 6303): GC_MINOR: (Nursery full) pause 3.26ms, total 3.60ms, bridge 0.00ms promoted 0K major 3248K los 251K

06-17 10:53:14.556 D/Mono    ( 6303): GC_OLD_BRIDGE num-objects 1 num_hash_entries 1 sccs size 1 init 0.00ms df1 0.01ms sort 0.04ms dfs2 0.00ms setup-cb 0.00ms free-data 0.00ms links 0/0/0/0 dfs passes 0/0

06-17 10:53:14.558 D/Mono    ( 6303): GC_MINOR: (Nursery full) pause 3.40ms, total 3.70ms, bridge 0.00ms promoted 0K major 3248K los 251K

06-17 10:53:15.768 D/Mono    ( 6303): GC_OLD_BRIDGE num-objects 1 num_hash_entries 1 sccs size 1 init 0.00ms df1 0.01ms sort 0.04ms dfs2 0.00ms setup-cb 0.00ms free-data 0.00ms links 0/0/0/0 dfs passes 0/0

06-17 10:53:15.769 D/Mono    ( 6303): GC_MINOR: (Nursery full) pause 3.02ms, total 3.26ms, bridge 0.00ms promoted 0K major 3248K los 251K
Comment 1 John Chiodini 2016-06-22 20:11:15 UTC
Created attachment 16447 [details]
Trace of Native Android App Threads
Comment 2 John Chiodini 2016-06-22 20:12:09 UTC
Created attachment 16448 [details]
Trace of Xamarin Forms App Threads
Comment 3 John Chiodini 2016-06-22 20:14:04 UTC
I have also attached Traces of the "gold standard" Native Android app, and the Xamarin Forms app that is generating the issue. 

Looking at them, it seems pretty clear that something fishy is going on inside the OnCharacteristicChanged method.
Comment 4 John Chiodini 2016-06-30 19:11:13 UTC
Upon Request, added sample project. Readme is inside.
Comment 5 John Chiodini 2016-06-30 19:12:26 UTC
Created attachment 16537 [details]
BLE project testing functionality

Added BLE sample project
Comment 6 Jonathan Pryor 2016-07-07 21:41:40 UTC
How do you run the app? You mention a "BLE device"; is this device required to locally test the app?

I haven't tried to run the app. I have looked at TrignoTestProcess.OnCharacteristicChanged(), which appears to be using most of your CPU. (Thank you for the source.)

*Normally* when "the GC runs too often," I think that GREFs may be involved. In this case, I don't think that's the case, as the GC_OLD_BRIDGE values are very small.

Additionally, all the GC messages are because "Nursery full". Xamarin.Android's GC is a generational GC with two generations, the "nursery," and end everything else. If the nursery is constantly being filled and collecting, that implies that *something* is filling it.

Which brings us to:

            characteristic.GetValue();

This is called within TrignoTestProcess.OnCharacteristicChanged(), and BluetoothGattCharacteristic.GetValue() returns a byte[].

What isn't recorded within TrignoTestProcess.OnCharacteristicChanged() is the value returned by characteristic.GetValue(). Arrays are "deep marshaled", so if the Java-side array is e.g. 1024 entries, then 1024 bytes will be *copied* across the JNI bridge to create a C#-side 1024-entry array.

https://developer.xamarin.com/api/member/Android.Bluetooth.BluetoothGattCharacteristic.GetValue()/

I would suggest that you record this information:

    var value = characteristic.GetValue();
    Console.WriteLine ("Callback value {0} bytes", value?.Length);

I imagine that this is actually the problem, given the following comment:

    //TONS OF OVERHEAD HERE

Assuming that the array marshaling is at fault, I can only think of three "solutions":

1. Don't Do That™. Why are you calling characteristic.GetValue() if you're not using the return value?

Presumably you want to use the return value, so this isn't viable.

2. Somehow cause OnCharacteristicChanged() to be called less frequently. (I don't know if this is possible or viable either...)

3. Skip the array marshaling.

(3) involves "re-binding" the existing GetValue() binding, so that you can bypass normal marshaling behavior:

	public static unsafe Java.Interop.JniObjectReference GetJniArrayValue (
			this BluetoothGattCharacteristic self)
	{
		if (self == null)
			return new Java.Interop.JniObjectReference ();
		const string __id = "getValue.()[B";
		var array = self.JniPeerMembers.InstanceMethods.InvokeVirtualObjectMethod (__id, self, null);
		return array;
	}

You would then do:

    var array = characteristic.GetJniArrayValue();
    // ...use array, if necessary...
    Java.Interop.JniObjectReference.Dispose (ref a);
Comment 7 John Chiodini 2016-07-07 22:55:54 UTC
Thanks for the response!

We are developing a ble device in house which is unfortunately required to test the app functionality. 

In my program, I always get back 20 bytes from the GetValue(), which was by design from our device, and I think is the max allowable for BLE protocol.

As to your suggestions:

1) I wasn't doing anything with the GetValue() as this was just a quick sample I whipped up.

2) Unfortunately, we are trying to keep the updates as quick as possible, so less frequent calls might pose a problem. 

3) I tested your code, and the CPU has gone down quite a bit, and is now hovering at around 10% (!) where before it could go northwards of 20%.


The odd thing to me (and this may just be the reality of the situation) Is that even if I comment out the GetValue() method, my CPU usage is still around 5-7%. I know it dosen't seem like much, but this would be the upper bound of what I would see from an app running with GetValue() enabled in Native Android.

To me, this residual cpu use still points to something in the OnCharacteristicChanged() event that is still causing it to take a while. I noticed in the .Trace file, that Xamarin seems to call the OnCharacteristicChanged() twice?
Comment 8 John Chiodini 2016-07-08 17:01:07 UTC
I'm also trying to work with the code you posted. I admit I'm a bit confused about how to use the JniObjectReference to read my byte [].

Here was the code I tried:

    var array = characteristic.GetJniArrayValue();
    byte[] managedArray = new byte[20];
    Marshal.Copy(array.Handle,managedArray,0,20);

Unfortunately, things seem to crash on the copy action.

I also tried this:

  var array = characteristic.GetJniArrayValue();
  byte[] test = new byte[Marshal.SizeOf(array.Handle)];
  Marshal.Copy(array.Handle, test, 0, Marshal.SizeOf(array.Handle));

Oddly enough, test only is 8 bytes long. crash also occurs on the copy action


07-08 12:47:40.862 E/mono-rt (30913): 
Stacktrace:

07-08 12:47:40.862 E/mono-rt (30913): 

07-08 12:47:40.862 E/mono-rt (30913):   
at <unknown> <0xffffffff>

07-08 12:47:40.862 E/mono-rt (30913):   
at (wrapper managed-to-native) System.Runtime.InteropServices.Marshal.copy_from_unmanaged (intptr,int,System.Array,int) <0x00007>

07-08 12:47:40.863 E/mono-rt (30913):   
at System.Runtime.InteropServices.Marshal.Copy (intptr,byte[],int,int) [0x00000] in /Users/builder/data/lanes/3415/7db2aac3/source/mono/mcs/class/corlib/System.Runtime.InteropServices/Marshal.cs:146

07-08 12:47:40.863 E/mono-rt (30913):   
at BluetoothLeGatt.TrignoTestProcess.OnCharacteristicChanged (Android.Bluetooth.BluetoothGatt,Android.Bluetooth.BluetoothGattCharacteristic) [0x00022] in C:\Users\jpchiodini\Downloads\monodroid-samples-master\monodroid-samples-master\BluetoothLeGatt\TrignoTestProcess.cs:33

07-08 12:47:40.863 E/mono-rt (30913):   
at Android.Bluetooth.BluetoothGattCallback.n_OnCharacteristicChanged_Landroid_bluetooth_BluetoothGatt_Landroid_bluetooth_BluetoothGattCharacteristic_ (intptr,intptr,intptr,intptr) [0x00019] in /Users/builder/data/lanes/3415/7db2aac3/source/monodroid/src/Mono.Android/platforms/android-23/src/generated/Android.Bluetooth.BluetoothGattCallback.cs:65

07-08 12:47:40.864 E/mono-rt (30913):   
at (wrapper dynamic-method) object.5fc1fa92-c421-4634-9437-5b0f73687eea (intptr,intptr,intptr,intptr) <IL 0x0001d, 0x0002f>

07-08 12:47:40.864 E/mono-rt (30913):   
at (wrapper native-to-managed) object.5fc1fa92-c421-4634-9437-5b0f73687eea (intptr,intptr,intptr,intptr) <IL 0x00020, 0x00097>

07-08 12:47:40.864 E/mono-rt (30913): 

07-08 12:47:40.864 E/mono-rt (30913): 
Attempting native Android stacktrace:

07-08 12:47:40.864 E/mono-rt (30913):
Comment 9 Jonathan Pryor 2016-07-08 20:31:27 UTC
> In my program, I always get back 20 bytes from the GetValue()

How frequently is this method called? The nursery is ~512KB, so I wouldn't expect it to fill up that fast when it's only getting 20-ish bytes at a time...


> The odd thing to me Is that even if I comment out the GetValue() method,
> my CPU usage is still around 5-7%...this would be the upper bound of what
> I would see from an app running with GetValue() enabled in Native Android.

That's likely attributable to all the JNI transitions that are involved. :-(

> I noticed in the .Trace file, that Xamarin seems to call the 
> OnCharacteristicChanged() twice?

That seems quite odd. OnCharacteristicChanged() should be called exactly as many times as the Java onCharacteristicChanged() method; see also n_onCharacteristicChanged() in call stacks.
Comment 10 Jonathan Pryor 2016-07-08 20:40:23 UTC
> I admit I'm a bit confused about how to use the JniObjectReference to read my byte []

The JniObjectReference abstraction is new to Xamarin.Android 6.1, and unfortunately there's not a lot of documentation on it yet.

A JniObjectReference is JNI Reference; it's a "handle" to a Java instance.

If that instance is a Java array, you can use the Java.Interop.JniEnvironment.Arrays methods to read individual elements.

You might find this handy: https://github.com/xamarin/java.interop/blob/master/src/Java.Interop/Java.Interop/JavaPrimitiveArrays.cs#L299-L321

(Note: JavaArray, JavaSByteArray, etc. aren't currently included in Xamarin.Android.)

    JniObjectReference array = ...;
    int length = JniEnvironment.Arrays.GetArrayLength(array);
    sbyte* items = JniEnvironment.Arrays.GetByteArrayElements(array, null);
    // items [0]..items[length-1] are valid
    JniEnvironment.Arrays.ReleaseCharArrayElements(array, items, 0);

See also the JNI documentation: http://docs.oracle.com/javase/8/docs/technotes/guides/jni/spec/functions.html#array_operations

*Normal* use would generally use the default marshaler, which makes for a much nicer experience. :-)
Comment 11 John Chiodini 2016-07-08 21:37:19 UTC
Thanks again for all your help, this has been very enlightening!

>How frequently is this method called? The nursery is ~512KB, so I wouldn't >expect it to fill up that fast when it's only getting 20-ish bytes at a >time...

The device uses the minimum connection interval allowed by Android Marshmallow, which is 11.25 ms. On the current Nexus Tablet we have, the BT stack allows 4 packets to be sent per connection interval. I think that should put us in around one Characteristic Notification every ~3ms. Would this be quick enough to force GC to run?


>That seems quite odd. OnCharacteristicChanged() should be called exactly as >many times as the Java onCharacteristicChanged() method; see also >n_onCharacteristicChanged() in call stacks.

Ah, I see. looking at the .Trace (attached) it seems like the OnCharacteristicChanged() is indeed called once, it just seems to take a bit, then calls the internal n_OnCharacteristicChanged. I'm guessing that internal method is by design and has to do with the JNI binding, so I may just have to live with the added overhead... 

I will take a look at the documentation and code you provided to see if I can get that Byte[] out.
Comment 12 Jon Douglas [MSFT] 2017-10-04 15:18:35 UTC
I am marking this bug as RESOLVED ANSWERED after reading through the comments.  If you are still experiencing the issue, please reopen this report with an update to https://bugzilla.xamarin.com/show_bug.cgi?id=42048#c11.

Note You need to log in before you can comment on or make changes to this bug.