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

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

Author: jonpryor

src/Mono.Android/Android.Runtime/AndroidRuntime.cs

@@ -846,7 +846,13 @@ public override void FinalizePeer (IJavaPeerable value)
 				throw new ArgumentNullException (nameof (value));
 
 			if (Logger.LogGlobalRef) {
-				RuntimeNativeMethods._monodroid_gref_log ($"Finalizing handle {value.PeerReference}\n");
+				RuntimeNativeMethods._monodroid_gref_log (
+						string.Format (CultureInfo.InvariantCulture,
+							"Finalizing Instance.Type={0} PeerReference={1} IdentityHashCode=0x{2:x} Instance=0x{3:x}",
+							value.GetType ().ToString (),
+							value.PeerReference.ToString (),
+							value.JniIdentityHashCode,
+							RuntimeHelpers.GetHashCode (value)));
 			}
 
 			// FIXME: need hash cleanup mechanism.

src/native/monodroid/monodroid-glue.cc

@@ -779,15 +779,19 @@ MonodroidRuntime::lookup_bridge_info (MonoClass *klass, const OSBridge::MonoJava
 	info->handle            = mono_class_get_field_from_name (info->klass, const_cast<char*> ("handle"));
 	info->handle_type       = mono_class_get_field_from_name (info->klass, const_cast<char*> ("handle_type"));
 	info->refs_added        = mono_class_get_field_from_name (info->klass, const_cast<char*> ("refs_added"));
+	info->key_handle        = mono_class_get_field_from_name (info->klass, const_cast<char*> ("key_handle"));
+
+	// key_handle is optional, as Java.Interop.JavaObject doesn't currently have it
 	if (info->klass == nullptr || info->handle == nullptr || info->handle_type == nullptr || info->refs_added == nullptr) {
 		Helpers::abort_application (
 			Util::monodroid_strdup_printf (
-				"The type `%s.%s` is missing required instance fields! handle=%p handle_type=%p refs_added=%p",
+				"The type `%s.%s` is missing required instance fields! handle=%p handle_type=%p refs_added=%p key_handle=%p",
 				type->_namespace,
 				type->_typename,
 				info->handle,
 				info->handle_type,
-				info->refs_added
+				info->refs_added,
+				info->key_handle
 			)
 		);
 	}
@@ -965,7 +969,6 @@ MonodroidRuntime::propagate_uncaught_exception (JNIEnv *env, jobject javaThread,
 	mono_runtime_invoke (method, nullptr, args, nullptr);
 }
 
-#if DEBUG
 static void
 setup_gc_logging (void)
 {
@@ -974,7 +977,6 @@ setup_gc_logging (void)
 		log_categories |= LOG_GC;
 	}
 }
-#endif
 
 inline void
 MonodroidRuntime::set_environment_variable_for_directory (const char *name, jstring_wrapper &value, bool createDirectory, mode_t mode)
@@ -1431,8 +1433,9 @@ MonodroidRuntime::Java_mono_android_Runtime_initInternal (JNIEnv *env, jclass kl
 
 	Logger::init_reference_logging (AndroidSystem::get_primary_override_dir ());
 
-#if DEBUG
 	setup_gc_logging ();
+
+#if DEBUG
 	set_debug_env_vars ();
 #endif
 

src/native/monodroid/osbridge.cc

@@ -47,6 +47,7 @@ OSBridge::MonoJavaGCBridgeInfo OSBridge::empty_bridge_info = {
 	nullptr,
 	nullptr,
 	nullptr,
+	nullptr,
 	nullptr
 };
 
@@ -461,18 +462,31 @@ OSBridge::take_global_ref_jni (JNIEnv *env, MonoObject *obj)
 		_monodroid_gref_log_new (weak, get_object_ref_type (env, weak),
 				handle, get_object_ref_type (env, handle),
 				"finalizer", gettid (),
-				"take_global_ref_jni", 0);
-	}
-	_monodroid_weak_gref_delete (weak, get_object_ref_type (env, weak),
-			"finalizer", gettid (), "take_global_ref_jni", 0);
-	env->DeleteWeakGlobalRef (weak);
-	if (!handle) {
-		void *old_handle = nullptr;
+				"   at [[gc:take_global_ref_jni]]", 0);
+	} else if (Logger::gc_spew_enabled ()) [[unlikely]] {
+		void   *key_handle  = nullptr;
+		if (bridge_info->key_handle) {
+			mono_field_get_value (obj, bridge_info->key_handle, &key_handle);
+		}
 
-		mono_field_get_value (obj, bridge_info->handle, &old_handle);
+		MonoClass *klass = mono_object_get_class (obj);
+		char *message = Util::monodroid_strdup_printf (
+				"handle %p/W; key_handle %p; MCW type: `%s.%s`: was collected by a Java GC",
+				weak,
+				key_handle,
+				mono_class_get_namespace (klass),
+				mono_class_get_name (klass));
+		_monodroid_gref_log (message);
+		free (message);
 	}
+
 	mono_field_set_value (obj, bridge_info->handle, &handle);
 	mono_field_set_value (obj, bridge_info->handle_type, &type);
