From bd7c9df5f7db5bc2c2b7c84d3f812e4aa05b9aa3 Mon Sep 17 00:00:00 2001 From: Jonathan Peppers Date: Wed, 19 Aug 2026 14:45:10 -0500 Subject: [PATCH] Fix FastTiming concurrent event storage Replace the reallocating event vector with stable chunks, publish completed events safely for concurrent dumps, and fix startup-aware lock ownership. Add a CoreCLR device regression that grows and dumps fast timing events. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> Copilot-Session: d40daefe-fd3f-4c2d-96d9-9c91a6b0c5c2 --- .../include/runtime-base/monodroid-state.hh | 4 +- .../runtime-base/startup-aware-lock.hh | 9 +- .../include/runtime-base/timing-internal.hh | 193 +++++++++--------- .../common/runtime-base/timing-internal.cc | 8 +- .../mono/runtime-base/monodroid-state.hh | 4 +- .../mono/runtime-base/startup-aware-lock.hh | 9 +- .../Tests/FastTimingTests.cs | 84 ++++++++ 7 files changed, 200 insertions(+), 111 deletions(-) create mode 100644 tests/MSBuildDeviceIntegration/Tests/FastTimingTests.cs diff --git a/src/native/clr/include/runtime-base/monodroid-state.hh b/src/native/clr/include/runtime-base/monodroid-state.hh index 283040d4992..998f6ffb2e4 100644 --- a/src/native/clr/include/runtime-base/monodroid-state.hh +++ b/src/native/clr/include/runtime-base/monodroid-state.hh @@ -7,12 +7,12 @@ namespace xamarin::android public: static auto is_startup_in_progress () noexcept -> bool { - return startup_in_progress; + return __atomic_load_n (&startup_in_progress, __ATOMIC_ACQUIRE); } static void mark_startup_done () noexcept { - startup_in_progress = false; + __atomic_store_n (&startup_in_progress, false, __ATOMIC_RELEASE); } private: diff --git a/src/native/clr/include/runtime-base/startup-aware-lock.hh b/src/native/clr/include/runtime-base/startup-aware-lock.hh index 8b869151b61..8d980339f55 100644 --- a/src/native/clr/include/runtime-base/startup-aware-lock.hh +++ b/src/native/clr/include/runtime-base/startup-aware-lock.hh @@ -16,17 +16,15 @@ namespace xamarin::android // During startup we run without threads, do nothing return; } - lock.lock (); + owns_lock = true; } ~StartupAwareLock () { - if (MonodroidState::is_startup_in_progress ()) { - return; + if (owns_lock) { + lock.unlock (); } - - lock.unlock (); } StartupAwareLock (StartupAwareLock const&) = delete; @@ -36,5 +34,6 @@ namespace xamarin::android private: std::mutex& lock; + bool owns_lock = false; }; } diff --git a/src/native/common/include/runtime-base/timing-internal.hh b/src/native/common/include/runtime-base/timing-internal.hh index 25fdc20b3cd..ae986be6ea8 100644 --- a/src/native/common/include/runtime-base/timing-internal.hh +++ b/src/native/common/include/runtime-base/timing-internal.hh @@ -4,17 +4,13 @@ #include #include #include -#include #include #include #include -#include -#include #include #include #include #include -#include #if defined(XA_HOST_MONOVM) #include @@ -26,7 +22,7 @@ using namespace xamarin::android::internal; #endif #include -#include +#include #include #include @@ -66,6 +62,7 @@ namespace xamarin::android { time_point end; TimingEventKind kind; std::string *more_info = nullptr; + bool complete = false; }; class FastTiming; @@ -73,23 +70,17 @@ namespace xamarin::android { class FastTiming final { -#if defined(XA_HOST_MONOVM) - using mutex = xamarin::android::mutex; -#else - using mutex = std::mutex; -#endif - enum class SequenceError + // Number of TimingEvent entries in each allocation. It's an arbitrary + // value large enough to avoid allocating additional chunks during + // normal application startup. + static constexpr size_t EVENT_CHUNK_SIZE = 4096uz; + + struct TimingEventChunk { - EmptyStack, - InvalidIndex, + TimingEvent events [EVENT_CHUNK_SIZE]; + TimingEventChunk *next = nullptr; }; - // Number of TimingEvent entries in the event vector allocated at the - // time of class instantiation. It's an arbitrary value, but it should - // be large enough to not require any dynamic reallocation of memory at - // the run time. - static constexpr size_t INITIAL_EVENT_VECTOR_SIZE = 4096uz; - // defaults static constexpr bool default_fast_timing_enabled = false; static constexpr bool default_log_to_file = false; @@ -104,17 +95,30 @@ namespace xamarin::android { protected: void configure_for_use () noexcept { - events.reserve (INITIAL_EVENT_VECTOR_SIZE); + first_event_chunk = new TimingEventChunk; } public: constexpr FastTiming () noexcept {} + ~FastTiming () + { + TimingEventChunk *chunk = first_event_chunk; + while (chunk != nullptr) { + TimingEventChunk *next = chunk->next; + for (TimingEvent &event : chunk->events) { + delete event.more_info; + } + delete chunk; + chunk = next; + } + } + [[gnu::always_inline]] static auto enabled () noexcept -> bool { - return is_enabled; + return __atomic_load_n (&is_enabled, __ATOMIC_ACQUIRE); } [[gnu::always_inline]] @@ -154,6 +158,7 @@ namespace xamarin::android { get_time_overhead.end = get_time (); init_time.end = get_time (); + __atomic_store_n (&is_enabled, true, __ATOMIC_RELEASE); if (!immediate_logging) { return; } @@ -241,35 +246,15 @@ namespace xamarin::android { format_and_log (event); } - // std::vector isn't used in a conventional manner here. We treat it as if it was a standard array and we - // don't take advantage of any emplacement functionality, merely using vector's ability to resize itself when - // needed. The reason for this is speed - we can atomically increase index into the array and relatively - // quickly check whether it's within the boundaries. We can then safely use thus indexed element without - // worrying about concurrency. Emplacing a new element in the vector would require holding the mutex, something - // that's fairly costly and has unpredictable effect on time spent acquiring and holding the lock (the OS can - // preempt us at this point) [[gnu::always_inline]] 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 ()) { // don't increase unnecessarily, if another thread has already done that - // Double the vector size. We should, in theory, check for integer overflow here, but it's more - // likely we'll run out of memory way, way, way before that happens - 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]; + TimingEvent &ev = get_event (index); ev.start = get_time (); ev.kind = kind; ev.before_managed = MonodroidState::is_startup_in_progress (); - ev.more_info = nullptr; + open_sequences.push (&ev); } // If `uses_more_info` is `true`, the caller **MUST** call `add_more_info`, since the @@ -277,21 +262,18 @@ namespace xamarin::android { [[gnu::always_inline]] void end_event (bool uses_more_info = false, bool skip_log = false) noexcept { - std::expected index; - if (!uses_more_info) [[likely]] { - index = pop_valid_sequence_index (); - } else { - index = get_valid_sequence_index (); - } - - if (!index.has_value ()) [[unlikely]] { + TimingEvent *event = uses_more_info ? get_sequence_event () : pop_sequence_event (); + if (event == nullptr) [[unlikely]] { log_warn (LOG_TIMING, "FastTiming::end_event called without prior FastTiming::start_event called"sv); return; } - events[*index].end = get_time (); + event->end = get_time (); + if (!uses_more_info) [[likely]] { + __atomic_store_n (&event->complete, true, __ATOMIC_RELEASE); + } if (!skip_log) [[likely]] { - log (events[*index], uses_more_info /* skip_log_if_more_info_missing */); + log (*event, uses_more_info /* skip_log_if_more_info_missing */); } } @@ -299,40 +281,43 @@ namespace xamarin::android { [[gnu::always_inline]] void add_more_info (string_base const& str) noexcept { - auto index = pop_valid_sequence_index (); - if (!index.has_value ()) [[unlikely]] { + TimingEvent *event = pop_sequence_event (); + if (event == nullptr) [[unlikely]] { log_warn (LOG_TIMING, "FastTiming::add_more_info called without prior FastTiming::start_event called"sv); return; } - events[*index].more_info = new std::string (str.get (), str.length ()); - log (events[*index], false /* skip_log_if_more_info_missing */); + event->more_info = new std::string (str.get (), str.length ()); + __atomic_store_n (&event->complete, true, __ATOMIC_RELEASE); + log (*event, false /* skip_log_if_more_info_missing */); } [[gnu::always_inline]] void add_more_info (const char* str) noexcept { - auto index = pop_valid_sequence_index (); - if (!index.has_value ()) [[unlikely]] { + TimingEvent *event = pop_sequence_event (); + if (event == nullptr) [[unlikely]] { log_warn (LOG_TIMING, "FastTiming::add_more_info called without prior FastTiming::start_event called"sv); return; } - events[*index].more_info = new std::string (str); - log (events[*index], false /* skip_log_if_more_info_missing */); + event->more_info = new std::string (str); + __atomic_store_n (&event->complete, true, __ATOMIC_RELEASE); + log (*event, false /* skip_log_if_more_info_missing */); } [[gnu::always_inline]] void add_more_info (std::string_view const& str) noexcept { - auto index = pop_valid_sequence_index (); - if (!index.has_value ()) [[unlikely]] { + TimingEvent *event = pop_sequence_event (); + if (event == nullptr) [[unlikely]] { log_warn (LOG_TIMING, "FastTiming::add_more_info called without prior FastTiming::start_event called"sv); return; } - events[*index].more_info = new std::string (str); - log (events[*index], false /* skip_log_if_more_info_missing */); + event->more_info = new std::string (str); + __atomic_store_n (&event->complete, true, __ATOMIC_RELEASE); + log (*event, false /* skip_log_if_more_info_missing */); } void dump () noexcept; @@ -345,7 +330,7 @@ namespace xamarin::android { std::enable_if_t()(std::declval()...))>, decltype(std::declval()(std::declval()...))> static time_call (std::string_view const& name, F&& fn, Args... args) noexcept { - if (!is_enabled) [[likely]] { + if (!enabled ()) [[likely]] { return fn (std::forward(args)...); } @@ -360,7 +345,7 @@ namespace xamarin::android { std::enable_if_t()(std::declval()...))>, void> static time_call (std::string_view const& name, F&& fn, Args... args) noexcept { - if (!is_enabled) [[likely]] { + if (!enabled ()) [[likely]] { fn (std::forward(args)...); return; } @@ -391,34 +376,24 @@ namespace xamarin::android { void dump (size_t entries, bool indent, std::function line_writer) noexcept; [[gnu::always_inline]] - auto get_valid_sequence_index () noexcept -> std::expected + auto get_sequence_event () noexcept -> TimingEvent* { if (open_sequences.empty ()) [[unlikely]] { - return std::unexpected (SequenceError::EmptyStack); - } - - size_t index = open_sequences.top (); - if (!is_valid_event_index (index)) [[unlikely]] { - return std::unexpected (SequenceError::InvalidIndex); + return nullptr; } - return index; + return open_sequences.top (); } [[gnu::always_inline]] - auto pop_valid_sequence_index () noexcept -> std::expected + auto pop_sequence_event () noexcept -> TimingEvent* { - auto ret = get_valid_sequence_index (); - if (ret.has_value ()) [[likely]] { + TimingEvent *event = get_sequence_event (); + if (event != nullptr) [[likely]] { open_sequences.pop (); - return ret; } - if (ret.error () != SequenceError::EmptyStack) { - open_sequences.pop (); - } - - return ret; + return event; } template [[gnu::always_inline]] @@ -506,24 +481,56 @@ namespace xamarin::android { void parse_options (dynamic_local_property_string const& value) noexcept; static void really_initialize (bool log_immediately) noexcept; - [[gnu::always_inline, nodiscard]] - auto is_valid_event_index (size_t index, std::source_location sloc = std::source_location::current ()) const noexcept -> bool + [[gnu::always_inline]] + auto get_event (size_t index) noexcept -> TimingEvent& { - if (index >= events.capacity ()) [[unlikely]] { - log_warnf (LOG_TIMING, "Invalid event index passed to method '%s'", optional_string (sloc.function_name ())); - return false; + size_t chunk_index = index / EVENT_CHUNK_SIZE; + size_t current_chunk_index = cached_event_chunk_index; + TimingEventChunk *chunk = cached_event_chunk; + if (chunk == nullptr || chunk_index < current_chunk_index) { + current_chunk_index = 0uz; + chunk = first_event_chunk; + } + + for (size_t i = current_chunk_index; i < chunk_index; ++i) { + TimingEventChunk *next = __atomic_load_n (&chunk->next, __ATOMIC_ACQUIRE); + if (next == nullptr) [[unlikely]] { + TimingEventChunk *new_chunk = new TimingEventChunk; + if (__atomic_compare_exchange_n ( + &chunk->next, + &next, + new_chunk, + false /* weak */, + __ATOMIC_RELEASE, + __ATOMIC_ACQUIRE + )) { + next = new_chunk; + log_warnf ( + LOG_TIMING, + "Allocated timing event buffer from %zu to %zu", + (i + 1uz) * EVENT_CHUNK_SIZE, + (i + 2uz) * EVENT_CHUNK_SIZE + ); + } else { + delete new_chunk; + } + } + chunk = next; } - return true; + cached_event_chunk = chunk; + cached_event_chunk_index = chunk_index; + return chunk->events[index % EVENT_CHUNK_SIZE]; } private: std::atomic_size_t next_event_index = 0uz; - mutex event_vector_realloc_mutex; - std::vector events; + TimingEventChunk *first_event_chunk = nullptr; std::unique_ptr output_file_name{}; - static inline thread_local std::stack open_sequences; + static inline thread_local std::stack open_sequences; + static inline thread_local TimingEventChunk *cached_event_chunk = nullptr; + static inline thread_local size_t cached_event_chunk_index = 0uz; static inline bool is_enabled = false; static inline bool immediate_logging = false; static inline bool log_to_file = default_log_to_file; diff --git a/src/native/common/runtime-base/timing-internal.cc b/src/native/common/runtime-base/timing-internal.cc index ebf8d111893..209e1af6eb4 100644 --- a/src/native/common/runtime-base/timing-internal.cc +++ b/src/native/common/runtime-base/timing-internal.cc @@ -1,7 +1,6 @@ #include #include -#include #include #include #include @@ -18,7 +17,6 @@ namespace chrono = std::chrono; void FastTiming::really_initialize (bool log_immediately) noexcept { internal_timing.configure_for_use (); - is_enabled = true; immediate_logging = log_immediately; // TLS variables are initialized on first use, do it here so that we can have @@ -113,7 +111,10 @@ void FastTiming::dump (size_t entries, bool indent, std::function { + for (int i = 0; i < 1024; i++) { + Android.Runtime.JNIEnv.GetJniName (typeof (MainActivity)); + } + }); + Android.Util.Log.Info ("FastTimingTest", "{{completedMessage}}"); +""" + ); + + using var builder = CreateApkBuilder (packageName: packageName); + Assert.IsTrue (builder.Install (proj), "Project should have installed."); + + string previousMonoLog = RunAdbCommand ("shell getprop debug.mono.log").Trim (); + try { + RunAdbCommand ("shell setprop debug.mono.log timing=fast-bare"); + ClearAdbLogcat (); + + bool sawBufferGrowth = false; + bool appCompleted = MonitorAdbLogcat ( + line => { + sawBufferGrowth |= line.Contains (bufferGrowthMessage, StringComparison.Ordinal); + return line.Contains (completedMessage, StringComparison.Ordinal); + }, + Path.Combine (Root, builder.ProjectDirectory, "fast-timing-events.log"), + timeout: 60, + onMonitoringStarted: () => StartActivityAndAssert (proj) + ); + + Assert.IsTrue (appCompleted, $"Output did not contain {completedMessage}."); + Assert.IsTrue (sawBufferGrowth, $"Output did not contain {bufferGrowthMessage}."); + + bool dumpCompleted = MonitorAdbLogcat ( + line => line.Contains (dumpCompletedMessage, StringComparison.Ordinal), + Path.Combine (Root, builder.ProjectDirectory, "fast-timing-dump.log"), + timeout: 60, + onMonitoringStarted: () => RunAdbCommand ( + $"shell am broadcast -a mono.android.app.DUMP_TIMING_DATA -n {proj.PackageName}/mono.android.app.DumpTimingData" + ) + ); + + Assert.IsTrue (dumpCompleted, $"Output did not contain {dumpCompletedMessage}."); + } finally { + RunAdbCommand ($"shell am force-stop {proj.PackageName}"); + string value = previousMonoLog.Length == 0 ? "\"\"" : $"\"{previousMonoLog}\""; + RunAdbCommand ($"shell setprop debug.mono.log {value}"); + } + } +}