Jni warning

gameleongameleon ✭✭NLMember ✭✭

I'm currently having a issue with Mono for Android considering a JNI warning.

The problem appears in the following BackgroundWorker doWork handler:

private void loadBookingList_Async(object sender, DoWorkEventArgs e)
{
     TTGetBookingListResult result = TTWebservice.GetBookingListCall();

     //.....
}

The GetBookingListCall is a static method:

public static TTGetBookingListResult GetBookingListCall()
{
    //Omitted retrieval of jsonResult variable


    TTGetBookingListResult result = new TTGetBookingListResult();
    MemoryStream ms = new MemoryStream(Encoding.Unicode.GetBytes(jsonResult));
    DataContractJsonSerializer serializer = new DataContractJsonSerializer(result.GetType());
    result = serializer.ReadObject(ms) as TTGetBookingListResult;
    ms.Close();
    return result;
}

The first few times this doWork handler is run, it works with no issue. However, when the handler has been called a few times (usually when the GREF reaches 1100-1300) in a single run, the DataContractJsonSerializer generates the following error at the serialized.ReadObject(ms)statement:

11-29 15:20:16.565 W/dalvikvm( 1318): JNI WARNING: 0xb6e72250 is not a valid JNI reference
11-29 15:20:16.565 W/dalvikvm( 1318):              in Ldalvik/system/NativeStart;.run ()V (NewWeakGlobalRef)
11-29 15:20:16.565 I/dalvikvm( 1318): "Thread-19" prio=5 tid=13 RUNNABLE
11-29 15:20:16.565 I/dalvikvm( 1318):   | group="main" sCount=0 dsCount=0 obj=0xb6ee2e48 self=0x9b45be0
In mgmain JNI_OnLoad
11-29 15:20:16.575 I/dalvikvm( 1318):   | sysTid=1341 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=162787376
11-29 15:20:16.575 I/dalvikvm( 1318):   at dalvik.system.NativeStart.run(Native Method)
11-29 15:20:16.586 I/dalvikvm( 1318): 
11-29 15:20:16.586 E/dalvikvm( 1318): VM aborting
11-29 15:20:16.586 I/mono    ( 1318): Stacktrace:
11-29 15:20:16.586 I/mono    ( 1318): 
11-29 15:20:16.586 I/mono    ( 1318):   at (wrapper managed-to-native) object.__icall_wrapper_mono_array_new_specific (intptr,int) <IL 0x00022, 0xffffffff>
11-29 15:20:16.586 I/mono    ( 1318):   at System.Text.UnicodeEncoding.GetPreamble () <IL 0x00044, 0x00147>
11-29 15:20:16.586 I/mono    ( 1318):   at System.IO.StreamReader.Initialize (System.IO.Stream,System.Text.Encoding,bool,int) <IL 0x0015d, 0x00639>
11-29 15:20:16.586 I/mono    ( 1318):   at System.IO.StreamReader..ctor (System.IO.Stream,System.Text.Encoding,bool,int) <IL 0x0000c, 0x0005b>
11-29 15:20:16.586 I/mono    ( 1318):   at System.IO.StreamReader..ctor (System.IO.Stream,System.Text.Encoding) <IL 0x00009, 0x00043>
11-29 15:20:16.586 I/mono    ( 1318):   at System.Runtime.Serialization.Json.PushbackReader..ctor (System.IO.Stream,System.Text.Encoding) <IL 0x00003, 0x0002b>
11-29 15:20:16.586 I/mono    ( 1318):   at System.Runtime.Serialization.Json.PushbackReader..ctor (System.Runtime.Serialization.Json.EncodingDetecingInputStream) <IL 0x00008, 0x00047>
11-29 15:20:16.586 I/mono    ( 1318):   at System.Runtime.Serialization.Json.PushbackReader..ctor (System.IO.Stream) <IL 0x00007, 0x00063>
11-29 15:20:16.586 I/mono    ( 1318):   at System.Runtime.Serialization.Json.JsonReader.SetInput (System.IO.Stream,System.Text.Encoding,System.Xml.XmlDictionaryReaderQuotas,System.Xml.OnXmlDictionaryReaderClose) <IL 0x0001a, 0x000e3>
11-29 15:20:16.586 I/mono    ( 1318):   at System.Runtime.Serialization.Json.JsonReader..ctor (System.IO.Stream,System.Text.Encoding,System.Xml.XmlDictionaryReaderQuotas,System.Xml.OnXmlDictionaryReaderClose) <IL 0x00034, 0x00193>
11-29 15:20:16.586 I/mono    ( 1318):   at System.Runtime.Serialization.Json.JsonReaderWriterFactory.CreateJsonReader (System.IO.Stream,System.Text.Encoding,System.Xml.XmlDictionaryReaderQuotas,System.Xml.OnXmlDictionaryReaderClose) <IL 0x00004, 0x00067>
11-29 15:20:16.586 I/mono    ( 1318):   at System.Runtime.Serialization.Json.JsonReaderWriterFactory.CreateJsonReader (System.IO.Stream,System.Xml.XmlDictionaryReaderQuotas) <IL 0x00004, 0x00033>
11-29 15:20:16.586 I/mono    ( 1318):   at System.Runtime.Serialization.Json.DataContractJsonSerializer.ReadObject (System.IO.Stream) <IL 0x00006, 0x0003b>
11-29 15:20:16.586 I/mono    ( 1318):   at TTApp.TTWebservice.GetBookingListCall (System.DateTime) [0x000af] in <FILENAME OMITTED>:528
11-29 15:20:16.586 I/mono    ( 1318):   at TTApp.TTBookingListScreen.loadBookingList_Async (object,System.ComponentModel.DoWorkEventArgs) [0x00027] in <FILENAME OMITTED>:262
11-29 15:20:16.586 I/mono    ( 1318):   at System.ComponentModel.BackgroundWorker.OnDoWork (System.ComponentModel.DoWorkEventArgs) <IL 0x00013, 0x00045>
    11-29 15:20:16.586 I/mono    ( 1318):   at System.ComponentModel.BackgroundWorker.ProcessWorker (object,System.ComponentModel.AsyncOperation,System.Threading.SendOrPostCallback) <IL 0x0000b, 0x0008c>
