From 4751b823dbd3dbedfdd9b76d1e94b534957ae047 Mon Sep 17 00:00:00 2001 From: Jonathan Pryor Date: Wed, 6 Nov 2024 08:12:04 -0500 Subject: [PATCH] [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. 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 "Promote" `LOG_GC` to work in Release builds as well. This means that both: adb shell setprop debug.mono.log gc adb shell setprop debug.mono.gc 1 will work with `libmono-android.release.so`, i.e. Release builds of apps. Update `OSBridge::gc_cross_references()` log the `handle` field of bridged instances. --- .../Android.Runtime/AndroidRuntime.cs | 8 ++++- src/native/monodroid/monodroid-glue.cc | 5 ++- src/native/monodroid/osbridge.cc | 36 ++++++++++--------- src/native/runtime-base/logger.cc | 2 -- src/native/runtime-base/logger.hh | 4 +-- 5 files changed, 31 insertions(+), 24 deletions(-) diff --git a/src/Mono.Android/Android.Runtime/AndroidRuntime.cs b/src/Mono.Android/Android.Runtime/AndroidRuntime.cs index fb3fc8703ee..e6de9e23399 100644 --- a/src/Mono.Android/Android.Runtime/AndroidRuntime.cs +++ b/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. diff --git a/src/native/monodroid/monodroid-glue.cc b/src/native/monodroid/monodroid-glue.cc index 03c8ead558e..790e138b2f1 100644 --- a/src/native/monodroid/monodroid-glue.cc +++ b/src/native/monodroid/monodroid-glue.cc @@ -965,7 +965,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 +973,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 +1429,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 diff --git a/src/native/monodroid/osbridge.cc b/src/native/monodroid/osbridge.cc index 08b4f80b79d..d1578be7ecb 100644 --- a/src/native/monodroid/osbridge.cc +++ b/src/native/monodroid/osbridge.cc @@ -461,18 +461,16 @@ 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); + " at [[gc: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; - mono_field_get_value (obj, bridge_info->handle, &old_handle); - } 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 +493,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 +902,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 +910,18 @@ 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; + if (bridge_info != nullptr) { + mono_field_get_value (obj, bridge_info->handle, &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", obj, mono_class_get_namespace (klass), - mono_class_get_name (klass)); + mono_class_get_name (klass), + handle); } } @@ -925,7 +930,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 (); diff --git a/src/native/runtime-base/logger.cc b/src/native/runtime-base/logger.cc index 4f39b25ff6b..8d4635cef56 100644 --- a/src/native/runtime-base/logger.cc +++ b/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 */ } diff --git a/src/native/runtime-base/logger.hh b/src/native/runtime-base/logger.hh index 2111c628bdd..6246b929937 100644 --- a/src/native/runtime-base/logger.hh +++ b/src/native/runtime-base/logger.hh @@ -30,6 +30,7 @@ namespace xamarin::android { { return _debugger_log_level; } +#endif // def DEBUG static void set_gc_spew_enabled (int yesno) noexcept { @@ -40,7 +41,6 @@ namespace xamarin::android { { 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 int _gc_spew_enabled = 0; }; } #endif