MONO GC log messages are not being printed in .net8.0-android

[jfichtner]

Android framework version

net8.0-android

Affected platform version

.NET 8.0.405

Description

My team is developing an application that was recently converted from Xamarin.Android and Xamarin.Forms to .net8-android and .NET MAUI. It seems that after this conversion, the MONO garbage collection logging cannot be configured using the same methods as were previously used. I had actually created issue #6483 for a similar issue I had previously when upgrading within the Xamarin.Android framework, which changed the default log level. In this ticket, @grendello provided me with the following adb command to set an environment variable that would turn this logging back on:

$ adb shell setprop debug.mono.log default,mono_log_level=info,mono_log_mask=gc

However, setting this environment variable no longer results in the MONO GC log messages being displayed, and I cannot find any information regarding how to configure this logging in .net8-android.

Steps to Reproduce

1. Set the debug.mono.log environment variable with the command
   $ adb shell setprop debug.mono.log default,mono_log_level=info,mono_log_mask=gc
2. Run an application compiled with .net8-android that causes a major MONO GC to occur
3. Observe logcat to see that MONO GC messages such as "GC_BRIDGE", "GC_MAJOR" and "GC_MAJOR_SWEEP" are not displayed in the log when ART GC's are observed (MONO GC's typically run sequentially with the ART GC's)

Did you find any workaround?

No

Relevant log output

01-01 00:30:20.460  1318  1460 I InitializationService: Forcing GC  (total elapsed time 15.419 s)
01-01 00:30:20.809  1318  1460 I art     : Starting a blocking GC Explicit
01-01 00:30:20.851  1318  1460 I art     : Explicit concurrent mark sweep GC freed 4217(513KB) AllocSpace objects, 1(20KB) LOS objects, 39% free, 2MB/3MB, paused 677us total 41.332ms
01-01 00:30:20.865  1318  1460 I IInitializationService: New initialization state: Initialized

[cdahlstrand]

I work on the same team with @jfichtner. We've found that, in addition to the logging, we are unable to configure the MONO garbage collector to run concurrently. We've tried setting the environment variables, like so:

Environment.SetEnvironmentVariable("MONO_GC_PARAMS", "major=marksweep-conc-par");

and we've tried configuring it through the .csproj file:

<AndroidEnableSGenConcurrent>true</AndroidEnableSGenConcurrent>

However, according to the struct returned by GC.GetGCMemoryInfo(), the Concurrent boolean is always false.

[jonpryor]

@jfichtner wrote that they were using:

adb shell setprop debug.mono.log default,mono_log_level=info,mono_log_mask=gc

This isn't correct; debug.mono.log does not support mono_log_level or mono_log_mask; those are environment variables, and should instead be set via debug.mono.env or @(AndroidEnvironment):

adb shell setprop debug.mono.env "'MONO_LOG_LEVEL=info|MONO_LOG_MASK=gc'"

(Note the double-quoting.)

With these set, a GC.Collect() invocation produces the following to my adb logcat:

net9_android_gc: Explicit concurrent mark compact GC freed 3233KB AllocSpace bytes, 3(60KB) LOS objects, 90% free, 2536KB/26MB, paused 103us,2.441ms total 13.650ms

If we add gc to debug.mono.log:

adb shell setprop debug.mono.log gc

and restart the app, we get slightly more:

I net9_android_gc: Explicit concurrent mark compact GC freed 64KB AllocSpace bytes, 0(0B) LOS objects, 90% free, 2504KB/26MB, paused 165us,3.741ms total 18.207ms
I monodroid-gc: GC cleanup summary: 1 objects tested - resurrecting 1.

If you set the debug.mono.gc property to 1:

adb shell setprop debug.mono.gc 1

then you'll see a bit more about the GC bridge:

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 0x7bd1494f30 [net9_android_gc::MainActivity]

This was added to .NET 9 with 32495f3.

[jonpryor]

That said…. We appear to have at least a couple of bugs here. (Doh!)

Firstly, debug.mono.env doesn't actually behave as expected; if I do:

adb shell setprop debug.mono.env "'BEGIN=1|MONO_LOG_LEVEL=debug|MONO_LOG_MASK=gc|JONP_TEST=1|END=2'"

then

android/src/native/mono/monodroid/monodroid-glue.cc

Line 1043 in 70bd636

log_debug (LOG_DEFAULT, "Env variable '{}' set to '{}'.", optional_string (name), optional_string (v));

doesn't log all the variables! It only sets MONO_LOG_LEVEL and MONO_LOG_MASK, to the wrong values:

D monodroid: Env variable 'MONO_LOG_LEVEL' set to 'info'.
D monodroid: Env variable 'MONO_LOG_MASK' set to 'gc'.

