Bug 41733 - JNIEnv.GetArray(IntPtr, JniHandleOwnership.TransferLocalRef, typeof(byte)) floods log with exceptions in Xamarin.Android 6
Summary: JNIEnv.GetArray(IntPtr, JniHandleOwnership.TransferLocalRef, typeof(byte)) fl...
Status: VERIFIED FIXED
Alias: None
Product: Android
Classification: Xamarin
Component: Bindings ()
Version: 6.1.0 (C7)
Hardware: Macintosh Mac OS
: Highest major
Target Milestone: 7.0 (C8)
Assignee: Jonathan Pryor
URL:
Depends on:
Blocks:
 
Reported: 2016-06-11 18:23 UTC by Anton Venema
Modified: 2016-08-04 15:17 UTC (History)
9 users (show)

Tags: BZRC7S1_C6SR4S1
Is this bug a regression?: Yes
Last known good build: 6.0.4


Attachments
Minimal Android project that demonstrates the issue (1.42 MB, application/zip)
2016-06-11 18:23 UTC, Anton Venema
Details


Notice (2018-05-24): bugzilla.xamarin.com is now in read-only mode.

Please join us on Visual Studio Developer Community and in the Xamarin and Mono organizations on GitHub to continue tracking issues. Bugzilla will remain available for reference in read-only mode. We will continue to work on open Bugzilla bugs, copy them to the new locations as needed for follow-up, and add the new items under Related Links.

Our sincere thanks to everyone who has contributed on this bug tracker over the years. Thanks also for your understanding as we make these adjustments and improvements for the future.


Please create a new report on Developer Community or GitHub with your current version information, steps to reproduce, and relevant error messages or log files if you are hitting an issue that looks similar to this resolved bug and you do not yet see a matching new report.

Related Links:
Status:
VERIFIED FIXED

Description Anton Venema 2016-06-11 18:23:22 UTC
Created attachment 16288 [details]
Minimal Android project that demonstrates the issue

Since upgrading to Xamarin.Android 6, calling JNIEnv.GetArray to retrieve a JNI jbytearray into a C# byte[] floods the log with exceptions and brings performance to a crawl.

Sample method call from C#:

    // Invoke the test method in native code, which
    // returns the result of calling NewByteArray.
    IntPtr outputPtr = DemoLibrary.Java_demo_DemoLibrary_test(JNIEnv.Handle, IntPtr.Zero);

    // Get the result of the method as a C# byte[].
    // This worked in Xamarin.Android 5, but now floods the logs
    // with exceptions. What has changed in Xamarin.Android 6?
    byte[] output = (byte[])JNIEnv.GetArray(outputPtr, JniHandleOwnership.TransferLocalRef, typeof(byte));

Sample extern declaration in C#:

    public static extern IntPtr Java_demo_DemoLibrary_test(IntPtr env, IntPtr jniClass);

Sample method definition in C (JNI):

    JNIEXPORT jbyteArray JNICALL Java_demo_DemoLibrary_test (JNIEnv *env, jclass obj)
    {
        return env->NewByteArray(512);
    }

This used to work flawlessly in Xamarin.Android 5. Our use case is very "chatty" with JNI/C# interop, so this impacts us severely.

A barebones example is attached that demonstrates the issue.
Comment 1 Shane 2016-06-11 19:01:37 UTC
This is a showstopper for us using Xamarin 6.0, we'll have to go back to 5 until this is fixed. The quantity of exceptions this throws when using video grounds the app to a halt. I hope this can be fixed quickly.

Thanks!
Comment 2 Atsushi Eno 2016-06-13 06:23:05 UTC
@jonp: Java.Interop issue?
Comment 3 Anton Venema 2016-06-13 19:45:17 UTC
Confirmed that this is new in Xamarin.Android 6.1. It worked in 6.04.
Comment 4 Jonathan Pryor 2016-06-15 02:08:30 UTC
The message:

> 06-14 21:55:04.063 16462 16771 I mono-stdout: Fail: LREF count is -909, expected to be >= 0 when dealing with handle 0x100005/L on thread ''(3).

As @eno notes, this is a Java.Interop issue:

https://github.com/xamarin/java.interop/blob/3256144/src/Java.Interop/Java.Interop/JniRuntime.JniObjectReferenceManager.cs#L74
https://github.com/xamarin/java.interop/blob/3256144/src/Java.Interop/Java.Interop/JniRuntime.JniObjectReferenceManager.cs#L176-L182

There are two problems:

1. We *probably* shouldn't be using Debug builds with asserts enabled in the final product. (Maybe? Just a thought?)

2. Our JNI handle accounting logic is sufficiently buggy that the assert is failing.

It's not problematic, per-se, that what we *think* is the number of outstanding JNI handles is wrong. They're largely only advisory. (Unless we hard crash due to too many local references, then there's a major issue somewhere, but that's not the case here.)

