[CoreCLR] FastTiming::start_event corrupts the heap when debug.mono.log=timing (Scudo "invalid chunk state when deallocating")

[alexyakunin]

Android application type

.NET Android (net11.0-android), .NET MAUI Blazor Hybrid app

Affected platform version

.NET 11 preview 7 SDK (11.0.100-preview.7.26381.103), Android workload 37.0.0-preview.7.2131.
Also reproduced against a build using runtime pack 11.0.0-preview.6.26359.118.
Device: Samsung SM-S948U1, Android 16 (SDK 36), arm64-v8a. CoreCLR (not Mono).

Description

When debug.mono.log=timing is set, FastTiming::start_event corrupts the heap on a
multi-threaded app, and the process is aborted by Scudo:

Abort message: 'Scudo ERROR: invalid chunk state when deallocating address 0x200006eb724b000'
signal 6 (SIGABRT), code -1 (SI_QUEUE)

I have 5 such crashes from one device over 6 days, in two independently built apps
(a Release/App-Store build and a dev build). The crashing native frame is always
TypeMapper::java_to_managed or TypeMapper::managed_to_java, and it always
resolves to the events.reserve() call inside FastTiming::start_event.

Looking at start_event on main
(src/native/common/include/runtime-base/timing-internal.hh), there are two
structural problems, independent of each other:

void start_event (TimingEventKind kind = TimingEventKind::Unspecified) noexcept
{
    size_t index = next_event_index.fetch_add (1);

    if (index >= events.capacity ()) [[unlikely]] {
        StartupAwareLock lock (event_vector_realloc_mutex);
        if (index >= events.size ()) {                 // (1)
            size_t old_size = events.capacity ();
            events.reserve (old_size << 1);
            log_warnf (LOG_TIMING, "Reallocated timing event buffer from %zu to %zu", old_size, events.capacity ());
        }
    }

    open_sequences.push (index);
    TimingEvent &ev = events[index];                   // (2)
    ev.start = get_time ();
    ev.kind = kind;
    ev.before_managed = MonodroidState::is_startup_in_progress ();
    ev.more_info = nullptr;
}

(1) The inner double-checked-locking guard can never be false.
events is only ever grown with reserve() — there is no resize(), push_back()
or emplace_back() on it anywhere; it is used as a pre-allocated array indexed by an
atomic counter. So events.size() stays 0 for the lifetime of the process, and
index >= events.size() is index >= 0, which is unconditionally true for size_t.