11-29 15:20:16.586 I/mono    ( 1318):   at (wrapper runtime-invoke) <Module>.runtime_invoke_void__this___object_object_object (object,intptr,intptr,intptr) <IL 0x00064, 0xffffffff>

Posts

  • JonathanPryorJonathanPryor Xamurai USXamarin Team Xamurai

    I assume TTGetBookingListResult is a Java.Lang.Object subclass. Would it be possible to make it a System.Object subclass?

    Are you seeing this on a hardware device or on the emulator?

    Which Android version is this on?

    One puzzling thing is that the error is in dalvik.system.NativeStart.run(). That's Android/Dalvik, not Mono for Android; how is it obtaining that JNI reference, and why is it getting invalidated? I have no idea.

    Please enable gref logging. This will cause Mono for Android to log every time it creates and destroys a gref, allowing you to determine where gref 0xb6e72250 was allocated (and later freed?).

    adb shell setprop debug.mono.log gref
    

    Note: gref pointer values will be inconsistent from one app execution to another. It's unlikely that you'll be able to search for 0xb6e72250; you'll need to look at the JNI WARNING message on each app execution to determine the current value.

  • gameleongameleon ✭✭ NLMember ✭✭
    edited November 2012

    The TTGetBookingListResult is a System.Object class (it has no inheritance defined so it should default to that)

    I've tried it on emulators (both x86 and ARM image based) and 4 different devices. Android versions used are 2.2 (emulator only) , 2.3.3 , 4.0.3 and 4.1.

    Mono for Android version used is 4.2.7

    I will try the gref logging and edit this post with the results.

  • JonathanPryorJonathanPryor Xamurai USXamarin Team Xamurai

    The TTGetBookingListResult is a System.Object class

    Interesting. Then I would guess that the gref increase is unrelated to the TTGetBookingListResult deserialization, unless your TTGetBookingListResult instance creates Java.Lang.Object subclasses as part of its operation...

    I will try the gref logging and edit this post with the results.

    If possible, perform gref logging on your 2.3 device, not anything running Android 4.0 or later. This is because Android 4.0 introduced "indirect" JNI handles, so the values are less "stable", which greatly complicates determining where the value came from (as you'll need to trace through gref -> wref -> gref changes).

  • gameleongameleon ✭✭ NLMember ✭✭
    edited December 2012

    If possible, perform gref logging on your 2.3 device, not anything running Android 4.0 or later. This is because Android 4.0 introduced "indirect" JNI handles, so the values are less "stable", which greatly complicates determining where the value came from (as you'll need to trace through gref -> wref -> gref changes).

    I did some logging on my 2.3 device, here is the error:

    12-03 15:45:28.583 W/dalvikvm( 1816): JNI WARNING: 0xb6dcb8c8 is not a valid JNI reference
    12-03 15:45:28.583 W/dalvikvm( 1816):              in Lmono/java/lang/RunnableImplementor;.n_run ()V (NewWeakGlobalRef)
    12-03 15:45:28.583 I/dalvikvm( 1816): "main" prio=5 tid=1 RUNNABLE
    12-03 15:45:28.583 I/dalvikvm( 1816):   | group="main" sCount=0 dsCount=0 obj=0xb67adc38 self=0x93c7e48
    12-03 15:45:28.583 I/dalvikvm( 1816):   | sysTid=1816 nice=0 sched=0/0 cgrp=[fopen-error:2] handle=-2145907712
    12-03 15:45:28.583 I/dalvikvm( 1816):   at mono.java.lang.RunnableImplementor.n_run(Native Method)
    12-03 15:45:28.583 I/dalvikvm( 1816):   at mono.java.lang.RunnableImplementor.run(RunnableImplementor.java:29)
    12-03 15:45:28.583 I/dalvikvm( 1816):   at android.os.Handler.handleCallback(Handler.java:587)
    12-03 15:45:28.583 I/dalvikvm( 1816):   at android.os.Handler.dispatchMessage(Handler.java:92)
    12-03 15:45:28.583 I/dalvikvm( 1816):   at android.os.Looper.loop(Looper.java:130)
    12-03 15:45:28.583 I/dalvikvm( 1816):   at android.app.ActivityThread.main(ActivityThread.java:3683)
    12-03 15:45:28.583 I/dalvikvm( 1816):   at java.lang.reflect.Method.invokeNative(Native Method)
    12-03 15:45:28.583 I/dalvikvm( 1816):   at java.lang.reflect.Method.invoke(Method.java:507)
    12-03 15:45:28.583 I/dalvikvm( 1816):   at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:839)
    12-03 15:45:28.583 I/dalvikvm( 1816):   at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:597)
    12-03 15:45:28.583 I/dalvikvm( 1816):   at dalvik.system.NativeStart.main(Native Method)
    12-03 15:45:28.583 I/dalvikvm( 1816): 
    12-03 15:45:28.583 E/dalvikvm( 1816): VM aborting
    12-03 15:45:28.583 I/mono    ( 1816): Stacktrace:
    12-03 15:45:28.583 I/mono    ( 1816): 
    12-03 15:45:28.583 I/mono    ( 1816):   at (wrapper managed-to-native) string.InternalAllocateStr (int) <IL 0x00021, 0xffffffff>
    12-03 15:45:28.583 I/mono    ( 1816):   at System.Text.StringBuilder.InternalEnsureCapacity (int) <IL 0x000b2, 0x0021b>
    12-03 15:45:28.583 I/mono    ( 1816):   at System.Text.StringBuilder.Append (string) <IL 0x00084, 0x001b7>
    12-03 15:45:28.583 I/mono    ( 1816):   at string.FormatHelper (System.Text.StringBuilder,System.IFormatProvider,string,object[]) <IL 0x001c7, 0x009f3>
    12-03 15:45:28.583 I/mono    ( 1816):   at System.Text.StringBuilder.AppendFormat (System.IFormatProvider,string,object[]) <IL 0x00004, 0x00033>
    12-03 15:45:28.583 I/mono    ( 1816):   at System.Text.StringBuilder.AppendFormat (string,object,object) <IL 0x00011, 0x0009b>
    12-03 15:45:28.583 I/mono    ( 1816):   at System.Diagnostics.StackTrace.ToString () <IL 0x0009c, 0x0028f>
    12-03 15:45:28.583 I/mono    ( 1816):   at Android.Runtime.JNIEnv.NewGlobalRef (intptr) [0x00026] in /Users/builder/data/lanes/monodroid-mac-monodroid-4.2.7-branch/0e9eea34/source/monodroid/src/Mono.Android/src/Runtime/JNIEnv.cs:369
    12-03 15:45:28.583 I/mono    ( 1816):   at Java.Lang.Object.SetHandle (intptr,Android.Runtime.JniHandleOwnership) [0x00000] in /Users/builder/data/lanes/monodroid-mac-monodroid-4.2.7-branch/0e9eea34/source/monodroid/src/Mono.Android/src/Java.Lang/Object.cs:123
    12-03 15:45:28.583 I/monodroid-gref( 1816): *take_weak obj=0xb137ace8 -> wr12-03 15:45:28.583 I/mono    ( 1816):   at Android.Widget.ArrayAdapter`1..ctor (Android.Content.Context,int) [0x00064] in /Users/builder/data/lanes/monodroid-mac-monodroid-4.2.7-branch/0e9eea34/source/monodroid/src/Mono.Android/src/Android.Widget/ArrayAdapter.cs:29
    12-03 15:45:28.583 I/mono    ( 1816):   at TTApp.TTBookingListScreen/TTBookingListAdapter..ctor (Android.App.Activity,System.Collections.Generic.List`1<TTApp.TTBookingListData>,System.DateTime) [0x00021] in <OMITTED>\TTBookingListScreen.cs:438
    12-03 15:45:28.583 I/mono    ( 1816):   at TTApp.TTBookingListScreen/<>c__DisplayClassb.<loadBookingList_Async>b__8 () [0x00001] in <OMITTED>\TTBookingListScreen.cs:290
    12-03 15:45:28.583 I/mono    ( 1816):   at Java.Lang.Thread/RunnableImplementor.Run () [0x0000b] in /Users/builder/data/lanes/monodroid-mac-monodroid-4.2.7-branch/0e9eea34/source/monodroid/src/Mono.Android/src/Java.Lang/Thread.cs:32
    12-03 15:45:28.583 I/mono    ( 1816):   at Java.Lang.IRunnableInvoker.n_Run (intptr,intptr) [0x00008] in /Users/builder/data/lanes/monodroid-mac-monodroid-4.2.7-branch/0e9eea34/source/monodroid/src/Mono.Android/platforms/android-8/src/generated/Java.Lang.IRunnable.cs:69
    12-03 15:45:28.583 I/mono    ( 1816):   at (wrapper dynamic-method) object.67e2626f-6eab-49c4-abb5-8bac3543e4f3 (intptr,intptr) <IL 0x0000c, 0x00017>
    12-03 15:45:28.583 I/mono    ( 1816):   at (wrapper native-to-managed) object.67e2626f-6eab-49c4-abb5-8bac3543e4f3 (intptr,intptr) <IL 0x0001e, 0xffffffff>
    

    This are all references to that memory address I found in the GREF logging:

    1.

        12-03 15:45:22.533 I/monodroid-gref( 1816): handle 0xb6dcb8c8; key_handle 0xb6dcb8c8: Java Type: `ttapp/TTBookingListData`; MCW type: `TTApp.TTBookingListData`
        12-03 15:45:22.564 I/monodroid-gref( 1816): +g+ grefc 860 gwrefc 0 obj-handle 0xb6d00b90/L -> new-handle 0xb6d00b90/L from    at Android.Runtime.JNIEnv.NewGlobalRef(IntPtr jobject) in /Users/builder/data/lanes/monodroid-mac-monodroid-4.2.7-branch/0e9eea34/source/monodroid/src/Mono.Android/src/Runtime/JNIEnv.cs:line 369
        12-03 15:45:22.564 I/monodroid-gref( 1816):    at Android.Runtime.JNIEnv.FindClass(System.String classname) in /Users/builder/data/lanes/monodroid-mac-monodroid-4.2.7-branch/0e9eea34/source/monodroid/src/Mono.Android/src/Runtime/JNIEnv.cs:line 279
        12-03 15:45:22.564 I/monodroid-gref( 1816):    at Android.Runtime.JNIEnv.FindClass(System.Type type) in /Users/builder/data/lanes/monodroid-mac-monodroid-4.2.7-branch/0e9eea34/source/monodroid/src/Mono.Android/src/Runtime/JNIEnv.cs:line 233
        12-03 15:45:22.564 I/monodroid-gref( 1816):    at Android.Runtime.JNIEnv.CreateInstance(System.Type type, System.String signature, Android.Runtime.JValue[] constructorParameters) in /Users/builder/data/lanes/monodroid-mac-monodroid-4.2.7-branch/0e9eea34/source/monodroid/src/Mono.Android/src/Runtime/JNIEnv.cs:line 214
        12-03 15:45:22.564 I/monodroid-gref( 1816):    at Java.Lang.Object..ctor() in /Users/builder/data/lanes/monodroid-
    

    2.

        *take_weak obj=0xb137f260 -> wref=0x28d33c8f handle=0xb6dcb8c8
        12-03 15:45:23.044 I/monodroid-gref( 1816): +w+ grefc 848 gwrefc 15 obj-handle 0xb6dcb8c8/G -> new-handle 0x28d33c8f/W from take_weak_global_ref_jni
        12-03 15:45:23.044 I/monodroid-gref( 1816): -g- grefc 847 gwrefc 15 handle 0xb6dcb8c8/G from take_weak_global_ref_jni
    

    3.

    12-03 15:45:23.313 I/monodroid-gref( 1816): *try_take_global obj=0xb137f260 -> wref=0x28d33c8f handle=0xb6dcb8c8
    12-03 15:45:23.313 I/monodroid-gref( 1816): +g+ grefc 830 gwrefc 29 obj-handle 0x28d33c8f/W -> new-handle 0xb6dcb8c8/G from take_global_ref_jni
    12-03 15:45:23.313 I/monodroid-gref( 1816): -w- grefc 830 gwrefc 28 handle 0x28d33c8f/W from take_global_ref_jni
    

    First thing I noticed during the GREF logging is that the error doesn't always happen at the same time. But there always is either a TTGetBookingListResult or a TTBookingListData object involved. The TTBookingListData is used during the parsing of the TTGetBookingListResult.

    Since TTBookingListData DOES inherit the Java.Lang.Object class, it could be the culprit here.

  • JonathanPryorJonathanPryor Xamurai USXamarin Team Xamurai

    Thank you for providing Classes.txt. TTApp.TTBookingListData.Clone() is broken:

    partial class TTBookingListData : Java.Lang.Object, ICloneable {
    
        public new object Clone()
        {
            return this.MemberwiseClone() as TTBookingListData;
        }
    }
    

    This isn't safe because object.MemberwiseClone() creates a "shallow copy" of the data -- all members are bitwise copied and a new instance is allocated without invoking the constructor on the new type. The result is that the newly created instance will have the same Java.Lang.Object.Handle value as the "source" instance, meaning that there are two C# instance holding the same gref to the same Java instance. When one of those grefs is modified (by a GC, by an explicit .Dispose() call, etc.) the other instance will not be similarly updated. The result will be an invalid gref which will bomb when you attempt to use it.

    Which is precisely what you're seeing.

    A better implementation -- assuming you need ICloneable at all -- is this:

    partial class TTBookingListData : Java.Lang.Object, ICloneable {
    
        public new object Clone()
        {
            return new TTBookingListData () {
                _booking = this._booking,
                onClick  = this.onClick
                row      = this.row,
                section  = this.section,
            };
        }
    }
    
  • gameleongameleon ✭✭ NLMember ✭✭

    Fixing the clone method has seemed to solve it :) Thank you very much.

Sign In or Register to comment.