It *is* problematic when performance tanks because *so many* of those asserts are firing.
Comment 5 Anton Venema 2016-06-20 15:32:21 UTC
I assume this will be fixed in 6.2 (C8)? Is there an estimated release date?
Comment 6 Brendan Zagaeski (Xamarin Team, assistant) 2016-06-22 00:16:06 UTC
## Regression status: regression in Cycle 7

BAD:  Xamarin.Android 6.1.1.1 (7db2aac)
GOOD: Xamarin.Andorid 6.0.4.0 (ee215fc)




## BAD Results on Xamarin.Android 6.1

I added a `System.Diagnostics.Stopwatch` to the example from Comment 0 to measure the time to complete the loop.  I built the app in the Release configuration and deployed it to a hardware device (LG Optimus L9).  And then I repeated the test 3 times: 

44654 ms
45027 ms
44520 ms




## GOOD Results on Xamarin.Android 6.0

320 ms
264 ms
351 ms
Comment 7 Cooper Hilscher 2016-07-06 20:07:51 UTC
This issue is also makes our app unusable. Is there an estimated release date for this fix?
Comment 8 Jonathan Pryor 2016-07-06 21:17:39 UTC
My apologies for the delay, I didn't get a chance to look deeper into this until now.

Comment #4 suggests:

> 2. Our JNI handle accounting logic is sufficiently buggy that the assert is failing.

Upon further investigation, that's not quite right. The problem isn't that the existing accounting logic is "wrong" or "buggy," it's that your app is sidestepping *half* of our accounting logic -- the increment half -- while hitting the other half.

(No wonder it's unhappy.)

The way it's expected to work is that a binding will be used, and that binding will use Android.Runtime.JNIEnv.Call*ObjectMethod(), which calls JniEnvironment.*Methods.Call*ObjectMethod(), which calls the internal JniEnvironment.LogCreateLocalRef() method:

https://github.com/xamarin/java.interop/blob/3b038a87/src/Java.Interop/Java.Interop/JniEnvironment.cs#L85-L90

This calls JniObjectReferenceManager.CreatedLocalReference(), which increments the tracked JNI local reference count, which gets decremented -- and asserted -- in JniObjectReferenceManager.DeleteLocalReference():

https://github.com/xamarin/java.interop/blob/3b038a87/src/Java.Interop/Java.Interop/JniRuntime.JniObjectReferenceManager.cs#L68-L77

Your app bypasses JniEnvironment.LogCreateLocalRef(), so when `Java_demo_DemoLibrary_test()` is invoked the JNI local reference count is never incremented. Your app *does* call -- indirectly! -- JniObjectReferenceManager.DeleteLocalReference(), as that's what deletes the local reference, implicit in your JNIEnv.GetArray(..., JniHandleOwnership.TransferLocalRef, ...) call.

---

I'm less certain about the correct fix. (This scenario partly makes me wish that SafeHandles could be used, but they can't...)

Comment #4 suggests that we could (should?) do a Release build, such that DEBUG isn't defined. This would remove the assert, and thus would fix your performance problem.

While this is *a* fix, it has knock-on ramifications: it means that Java.Interop.JniEnvironment. LocalReferenceCount would be completely whack. It's supposed to be advisory, but there's a difference between "advisory" and "goes negative and could plausibly underflow from negative numbers to positive numbers if you call `Java_demo_DemoLibrary_test()` often enough."

An alternate fix would be to make JniEnvironment.LogCreateLocalRef(JniObjectReference) public. This would allow P/Invoke-based JNI invocations to take part in the accounting.
Comment 9 Anton Venema 2016-07-06 21:23:27 UTC
I don't like the possibility of introducing a possible underflow on a negative reference count. When we came across the bug, my instinct was to look for a public method that would increment the local ref count to satisfy the assertion. If something like that existed, it would definitely be sufficient for our use case.
Comment 10 Jonathan Pryor 2016-07-06 21:32:00 UTC
@Anton: Here is a patch to Attachment #16288 [details] which invokes JniEnvironment.LogCreateLocalRef() after calling `DemoLibrary.Java_demo_DemoLibrary_test()`, and adds the Stopwatch usage that Brendan mentions in Comment #6:

https://gist.github.com/jonpryor/3cb9902b9fa8c19324f8a0fedb3c1b8a

This appears to fix the performance problem, as I'm now seeing click execution times of ~240-300ms, which is in line with what Brendan reported for the previous stable release.

