dotnet / android

.NET for Android provides open-source bindings of the Android SDK for use with .NET managed languages such as C#
MIT License
1.93k stars 532 forks source link

[native, Mono.Android] GC bridge logging improvements #9491

Closed jonpryor closed 2 weeks ago

jonpryor commented 2 weeks ago

[native, Mono.Android] GC bridge logging improvements

Context: https://github.com/dotnet/android/issues/9039

While trying to further diagnose #9039, @jonpryor started fearing that a GC bridge issue might be at play, but the current GC bridge logging could use some improvements.

Update OSBridge::take_weak_global_ref_jni() to do two things:

  1. Set the handle and handle_type fields before deleting the original GREF. This is for a hypothetical thread-safety issue wherein the handle field and the Handle property could return a deleted GREF before being updated to the "new" Weak GREF.

    We have not seen this as being an issue in practice, but it's something we noticed. If it did happen, the app would crash and a JNI error message would be present in adb logcat, a'la:

    JNI DETECTED ERROR IN APPLICATION: use of deleted global reference 0x3d86
  2. Update the from parameter text to _monodroid_weak_gref_new() to look more like a stack trace.

    Previously, the GREF log would contain entries such as:

    monodroid-gref: -g- grefc 441 gwrefc 1 handle 0x4fda/G from thread 'finalizer'(17269)
    monodroid-gref: take_weak_global_ref_jni

    making me wonder "why is take_weak_global_ref_jni there?!"

    It's there because of the "from" parameter, to provide context. Update it to instead read:

    monodroid-gref: -g- grefc 441 gwrefc 1 handle 0x4fda/G from thread 'finalizer'(17269)
    monodroid-gref:    at [[gc:take_weak_global_ref_jni]]

    which makes it clearer what's intended.

Update OSBridge::take_global_ref_jni() in a similar manner.

Update other _monodroid*_gref_*() call sites to update their from parameters accordingly.

Update AndroidRuntime.FinalizePeer() so that the messages it logs are actually useful. Currently they are:

Finalizing handle 0x0/G

which leaves a lot to be desired. Update it to instead read:

Finalizing Instance.Type=Example.Whatever PeerReference=0x0/G IdentityHashCode=0x123456 Instance=0xdeadbeef

Note that the Instance value is RuntimeHelpers.GetHashCode(), which may not be immediately useful.

"Promote" LOG_GC to work in Release builds as well. This allows:

adb shell setprop debug.mono.gc 1

to work with libmono-android.release.so, i.e. Release builds of apps.

Update OSBridge::gc_cross_references() log the handle field of bridged instances when debug.mono.gc is set.

When the debug.mono.log system property contains gref, you can then correlate the handle values; for example:

I monodroid-gc: cross references callback invoked with 1 sccs and 0 xrefs.
I monodroid-gc: group 0 with 1 objects
I monodroid-gc:  obj 0x6f4f3d4fd0 [android_net8_hw::MainActivity] handle 0x39c6
I monodroid-gref: +w+ grefc 18 gwrefc 1 obj-handle 0x39c6/G -> new-handle 0x8cf/W from thread 'finalizer'(18712)
I monodroid-gref:    at [[gc:take_weak_global_ref_jni]]
I monodroid-gref: -g- grefc 17 gwrefc 1 handle 0x39c6/G from thread 'finalizer'(18712)
I monodroid-gref:    at [[gc:take_weak_global_ref_jni]]
I monodroid-gref: +g+ grefc 18 gwrefc 1 obj-handle 0x8cf/W -> new-handle 0x39ce/G from thread 'finalizer'(18712)
I monodroid-gref:    at [[gc:take_global_ref_jni]]
I monodroid-gref: -w- grefc 18 gwrefc 0 handle 0x8cf/W from thread 'finalizer'(18712)
I monodroid-gref:    at [[gc:take_global_ref_jni]]
I monodroid-gc: GC cleanup summary: 1 objects tested - resurrecting 1.

shows that the MainActivity instance with handle 0x39c6 was provided to the GC bridge, and it survived the Java-side GC and was kept alive ("resurrected").

jonpryor commented 2 weeks ago

wrt e27aad8b9373a2b96204d2c4c16ba59566fcfdcd, the contextual log ends with:

D monodroid-gref: Finalizing Instance.Type=Javax.Net.Ssl.HttpsURLConnectionInvoker PeerReference=0x0/G IdentityHashCode=0xde7924e Instance=0xf7d6f98c
jonpryor commented 2 weeks ago
Context: https://github.com/dotnet/android/issues/9039

While trying to further diagnose #9039, @jonpryor started fearing
that a GC bridge issue might be in play, but the current GC bridge
logging could use some improvements.

