Skip to content

Commit

Permalink
[native, Mono.Android] GC bridge logging improvements
Browse files Browse the repository at this point in the history
Context: #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.
  • Loading branch information
jonpryor committed Nov 6, 2024
1 parent 4266c2b commit 4751b82
Show file tree
Hide file tree
Showing 5 changed files with 31 additions and 24 deletions.
8 changes: 7 additions & 1 deletion src/Mono.Android/Android.Runtime/AndroidRuntime.cs
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down
5 changes: 2 additions & 3 deletions src/native/monodroid/monodroid-glue.cc
Original file line number Diff line number Diff line change
Expand Up @@ -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)
{
Expand All @@ -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)
Expand Down Expand Up @@ -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

Expand Down
36 changes: 20 additions & 16 deletions src/native/monodroid/osbridge.cc
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}

Expand All @@ -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;
}

Expand Down Expand Up @@ -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);
Expand All @@ -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);
}
}

Expand All @@ -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 ();

Expand Down
2 changes: 0 additions & 2 deletions src/native/runtime-base/logger.cc
Original file line number Diff line number Diff line change
Expand Up @@ -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 */
}
4 changes: 2 additions & 2 deletions src/native/runtime-base/logger.hh
Original file line number Diff line number Diff line change
Expand Up @@ -30,6 +30,7 @@ namespace xamarin::android {
{
return _debugger_log_level;
}
#endif // def DEBUG

static void set_gc_spew_enabled (int yesno) noexcept
{
Expand All @@ -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;
Expand All @@ -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

0 comments on commit 4751b82

Please sign in to comment.