Hopefully this can be used as a workaround while I consider whether I should just make `JniEnvironment.LogCreateLocalRef()` public or if I should use some "better" named method.
Comment 11 Anton Venema 2016-07-06 22:07:11 UTC
@Jon: I've pulled that into our code-base, and it appears to have alleviated the performance problem. I agree that the name doesn't quite sound right. From my perspective, it would make more sense to add an extra boolean parameter to JNIEnv.GetArray to indicate whether `array_ptr` was obtained through a P/Invoke-based JNI invocation. The implementation for GetArray could then increment the local ref count internally if that boolean parameter was true, and you wouldn't have to expose any new public methods.
Comment 12 Jonathan Pryor 2016-07-07 16:06:26 UTC
PR for the proper Java.Interop API to fix things:

https://github.com/xamarin/java.interop/pull/52
Comment 13 Jonathan Pryor 2016-07-28 19:11:37 UTC
Addressed in:

* https://github.com/xamarin/java.interop/commit/59c4f44f
* monodroid/master/3ef12f00
* monodroid/cycle8/6fb52c6f
Comment 14 Abhishek 2016-08-01 18:46:35 UTC
I have checked this issue and able to reproduce this issue with the attach sample at my end with the following build:
xamarin.android-6.1.1-1_7db2aac379d451ca08ebf968a715f32c2341afaf

Application Output: https://gist.githubusercontent.com/Abhishekk360/ca0a8fea5105aefdd38942da5948649b/raw/9960a85b70b63ad67a37efc7675f5a7ee5d54908/Application%2520Output


GOOD build: xamarin.android-6.0.4-0_ee215fc923a4650cfa49d4f38ff175c7441f8281

Application Output: https://gist.github.com/Abhishekk360/e51fab39c897499b79cbac7bd41af2f3

To verify this issue I have checked this issue with latest C8 build:
xamarin.android-6.2.0-23/fdaf900a.

I am not observing the correct behavior as What I am seeing with GOOD Build.

Screencast: http://www.screencast.com/t/Tsr2l44hXY
Application Output: https://gist.githubusercontent.com/Abhishekk360/5b47fdd9936e4a23c7581cb05f52bff6/raw/5da6bf735daad58a7a20b7927d8358b30ac74d50/Application%2520Output

Also I have checked this issue with latest master Build:
xamarin.android-6.1.99-415/cb591d4

Observing the same reported behavior.

Application Output: https://gist.githubusercontent.com/Abhishekk360/f1164d8f00c9ca60ef8ff053c2f98630/raw/c42edff17937135268e2b87ddd0d9ab5909ef49a/Application%2520Output

Hence reopening this issue.

Thanks!
Comment 15 Jonathan Pryor 2016-08-01 19:02:07 UTC
@Abhishek: As Comment #13 noted, it was "addressed", *not* "fixed", by adding a new API that apps can call to indicate that a JNI handle was created "externally": Java.Interop.JniEnvironment.References.CreatedReference().

Thus, the app would need to first be fixed to use the new API:

https://gist.github.com/jonpryor/b4f3589b08b7afeb7809a5b454e1126e

Once the API is used, the warning should no longer be generated.
Comment 16 Abhishek 2016-08-02 17:47:54 UTC
Thanks @Jonathan, 

******************
C8 build:
******************

I have checked this issue with latest C8 build:
xamarin.android-6.2.0-23/fdaf900a.

As per comment 15. Now I am successfully able to get expected result.

Screencast: http://www.screencast.com/t/0cz5Gyu2N
Application Output: https://gist.github.com/Abhishekk360/dcb7bdff105ee63b0a239d2b7b70fa21

Also I have checked this with latest XVS c8 build:
Xamarin.VisualStudio_4.2.0.413\b5d9567

Screencast: http://www.screencast.com/t/w6GugoqW
Application Output: https://gist.github.com/Abhishekk360/44c349eb8091fc397f4d6a35ad95075c

******************
Master build
******************

I have checked this issue with latest master
xamarin.android-6.1.99-415/cb591d4

Now this issue is working fine.

Screencast: http://www.screencast.com/t/LTya1ojHE9
Application Output: https://gist.github.com/Abhishekk360/d1bf184f6361f509198bb49599c1cf17

However I have checked this issue with latest master xvs:
Xamarin   99.0.0.3286 (e471f3e)

Unable to find Java.Interop.JniEnvironment.References.CreatedReference().


Could you please let me know about XVS master build so that I can verify this issue on Windows environment also?

@Jonathan, I have observe the difference in Elapsed time on C8 XS and XVS.
Comment 17 abhi 2016-08-04 15:17:02 UTC
@Jonathan, However I have checked this issue with latest master xvs:
Xamarin   99.0.0.3298 (65fae8)

and I observed that this issue is working fine.

Screencast:http://www.screencast.com/t/5IEquLFCWeLD
Application Output:https://gist.github.com/tajinder360/00a8af6c027dc3ed8c780f998d210aea

Build Info:https://gist.github.com/tajinder360/0a02b134e1a87cf568902dc39380646d

Hence I closing this issue.
Thanks!!