Update `OSBridge::take_weak_global_ref_jni()` to do three things:

 1. Set the `handle` and `handle_type` fields *before* deleting the
    original GREF.  This is for a hypothetical thread-safety issue
    wherein the `handle` field and the `Handle` property could return
    a *deleted* GREF before being updated to the "new" Weak GREF.

    We have not seen this as being an issue in practice, but it's
    something we noticed [^1].

 2. Update the `from` parameter text to `_monodroid_weak_gref_new()`
    to look more like a stack trace.

    Previously, the GREF log would contain entries such as:

        monodroid-gref: -g- grefc 441 gwrefc 1 handle 0x4fda/G from thread 'finalizer'(17269)
        monodroid-gref: take_weak_global_ref_jni

    making @jonpryor wonder "why is `take_weak_global_ref_jni` there?!"

    It's there because of the `from` parameter, to provide context.
    Update it to instead read:

        monodroid-gref: -g- grefc 441 gwrefc 1 handle 0x4fda/G from thread 'finalizer'(17269)
        monodroid-gref:    at [[gc:take_weak_global_ref_jni]]

    which makes it clearer what's intended.

 3. Explicitly log when an instance was collected by the Java GC when
    the `debug.mono.gc` system property is set:

        monodroid-gref: handle 0x80f/W; key_handle 0xde7924e; MCW type: `Javax.Net.Ssl.HttpsURLConnectionInvoker`: was collected by a Java GC

Update `OSBridge::take_global_ref_jni()` in a similar manner.

Update other `_monodroid*_gref_*()` call sites to update *their*
`from` parameters accordingly.

Update `AndroidRuntime.FinalizePeer()` so that the messages it logs
are actually useful.  Currently they are:

    Finalizing handle 0x0/G

which leaves a lot to be desired.  Update it to instead read:

    Finalizing Instance.Type=Example.Whatever PeerReference=0x0/G IdentityHashCode=0x123456 Instance=0xdeadbeef

Note that the `Instance` value is `RuntimeHelpers.GetHashCode()`,
which may not be immediately useful.

"Promote" `LOG_GC` to work in Release builds as well.  This allows:

    adb shell setprop debug.mono.gc 1

to work with `libmono-android.release.so`, i.e. Release builds
of apps.

Update `OSBridge::gc_cross_references()` log the `handle` and
`key_handle` fields of bridged instances when `debug.mono.gc` is set.

All together, if you set:

    adb shell setprop debug.mono.log gref
    adb shell setprop debug.mono.gc 1

then `adb logcat` may have output similar to:

    /*   1 */   I monodroid-gref: +g+ grefc 38 gwrefc 0 obj-handle 0x7213951025/I -> new-handle 0x431a/G from thread '(null)'(1)
    /*   2 */   D monodroid-gref:    at …
    /*   3 */   D monodroid-gref: handle 0x431a; key_handle 0xde7924e: Java Type: `com/android/okhttp/internal/huc/HttpsURLConnectionImpl`; MCW type: `Javax.Net.Ssl.HttpsURLConnectionInvoker`
    /*   4 */   …
    /*   5 */   I monodroid-gc: cross references callback invoked with 36 sccs and 0 xrefs.
    /*   6 */   I monodroid-gc: group 4 with 1 objects
    /*   7 */   I monodroid-gc:  obj 0x6f4ecd4a60 [Javax.Net.Ssl::HttpsURLConnectionInvoker] handle 0x431a key_handle 0xde7924e
    /*   8 */   …
    /*   9 */   I monodroid-gref: +w+ grefc 67 gwrefc 5 obj-handle 0x431a/G -> new-handle 0x80f/W from thread 'finalizer'(6441)
    /*  10 */   I monodroid-gref:    at [[gc:take_weak_global_ref_jni]]
    /*  11 */   I monodroid-gref: -g- grefc 66 gwrefc 5 handle 0x431a/G from thread 'finalizer'(6441)
    /*  12 */   I monodroid-gref:    at [[gc:take_weak_global_ref_jni]]
    /*  13 */   D monodroid-gref: handle 0x80f/W; key_handle 0xde7924e; MCW type: `Javax.Net.Ssl.HttpsURLConnectionInvoker`: was collected by a Java GC
    /*  14 */   I monodroid-gref: -w- grefc 35 gwrefc 31 handle 0x80f/W from thread 'finalizer'(6441)
    /*  15 */   I monodroid-gref:    at [[gc:take_global_ref_jni]]
    /*  16 */   …
    /*  17 */   D monodroid-gref: Finalizing Instance.Type=Javax.Net.Ssl.HttpsURLConnectionInvoker PeerReference=0x0/G IdentityHashCode=0xde7924e Instance=0xf7d6f98c

with:

  * Lines 1-3: Creation of a `Javax.Net.Ssl.HttpsURLConnectionInvoker`
    instance with `key_handle` 0xde7924e.

    The omitted stack trace on "line 2" can be used to determine
    where the instance was created.

  * Lines 5-15+: GC bridge runs containing above
    `HttpsURLConnectionInvoker` instance.

  * Line 7: provides `key_handle` for correlation purposes.
    (`obj 0x6f4ecd4a60` is the raw pointer value, for MonoVM
    developer purposes.)

  * Line 13: Explicit call-out that the `HttpsURLConnectionInvoker`
    was collected by a Java-side GC.

  * Line 17: Finalization message. `IdentityHashCode` value is the
    `key_handle` value used elsewhere.

[^1]: If it did happen, the app would crash and a JNI error message
      would be present in `adb logcat`, a'la:

          JNI DETECTED ERROR IN APPLICATION: use of deleted global reference 0x3d86