The comment on that line describes the intent ("don't increase unnecessarily, if
another thread has already done that"), but the check cannot ever short-circuit. Every
thread that passes the outer index >= events.capacity() test will reallocate, even
when another thread has just grown the buffer. It should almost certainly be comparing
against events.capacity().

(2) Element access is entirely outside the mutex.
TimingEvent &ev = events[index]; and the subsequent field writes are outside the
StartupAwareLock scope, and end_event() does events[*index].end = get_time ();
with no lock at all. So while one thread is inside reserve() — which allocates a new
block, then deallocates the old one — other threads can still be dereferencing
__begin_ + index * sizeof(TimingEvent) into the block being freed. That is a
use-after-free by construction; the double-free/heap-corruption abort is the visible
consequence.

Note that fixing the lock alone would not fix this: serializing the reallocation still
leaves readers touching a buffer that is being freed underneath them.

Steps to Reproduce

1. Build a net11.0-android app that does a meaningful amount of multi-threaded
   JNI work. In my case a MAUI Blazor Hybrid app whose WebViewClient.ShouldInterceptRequest
   override runs on Chromium's ThreadPoolForegroundWorker threads, so several threads
   hit the typemap concurrently and continuously.
2. adb shell setprop debug.mono.log timing
3. Launch the app and use it normally.
4. The timing buffer doubles 4096 → 8192 → 16384 → …; the process aborts, usually
   around the third or fourth growth.

It is a race, so it is not perfectly deterministic — mine crashed at process uptimes
ranging from 38 seconds to ~8 hours.

Did you find any workaround?

Yes — clear the property (adb shell setprop debug.mono.log "", or reboot, since it is
not a persist.* property). With FastTiming::is_enabled false the whole code path is
unreachable and the crashes stop. No app change is needed.

Relevant log output

The clearest evidence is the moment of the abort. One buffer-growth message, then
three different threads reporting a bad free of the same address in the same
millisecond:

08-19 03:52:45.846  9932 24571 W monodroid-timing: Reallocated timing event buffer from 16384 to 0
08-19 03:52:45.846  9932 24571 I monodroid-timing: [0/6] Typemap.managed_to_java: end, total time; elapsed: 0:0::313
08-19 03:52:45.846  9932 24570 I monodroid-timing: [0/6] Typemap.managed_to_java: end, total time; elapsed: 0:0::208
08-19 03:52:45.846  9932 24563 I scudo   : Scudo ERROR: invalid chunk state when deallocating address 0x200006eb724b000
08-19 03:52:45.846  9932 24562 I scudo   : Scudo ERROR: invalid chunk state when deallocating address 0x200006eb724b000
08-19 03:52:45.846  9932 24549 I scudo   : Scudo ERROR: invalid chunk state when deallocating address 0x200006eb724b000

(The to 0 in that message is this app's older runtime printing events.size();
current main prints capacity() after #12153, so that part is already fixed.)

Tombstone, symbolized against the shipped libmonodroid.so — BuildId verified to match
the tombstone, disassembled with NDK 27 llvm-objdump. Frame #6's return address is a
bl to std::vector<xamarin::android::TimingEvent, …>::reserve(unsigned long),
immediately followed by the adrp/add of the "Reallocated timing event buffer …"
format string and the bl to log_warnf — i.e. it is unambiguously the reserve()
call in start_event:

signal 6 (SIGABRT), code -1 (SI_QUEUE), fault addr --------
Abort message: 'Scudo ERROR: invalid chunk state when deallocating address 0x200006eb724b000'
backtrace:
      #00 pc 00000000000757a8  /apex/com.android.runtime/lib64/bionic/libc.so (abort+160)
      #01 pc 000000000005cf50  /apex/com.android.runtime/lib64/bionic/libc.so (scudo::die()+12)
      #02 pc 000000000005d9b0  /apex/com.android.runtime/lib64/bionic/libc.so (scudo::reportRawError(char const*)+32)
      #03 pc 000000000005d924  /apex/com.android.runtime/lib64/bionic/libc.so (scudo::ScopedErrorReport::~ScopedErrorReport()+16)
      #04 pc 000000000005dd18  /apex/com.android.runtime/lib64/bionic/libc.so (scudo::reportInvalidChunkState(scudo::AllocatorAction, void const*)+120)
      #05 pc 000000000005f7d0  /apex/com.android.runtime/lib64/bionic/libc.so (scudo::Allocator<scudo::AndroidNormalConfig, &scudo_malloc_postinit>::deallocate(void*, scudo::Chunk::Origin, unsigned long, unsigned long)+296)
      #06 pc 000000000008ca34  .../lib/arm64/libmonodroid.so (xamarin::android::TypeMapper::java_to_managed(char const*, char const**, unsigned int*)+5752)

Managed stack for the same crash — this is just the highest-frequency typemap caller in
my app; 3 of my 5 crashes are in managed_to_java instead, so the caller is incidental:

Fatal error. Got a SIGABRT while executing native code.
   at Android.Runtime.RuntimeNativeMethods.<clr_typemap_java_to_managed>g____PInvoke|24_0(Byte*, IntPtr*, UInt32*)
   at Java.Interop.TypeManager.GetJavaToManagedTypeCore(System.String)
   at Android.Runtime.AndroidTypeManager+<GetTypesForSimpleReference>d__6.MoveNext()
   at Java.Interop.JniRuntime+ReflectionJniTypeManager+<GetReflectionConstructibleTypes>d__20.MoveNext()
   at Microsoft.Android.Runtime.AndroidReflectionJniValueManager.CreatePeerInstance(...)
   at Java.Lang.Object._GetObject[[System.__Canon, ...]](IntPtr, Android.Runtime.JniHandleOwnership)
   at ActualChat.App.Maui.AndroidWebViewClient.ShouldInterceptRequest(Android.Webkit.WebView, Android.Webkit.IWebResourceRequest)
   at Android.Webkit.WebViewClient.__n_ShouldInterceptRequest_...(IntPtr, IntPtr, IntPtr, IntPtr)

One thing I could not explain

If StartupAwareLock is active at this point — and it should be, since
MonodroidState::mark_startup_done() runs at the end of
Host::Java_mono_android_Runtime_initInternal and these crashes happen long after
startup — then the reallocations should be serialized, and I would expect to see three
separate "Reallocated timing event buffer" messages rather than one. Seeing one message
alongside three same-address deallocation failures is what I actually observe, in all
five crashes.

I could not reconcile that from the binary alone, so I am reporting the observation
rather than a theory about it. Defect (2) above — unsynchronized events[index] access
racing against the reserve() that frees the old buffer — is sufficient to corrupt the
chunk regardless of whether the reallocation itself is serialized, and may well be the
whole story.

Happy to provide the full tombstones, the complete monodroid-timing logcat, or run a
patched build if that would help.