Which would make me think that debug.mono.log is entirely ignored, but if it has a malformed value -- end with | -- then it crashes, so…it is processed, and does the wrong thing.

Okay then…

Next is the @(AndroidEnvironment) build action. The problem is that it doesn't add environment variables properly either! If I add Env.txt with contents:

# ignore bom?
ASDF_BEGIN=1
MONO_GC_PARAMS=major=marksweep-conc-par
MONO_LOG_LEVEL=debug
ASDF_END=2

then only MONO_GC_PARAMS and MONO_LOG_LEVEL appear within obj/Debug/net9.0-android/android/environment.arm64-v8a.ll, both of which with the wrong value; they get the default values in <GeneratePackageManagerJava/>!

android/src/Xamarin.Android.Build.Tasks/Tasks/GeneratePackageManagerJava.cs

Line 135 in 70bd636

static readonly string[] defaultLogLevel = {"MONO_LOG_LEVEL", "info"};

We then return to the original comment, and a desire to see GC_MAJOR/etc. messages. The problem is that these messages are at debug verbosity, not info, and since we can't actually override MONO_LOG_LEVEL to debug, we can't see them!

We've horrifically broken things in this area. ☹️

[jfichtner]

Wow, thanks for looking into this @jonpryor! Sounds like there is a bit of a mess to clean up.

I have a couple of comments/questions...

This is neither here nor there, but the adb command that I quoted did work in xamarin.android, and it was suggested to me in issue #6483 by @grendello. Perhaps it's not the correct way to do it, though.

More importantly, what we REALLY need to to be able to turn on concurrent GC, and to somehow verify that concurrent GC is on and working. This is the reason we needed to enable the logs. As @cdahlstrand mentioned, it seems as though we cannot enable the concurrent GC. Can you confirm that there is actually no way to enable the concurrent GC in .NET8?

[jonpryor]

@jfichtner asked:

an you confirm that there is actually no way to enable the concurrent GC in .NET8?

.NET 8. Oh. I was testing on .NET 9…

.NET 8 appears to be "better", but not perfect. I still can't get it to generate GC_MAJOR messages.

Where .NET 8 is better for me than .NET 9 is when using @(AndroidEnvironment): in .NET 8, my environment file can contain the line:

MONO_GC_PARAMS=major=marksweep-conc-par

and when I view obj/Debug/net8.0-android/android/environment.arm64-v8a.ll, I see:

@.env.6 = private unnamed_addr constant [15 x i8] c"MONO_GC_PARAMS\00", align 1 
@.env.7 = private unnamed_addr constant [25 x i8] c"major=marksweep-conc-par\00", align 1

showing that MONO_GC_PARAMS should be set to major=marksweep-conc-par. Additionally, with debug.mono.log all, my adb logcat contains:

I monodroid: Setting environment variable 'MONO_GC_PARAMS' to 'major=marksweep-conc-par'

Neither of those was true in .NET 9: with .NET 9, the contents and/or updates within my environment file were not present in environment.arm64-v8a.ll.

All that said, while MONO_GC_PARAMS=major=marksweep-conc-par should enable the parallel concurrent GC, I'm not confident that it is without the presence of the Mono GC messages, which I can't see.

I have found that we can set e.g. MONO_GC_DEBUG=9, and mono-gc messages will appear in adb logcat:

V mono-gc : 2025-02-12 16:23:27 Start major collection 3
V mono-gc : 2025-02-12 16:23:27 restarted (pause time: 1859 usec, max: 1876 usec)

None of the messages appear to state which GC parameters are in use.

[akoeplinger]

However, according to the struct returned by GC.GetGCMemoryInfo(), the Concurrent boolean is always false.

Just FYI, we don't populate the _concurrent flag in the struct on Mono so it will always be false: https://github.com/dotnet/runtime/blob/e417d2bbce348b5f06b2bfe9ed3ab0b190379f24/src/mono/System.Private.CoreLib/src/System/GC.Mono.cs#L251-L260

The concurrent sgen is enabled by default now:

android/src/Xamarin.Android.Build.Tasks/Microsoft.Android.Sdk/targets/Microsoft.Android.Sdk.DefaultProperties.targets

Line 9 in 70bd636

<AndroidEnableSGenConcurrent Condition=" '$(AndroidEnableSGenConcurrent)' == '' ">true</AndroidEnableSGenConcurrent>

However that property basically also sets MONO_GC_PARAMS so depending on the above findings I wonder what the runtime defaults to if that's not set.

[jfichtner]

So am I understanding correctly that there is no way to detect if using the AndroidEnvironment file to turn on concurrent GC actually works or not in net8-android?