+
+	_monodroid_weak_gref_delete (weak, get_object_ref_type (env, weak),
+			"finalizer", gettid (), "   at [[gc:take_global_ref_jni]]", 0);
+	env->DeleteWeakGlobalRef (weak);
+
 	return handle != nullptr;
 }
 
@@ -495,13 +509,14 @@ OSBridge::take_weak_global_ref_jni (JNIEnv *env, MonoObject *obj)
 	weak = env->NewWeakGlobalRef (handle);
 	_monodroid_weak_gref_new (handle, get_object_ref_type (env, handle),
 			weak, get_object_ref_type (env, weak),
-			"finalizer", gettid (), "take_weak_global_ref_jni", 0);
+			"finalizer", gettid (), "   at [[gc:take_weak_global_ref_jni]]", 0);
 
-	_monodroid_gref_log_delete (handle, get_object_ref_type (env, handle),
-			"finalizer", gettid (), "take_weak_global_ref_jni", 0);
-	env->DeleteGlobalRef (handle);
 	mono_field_set_value (obj, bridge_info->handle, &weak);
 	mono_field_set_value (obj, bridge_info->handle_type, &type);
+
+	_monodroid_gref_log_delete (handle, get_object_ref_type (env, handle),
+			"finalizer", gettid (), "   at [[gc:take_weak_global_ref_jni]]", 0);
+	env->DeleteGlobalRef (handle);
 	return 1;
 }
 
@@ -903,7 +918,6 @@ OSBridge::gc_cross_references (int num_sccs, MonoGCBridgeSCC **sccs, int num_xre
 	if (gc_disabled)
 		return;
 
-#if DEBUG
 	if (Logger::gc_spew_enabled ()) {
 		int i, j;
 		log_info (LOG_GC, "cross references callback invoked with %d sccs and %d xrefs.", num_sccs, num_xrefs);
@@ -912,11 +926,23 @@ OSBridge::gc_cross_references (int num_sccs, MonoGCBridgeSCC **sccs, int num_xre
 			log_info (LOG_GC, "group %d with %d objects", i, sccs [i]->num_objs);
 			for (j = 0; j < sccs [i]->num_objs; ++j) {
 				MonoObject *obj = sccs [i]->objs [j];
+
+				MonoJavaGCBridgeInfo    *bridge_info    = get_gc_bridge_info_for_object (obj);
+				jobject handle      = 0;
+				void   *key_handle  = nullptr;
+				if (bridge_info != nullptr) {
+					mono_field_get_value (obj, bridge_info->handle, &handle);
+					if (bridge_info->key_handle != nullptr) {
+						mono_field_get_value (obj, bridge_info->key_handle, &key_handle);
+					}
+				}
 				MonoClass *klass = mono_object_get_class (obj);
-				log_info (LOG_GC, "\tobj %p [%s::%s]",
+				log_info (LOG_GC, "\tobj %p [%s::%s] handle %p key_handle %p",
 						obj,
 						mono_class_get_namespace (klass),
-						mono_class_get_name (klass));
+						mono_class_get_name (klass),
+						handle,
+						key_handle);
 			}
 		}
 
@@ -925,7 +951,6 @@ OSBridge::gc_cross_references (int num_sccs, MonoGCBridgeSCC **sccs, int num_xre
 				log_info_nocheck (LOG_GC, "xref [%d] %d -> %d", i, xrefs [i].src_scc_index, xrefs [i].dst_scc_index);
 		}
 	}
-#endif
 
 	env = ensure_jnienv ();
 

src/native/monodroid/osbridge.hh

@@ -40,6 +40,7 @@ namespace xamarin::android::internal
 			MonoClassField  *handle;
 			MonoClassField  *handle_type;
 			MonoClassField  *refs_added;
+			MonoClassField  *key_handle;
 		};
 
 		// add_reference can work with objects which are either MonoObjects with java peers, or raw jobjects

src/native/runtime-base/logger.cc

@@ -239,8 +239,6 @@ Logger::init_logging_categories (char*& mono_log_mask, char*& mono_log_level) no
 #endif
 	}
 
-#if DEBUG
 	if ((log_categories & LOG_GC) != 0)
-		_gc_spew_enabled = 1;
-#endif  /* DEBUG */
+		_gc_spew_enabled = true;
 }

src/native/runtime-base/logger.hh

@@ -30,17 +30,17 @@ namespace xamarin::android {
 		{
 			return _debugger_log_level;
 		}
+#endif // def DEBUG
 
-		static void set_gc_spew_enabled (int yesno) noexcept
+		static void set_gc_spew_enabled (bool yesno) noexcept
 		{
 			_gc_spew_enabled = yesno;
 		}
 
-		static int gc_spew_enabled () noexcept
+		static bool gc_spew_enabled () noexcept
 		{
 			return _gc_spew_enabled;
 		}
-#endif // def DEBUG
 
 	private:
 		static bool set_category (std::string_view const& name, internal::string_segment& arg, unsigned int entry, bool arg_starts_with_name = false) noexcept;
@@ -50,8 +50,8 @@ namespace xamarin::android {
 #if defined(DEBUG)
 		static inline bool _got_debugger_log_level = false;
 		static inline int _debugger_log_level = 0;
-		static inline int _gc_spew_enabled = 0;
 #endif // def DEBUG
+		static inline bool _gc_spew_enabled = false;
 	};
 }
 #endif