From e5d4b7f87e1129d84369100abb2b41df5fd6c8b5 Mon Sep 17 00:00:00 2001 From: Marek Habersack Date: Wed, 21 Feb 2024 19:09:27 +0100 Subject: [PATCH 1/8] Extended timing of the native runtime performance Support for timing of some MonoVM bits --- src/monodroid/jni/debug.hh | 1 + src/monodroid/jni/monodroid-glue-internal.hh | 67 +++++---- src/monodroid/jni/monodroid-glue.cc | 127 +++++++++++++++-- src/monodroid/jni/robin-map.hh | 29 ++++ src/monodroid/jni/strings.hh | 21 +++ src/monodroid/jni/timing-internal.cc | 142 ++++++++++++++++--- src/monodroid/jni/timing-internal.hh | 119 +++++++++++++++- 7 files changed, 449 insertions(+), 57 deletions(-) create mode 100644 src/monodroid/jni/robin-map.hh diff --git a/src/monodroid/jni/debug.hh b/src/monodroid/jni/debug.hh index 9eafaa05624..4909e571bc8 100644 --- a/src/monodroid/jni/debug.hh +++ b/src/monodroid/jni/debug.hh @@ -43,6 +43,7 @@ namespace xamarin::android static inline constexpr std::string_view DEBUG_MONO_RUNTIME_ARGS_PROPERTY { "debug.mono.runtime_args" }; static inline constexpr std::string_view DEBUG_MONO_SOFT_BREAKPOINTS { "debug.mono.soft_breakpoints" }; static inline constexpr std::string_view DEBUG_MONO_TRACE_PROPERTY { "debug.mono.trace" }; + static inline constexpr std::string_view DEBUG_MONO_TIMING { "debug.mono.timing" }; static inline constexpr std::string_view DEBUG_MONO_WREF_PROPERTY { "debug.mono.wref" }; public: diff --git a/src/monodroid/jni/monodroid-glue-internal.hh b/src/monodroid/jni/monodroid-glue-internal.hh index abd3401671c..aaf3f0c3ce2 100644 --- a/src/monodroid/jni/monodroid-glue-internal.hh +++ b/src/monodroid/jni/monodroid-glue-internal.hh @@ -15,34 +15,12 @@ #include #include -// NDEBUG causes robin_map.h not to include which, in turn, prevents indirect inclusion of . -// conflicts with our std::mutex definition in cppcompat.hh -#if !defined (NDEBUG) -#define NDEBUG -#define NDEBUG_UNDEFINE -#endif - -// hush some compiler warnings -#if defined (__clang__) -#pragma clang diagnostic push -#pragma clang diagnostic ignored "-Wunused-parameter" -#endif // __clang__ - -#include - -#if defined (__clang__) -#pragma clang diagnostic pop -#endif // __clang__ - -#if defined (NDEBUG_UNDEFINE) -#undef NDEBUG -#undef NDEBUG_UNDEFINE -#endif - //#include #include #include +#include "robin-map.hh" + // See https://github.com/dotnet/runtime/pull/67024 // See https://github.com/xamarin/xamarin-android/issues/6935 extern mono_bool mono_opt_aot_lazy_assembly_load; @@ -64,6 +42,35 @@ namespace xamarin::android::internal } }; + using timing_sequence_map_t = tsl::robin_map; + + class TimingProfilerState + { + public: + template + void add_sequence (T* ptr, size_t sequence_number) + { + std::lock_guard lock (map_lock); + seq_map[ptr] = sequence_number; + } + + template + size_t get_sequence (T* ptr) + { + std::lock_guard lock (map_lock); + auto iter = seq_map.find (ptr); + if (iter == seq_map.end ()) { + return 0; + } + + return iter->second; + } + + private: + timing_sequence_map_t seq_map; + std::mutex map_lock; + }; + class MonodroidRuntime { using pinvoke_api_map = tsl::robin_map< @@ -228,6 +235,10 @@ namespace xamarin::android::internal void set_debug_options (); void parse_gdb_options (); void mono_runtime_init (JNIEnv *env, dynamic_local_string& runtime_args); + void timing_init () noexcept; + void timing_ensure_state () noexcept; + void timing_init_extended () noexcept; + void timing_init_verbose () noexcept; void init_android_runtime (JNIEnv *env, jclass runtimeClass, jobject loader); void set_environment_variable_for_directory (const char *name, jstring_wrapper &value, bool createDirectory, mode_t mode); @@ -261,6 +272,13 @@ namespace xamarin::android::internal static void jit_done (MonoProfiler *prof, MonoMethod *method, MonoJitInfo* jinfo); static void thread_start (MonoProfiler *prof, uintptr_t tid); static void thread_end (MonoProfiler *prof, uintptr_t tid); + static void prof_assembly_loading (MonoProfiler *prof, MonoAssembly *assembly) noexcept; + static void prof_assembly_loaded (MonoProfiler *prof, MonoAssembly *assembly) noexcept; + static void prof_image_loading (MonoProfiler *prof, MonoImage *assembly) noexcept; + static void prof_image_loaded (MonoProfiler *prof, MonoImage *assembly) noexcept; + static void prof_class_loading (MonoProfiler *prof, MonoClass *klass) noexcept; + static void prof_class_loaded (MonoProfiler *prof, MonoClass *klass) noexcept; + #if !defined (RELEASE) static MonoReflectionType* typemap_java_to_managed (MonoString *java_type_name) noexcept; static const char* typemap_managed_to_java (MonoReflectionType *type, const uint8_t *mvid) noexcept; @@ -325,6 +343,7 @@ namespace xamarin::android::internal static void *system_native_library_handle; static void *system_security_cryptography_native_android_library_handle; static void *system_io_compression_native_library_handle; + static inline TimingProfilerState* timing_profiler_state = nullptr; static std::mutex dso_handle_write_lock; }; } diff --git a/src/monodroid/jni/monodroid-glue.cc b/src/monodroid/jni/monodroid-glue.cc index 60eeeacbab4..d51a5419a37 100644 --- a/src/monodroid/jni/monodroid-glue.cc +++ b/src/monodroid/jni/monodroid-glue.cc @@ -511,6 +511,118 @@ MonodroidRuntime::set_debug_options (void) mono_debug_init (MONO_DEBUG_FORMAT_MONO); } +void +MonodroidRuntime::prof_assembly_loading ([[maybe_unused]] MonoProfiler *prof, MonoAssembly *assembly) noexcept +{ + size_t seq = internal_timing->start_event (TimingEventKind::MonoAssemblyLoad); + // This unfortunately has some overhead + timing_profiler_state->add_sequence (assembly, seq); +} + +void +MonodroidRuntime::prof_assembly_loaded ([[maybe_unused]] MonoProfiler *prof, MonoAssembly *assembly) noexcept +{ + // This unfortunately has some overhead + size_t seq = timing_profiler_state->get_sequence (assembly); + internal_timing->end_event (seq, true /* uses_more_info */); + internal_timing->add_more_info (seq, utils.strdup_new (mono_assembly_name_get_name (mono_assembly_get_name (assembly)))); +} + +void +MonodroidRuntime::prof_image_loading ([[maybe_unused]] MonoProfiler *prof, MonoImage *image) noexcept +{ + size_t seq = internal_timing->start_event (TimingEventKind::MonoImageLoad); + // This unfortunately has some overhead + timing_profiler_state->add_sequence (image, seq); +} + +void +MonodroidRuntime::prof_image_loaded ([[maybe_unused]] MonoProfiler *prof, MonoImage *image) noexcept +{ + // This unfortunately has some overhead + size_t seq = timing_profiler_state->get_sequence (image); + internal_timing->end_event (seq, true /* uses_more_info */); + internal_timing->add_more_info (seq, utils.strdup_new (mono_image_get_name (image))); +} + +void +MonodroidRuntime::prof_class_loading ([[maybe_unused]] MonoProfiler *prof, MonoClass *klass) noexcept +{ + size_t seq = internal_timing->start_event (TimingEventKind::MonoClassLoad); + // This unfortunately has some overhead + timing_profiler_state->add_sequence (klass, seq); +} + +void +MonodroidRuntime::prof_class_loaded ([[maybe_unused]] MonoProfiler *prof, MonoClass *klass) noexcept +{ + // This unfortunately has some overhead + size_t seq = timing_profiler_state->get_sequence (klass); + internal_timing->end_event (seq, true /* uses_more_info */); + internal_timing->add_more_info (seq, utils.strdup_new (mono_class_get_name (klass))); +} + +force_inline +void +MonodroidRuntime::timing_ensure_state () noexcept +{ + if (timing_profiler_state != nullptr) { + return; + } + + timing_profiler_state = new TimingProfilerState; +} +force_inline void +MonodroidRuntime::timing_init_extended () noexcept +{ + timing_ensure_state (); + + mono_profiler_set_assembly_loading_callback (profiler_handle, prof_assembly_loading); + mono_profiler_set_assembly_loaded_callback (profiler_handle, prof_assembly_loaded); + mono_profiler_set_image_loading_callback (profiler_handle, prof_image_loading); + mono_profiler_set_image_loaded_callback (profiler_handle, prof_image_loaded); +} + +force_inline void +MonodroidRuntime::timing_init_verbose () noexcept +{ + timing_ensure_state (); + + std::unique_ptr jit_log_path {utils.path_combine (androidSystem.override_dirs[0], "methods.txt")}; + jit_log = utils.monodroid_fopen (jit_log_path.get (), "a"); + utils.set_world_accessable (jit_log_path.get ()); + jit_time.mark_start (); + mono_profiler_set_jit_begin_callback (profiler_handle, jit_begin); + mono_profiler_set_jit_done_callback (profiler_handle, jit_done); + mono_profiler_set_jit_failed_callback (profiler_handle, jit_failed); + + mono_profiler_set_class_loading_callback (profiler_handle, prof_class_loading); + mono_profiler_set_class_loaded_callback (profiler_handle, prof_class_loaded); +} + +force_inline void +MonodroidRuntime::timing_init () noexcept +{ + if (!FastTiming::enabled () || FastTiming::mode () == TimingMode::Bare) { + return; + } + + // TODO: time this, so that we can subtract it from the cumulative results + switch (FastTiming::mode ()) { + case TimingMode::Verbose: + timing_init_verbose (); + [[fallthrough]]; + + case TimingMode::Extended: + timing_init_extended (); + break; + + default: + // ignored + break; + } +} + void MonodroidRuntime::mono_runtime_init ([[maybe_unused]] JNIEnv *env, [[maybe_unused]] dynamic_local_string& runtime_args) { @@ -620,24 +732,11 @@ MonodroidRuntime::mono_runtime_init ([[maybe_unused]] JNIEnv *env, [[maybe_unuse // TESTING UBSAN: integer overflow //log_warn (LOG_DEFAULT, "Let us have an overflow: %d", INT_MAX + 1); - bool log_methods = FastTiming::enabled () && !FastTiming::is_bare_mode (); - if (log_methods) [[unlikely]] { - std::unique_ptr jit_log_path {utils.path_combine (AndroidSystem::override_dirs [0], "methods.txt")}; - jit_log = utils.monodroid_fopen (jit_log_path.get (), "a"); - utils.set_world_accessable (jit_log_path.get ()); - } - profiler_handle = mono_profiler_create (nullptr); mono_profiler_set_thread_started_callback (profiler_handle, thread_start); mono_profiler_set_thread_stopped_callback (profiler_handle, thread_end); - if (log_methods) [[unlikely]]{ - jit_time.mark_start (); - mono_profiler_set_jit_begin_callback (profiler_handle, jit_begin); - mono_profiler_set_jit_done_callback (profiler_handle, jit_done); - mono_profiler_set_jit_failed_callback (profiler_handle, jit_failed); - } - + timing_init (); parse_gdb_options (); if (wait_for_gdb) { diff --git a/src/monodroid/jni/robin-map.hh b/src/monodroid/jni/robin-map.hh new file mode 100644 index 00000000000..8224cad751e --- /dev/null +++ b/src/monodroid/jni/robin-map.hh @@ -0,0 +1,29 @@ +// Dear Emacs, this is a -*- C++ -*- header +#if !defined (ROBIN_MAP_HH) +#define ROBIN_MAP_HH + +// NDEBUG causes robin_map.h not to include which, in turn, prevents indirect inclusion of . +// conflicts with our std::mutex definition in cppcompat.hh +#if !defined (NDEBUG) +#define NDEBUG +#define NDEBUG_UNDEFINE +#endif + +// hush some compiler warnings +#if defined (__clang__) +#pragma clang diagnostic push +#pragma clang diagnostic ignored "-Wunused-parameter" +#endif // __clang__ + +#include + +#if defined (__clang__) +#pragma clang diagnostic pop +#endif // __clang__ + +#if defined (NDEBUG_UNDEFINE) +#undef NDEBUG +#undef NDEBUG_UNDEFINE +#endif + +#endif // ndef ROBIN_MAP_HH diff --git a/src/monodroid/jni/strings.hh b/src/monodroid/jni/strings.hh index 97f22e0b805..fa6a18c2cc1 100644 --- a/src/monodroid/jni/strings.hh +++ b/src/monodroid/jni/strings.hh @@ -94,6 +94,27 @@ namespace xamarin::android::internal return starts_with (s, strlen (s)); } + force_inline bool equal (size_t start_index, std::string_view const& s) const noexcept + { + if (s.empty ()) { + return false; + } + + if (!can_access (s.length () + start_index)) { + return false; + } + + if (s.length () != length () - start_index) { + return false; + } + + if (length () == 0) { + return true; + } + + return memcmp (_start + start_index, s.data (), length () - start_index) == 0; + } + force_inline bool starts_with (const char *s, size_t s_length) const noexcept { if (s == nullptr || !can_access (s_length)) { diff --git a/src/monodroid/jni/timing-internal.cc b/src/monodroid/jni/timing-internal.cc index 5b91c5186f8..1895fab9533 100644 --- a/src/monodroid/jni/timing-internal.cc +++ b/src/monodroid/jni/timing-internal.cc @@ -1,3 +1,5 @@ +#include "debug.hh" +#include "strings.hh" #include "timing-internal.hh" #include "util.hh" @@ -8,8 +10,6 @@ namespace xamarin::android::internal { FastTiming *internal_timing = nullptr; } -bool FastTiming::is_enabled = false; -bool FastTiming::immediate_logging = false; TimingEvent FastTiming::init_time {}; void @@ -19,36 +19,105 @@ FastTiming::really_initialize (bool log_immediately) noexcept is_enabled = true; immediate_logging = log_immediately; + dynamic_local_string value; + if (androidSystem.monodroid_get_system_property (Debug::DEBUG_MONO_TIMING, value) != 0) { + parse_options (value); + } + if (immediate_logging) { return; } - log_write (LOG_TIMING, LogLevel::Info, "[2/1] To get timing results, send the mono.android.app.DUMP_TIMING_DATA intent to the application"); + log_info (LOG_TIMING, "[%s] To get timing results, send the mono.android.app.DUMP_TIMING_DATA intent to the application", DUMP_STAGE_INIT_TAG.data ()); } void -FastTiming::dump () noexcept +FastTiming::parse_options (dynamic_local_string const& value) noexcept { - if (immediate_logging) { + if (value.length () == 0) { return; } - StartupAwareLock lock { event_vector_realloc_mutex }; - size_t entries = next_event_index.load (); + string_segment param; + while (value.next_token (',', param)) { + if (param.equal (OPT_FAST)) { + immediate_logging = true; + continue; + } + + if (param.starts_with (OPT_MODE)) { + if (param.equal (OPT_MODE.length (), OPT_MODE_BARE)) { + timing_mode = TimingMode::Bare; + continue; + } + + if (param.equal (OPT_MODE.length (), OPT_MODE_EXTENDED)) { + timing_mode = TimingMode::Extended; + continue; + } + + if (param.equal (OPT_MODE.length (), OPT_MODE_VERBOSE)) { + timing_mode = TimingMode::Verbose; + continue; + } + continue; + } + + if (param.equal (OPT_TO_FILE)) { + log_to_file = true; + continue; + } + + if (param.starts_with (OPT_FILE_NAME)) { + output_file_name = utils.strdup_new (param.start () + OPT_FILE_NAME.length (), param.length () - OPT_FILE_NAME.length ()); + continue; + } - log_write (LOG_TIMING, LogLevel::Info, "[2/2] Performance measurement results"); - if (entries == 0) { - log_write (LOG_TIMING, LogLevel::Info, "[2/3] No events logged"); + if (param.starts_with (OPT_DURATION)) { + if (!param.to_integer (duration_ms, OPT_DURATION.length ())) { + log_warn (LOG_TIMING, "Failed to parse duration in milliseconds from '%s'", param.start ()); + duration_ms = default_duration_milliseconds; + } + continue; + } + } + + if (output_file_name != nullptr) { + log_to_file = true; + } + + // If logging to file is requested, turn off immediate logging. + if (log_to_file) { + immediate_logging = false; + } +} + +force_inline bool +FastTiming::no_events_logged (size_t entries) noexcept +{ + if (entries > 0) { + return false; + } + + log_info_nocheck (LOG_TIMING, "[%s] No events logged", DUMP_STAGE_NO_EVENTS_TAG.data ()); + return true; +} + +void +FastTiming::dump_to_logcat (size_t entries) noexcept +{ + log_info_nocheck (LOG_TIMING, "[%s] Performance measurement results", DUMP_STAGE_RESULTS_TAG.data ()); + if (no_events_logged (entries)) { return; } dynamic_local_string message; - // Values are in nanoseconds + // Values are in nanoseconds, we don't need to worry about overflow for our needs, when accumulating. uint64_t total_assembly_load_time = 0; uint64_t total_java_to_managed_time = 0; uint64_t total_managed_to_java_time = 0; - uint64_t total_ns; + uint64_t total_ns; // initialized by `calculate_interval` format_and_log (init_time, message, total_ns, true /* indent */); for (size_t i = 0; i < entries; i++) { @@ -75,14 +144,55 @@ FastTiming::dump () noexcept } uint32_t sec, ms, ns; - log_write (LOG_TIMING, LogLevel::Info, "[2/4] Accumulated performance results"); + log_info_nocheck (LOG_TIMING, "[%s] Accumulated performance results", DUMP_STAGE_ACCUMULATED_RESULTS_TAG.data ()); ns_to_time (total_assembly_load_time, sec, ms, ns); - log_info_nocheck (LOG_TIMING, " [2/5] Assembly load: %u:%u::%u", sec, ms, ns); + log_info_nocheck (LOG_TIMING, " [%s] Assembly load: %u:%u::%u", DUMP_STAGE_ACC_ASSEMBLY_LOAD_TAG.data (), sec, ms, ns); ns_to_time (total_java_to_managed_time, sec, ms, ns); - log_info_nocheck (LOG_TIMING, " [2/6] Java to Managed lookup: %u:%u::%u", sec, ms, ns); + log_info_nocheck (LOG_TIMING, " [%s] Java to Managed lookup: %u:%u::%u", DUMP_STAGE_ACC_JAVA_TO_MANAGED_TAG.data (), sec, ms, ns); ns_to_time (total_managed_to_java_time, sec, ms, ns); - log_info_nocheck (LOG_TIMING, " [2/7] Managed to Java lookup: %u:%u::%u", sec, ms, ns); + log_info_nocheck (LOG_TIMING, " [%s] Managed to Java lookup: %u:%u::%u", DUMP_STAGE_ACC_MANAGED_TO_JAVA_TAG.data (), sec, ms, ns); +} + +void +FastTiming::dump_to_file (size_t entries) noexcept +{ + std::unique_ptr timing_log_path { + utils.path_combine ( + androidSystem.override_dirs[0], + output_file_name == nullptr ? default_timing_file_name.data () : output_file_name + ) + }; + + log_info (LOG_TIMING, "[%s] Performance measurement results logged to file: %s", DUMP_STAGE_RESULTS_TAG.data (), timing_log_path.get ()); + if (no_events_logged (entries)) { + return; + } + + // TODO: implement +} + +void +FastTiming::dump () noexcept +{ + // TODO: measure (average over, say, 10 calls) and log the following: + // * timing_profiler_state->add_sequence + // * timing_profiler_state->get_sequence + // + // This will allow to subtract these values from various measurements + if (immediate_logging) { + return; + } + + StartupAwareLock lock { event_vector_realloc_mutex }; + size_t entries = next_event_index.load (); + + if (log_to_file) { + dump_to_file (entries); + } else { + dump_to_logcat (entries); + + } } diff --git a/src/monodroid/jni/timing-internal.hh b/src/monodroid/jni/timing-internal.hh index 47417123f27..8aadbb88642 100644 --- a/src/monodroid/jni/timing-internal.hh +++ b/src/monodroid/jni/timing-internal.hh @@ -36,7 +36,20 @@ namespace xamarin::android::internal RuntimeConfigBlob = 9, RuntimeRegister = 10, TotalRuntimeInit = 11, - Unspecified = 12, + MonoMethodJit = 12, + MonoClassLoad = 13, + MonoImageLoad = 14, + MonoAssemblyLoad = 15, + MonoMethodDuration = 16, + MonoMethodInvoke = 17, + Unspecified = std::numeric_limits>::max (), + }; + + enum class TimingMode + { + Bare, + Extended, + Verbose, }; struct TimingEventPoint @@ -85,6 +98,32 @@ namespace xamarin::android::internal static constexpr uint32_t ms_in_second = 1000; static constexpr uint32_t ns_in_second = ms_in_second * ns_in_millisecond; + // defaults + static constexpr TimingMode default_timing_mode = TimingMode::Bare; + static constexpr bool default_fast_timing_enabled = false; + static constexpr bool default_log_to_file = false; + static constexpr size_t default_duration_milliseconds = 1500; + static constexpr std::string_view default_timing_file_name { "timing.txt" }; + + // Parameters in the debug.mono.timing property + static constexpr std::string_view OPT_DURATION { "duration=" }; + static constexpr std::string_view OPT_FAST { "fast" }; + static constexpr std::string_view OPT_FILE_NAME { "filename=" }; + static constexpr std::string_view OPT_MODE { "mode=" }; + static constexpr std::string_view OPT_MODE_BARE { "bare" }; + static constexpr std::string_view OPT_MODE_EXTENDED { "extended" }; + static constexpr std::string_view OPT_MODE_VERBOSE { "verbose" }; + static constexpr std::string_view OPT_TO_FILE { "to-file" }; + + // Results dump stage log markers + static constexpr std::string_view DUMP_STAGE_INIT_TAG { "2/1" }; + static constexpr std::string_view DUMP_STAGE_RESULTS_TAG { "2/2" }; + static constexpr std::string_view DUMP_STAGE_NO_EVENTS_TAG { "2/3" }; + static constexpr std::string_view DUMP_STAGE_ACCUMULATED_RESULTS_TAG { "2/4" }; + static constexpr std::string_view DUMP_STAGE_ACC_ASSEMBLY_LOAD_TAG { "2/5" }; + static constexpr std::string_view DUMP_STAGE_ACC_JAVA_TO_MANAGED_TAG { "2/6" }; + static constexpr std::string_view DUMP_STAGE_ACC_MANAGED_TO_JAVA_TAG { "2/7" }; + protected: FastTiming () noexcept { @@ -104,6 +143,36 @@ namespace xamarin::android::internal (log_timing_categories & LOG_TIMING_FAST_BARE) == LOG_TIMING_FAST_BARE; } + force_inline static TimingMode mode () noexcept + { + return timing_mode; + } + + force_inline static void set_mode (TimingMode new_mode) noexcept + { + timing_mode = new_mode; + } + + force_inline static bool fast_mode_enabled () noexcept + { + return immediate_logging; + } + + force_inline static void set_fast_mode_enabled (bool yesno) noexcept + { + immediate_logging = yesno; + } + + force_inline size_t duration () noexcept + { + return duration_ms; + } + + force_inline void set_duration (size_t new_duration_ms) noexcept + { + duration_ms = new_duration_ms; + } + force_inline static void initialize (bool log_immediately) noexcept { if (!utils.should_log (LOG_TIMING)) [[likely]] { @@ -234,7 +303,11 @@ namespace xamarin::android::internal private: static void really_initialize (bool log_immediately) noexcept; + static void parse_options (dynamic_local_string const& value) noexcept; static void* timing_signal_thread (void *arg) noexcept; + bool no_events_logged (size_t entries) noexcept; + void dump_to_logcat (size_t entries) noexcept; + void dump_to_file (size_t entries) noexcept; force_inline static void mark (TimingEventPoint &point) noexcept { @@ -327,6 +400,42 @@ namespace xamarin::android::internal return; } + case TimingEventKind::MonoAssemblyLoad: { + constexpr std::string_view desc { "MonoVM assembly load: " }; + message.append (desc); + return; + } + + case TimingEventKind::MonoClassLoad: { + constexpr std::string_view desc { "MonoVM class load: " }; + message.append (desc); + return; + } + + case TimingEventKind::MonoImageLoad: { + constexpr std::string_view desc { "MonoVM image load: " }; + message.append (desc); + return; + } + + case TimingEventKind::MonoMethodJit: { + constexpr std::string_view desc { "MonoVM method JIT: " }; + message.append (desc); + return; + } + + case TimingEventKind::MonoMethodInvoke: { + constexpr std::string_view desc { "MonoVM method invocation: " }; + message.append (desc); + return; + } + + case TimingEventKind::MonoMethodDuration: { + constexpr std::string_view desc { "MonoVM method self duration: " }; + message.append (desc); + return; + } + default: { constexpr char desc[] = "Unknown timing event"; message.append (desc); @@ -443,8 +552,12 @@ namespace xamarin::android::internal std::vector events; static TimingEvent init_time; - static bool is_enabled; - static bool immediate_logging; + static inline bool is_enabled = false; + static inline bool immediate_logging = default_fast_timing_enabled; + static inline TimingMode timing_mode = default_timing_mode; + static inline bool log_to_file = default_log_to_file; + static inline size_t duration_ms = default_duration_milliseconds; + static inline char* output_file_name = nullptr; }; extern FastTiming *internal_timing; From cc4bd92af4a9f4f7619b4f9d8e19560193a1ea4b Mon Sep 17 00:00:00 2001 From: Marek Habersack Date: Thu, 22 Feb 2024 20:45:47 +0100 Subject: [PATCH 2/8] Improve output --- src/monodroid/jni/monodroid-glue.cc | 117 +++++++++++++++------------- 1 file changed, 62 insertions(+), 55 deletions(-) diff --git a/src/monodroid/jni/monodroid-glue.cc b/src/monodroid/jni/monodroid-glue.cc index d51a5419a37..f4f7132988f 100644 --- a/src/monodroid/jni/monodroid-glue.cc +++ b/src/monodroid/jni/monodroid-glue.cc @@ -514,113 +514,120 @@ MonodroidRuntime::set_debug_options (void) void MonodroidRuntime::prof_assembly_loading ([[maybe_unused]] MonoProfiler *prof, MonoAssembly *assembly) noexcept { - size_t seq = internal_timing->start_event (TimingEventKind::MonoAssemblyLoad); - // This unfortunately has some overhead - timing_profiler_state->add_sequence (assembly, seq); + size_t seq = internal_timing->start_event (TimingEventKind::MonoAssemblyLoad); + // This unfortunately has some overhead + timing_profiler_state->add_sequence (assembly, seq); } void MonodroidRuntime::prof_assembly_loaded ([[maybe_unused]] MonoProfiler *prof, MonoAssembly *assembly) noexcept { - // This unfortunately has some overhead - size_t seq = timing_profiler_state->get_sequence (assembly); - internal_timing->end_event (seq, true /* uses_more_info */); - internal_timing->add_more_info (seq, utils.strdup_new (mono_assembly_name_get_name (mono_assembly_get_name (assembly)))); + // This unfortunately has some overhead + size_t seq = timing_profiler_state->get_sequence (assembly); + internal_timing->end_event (seq, true /* uses_more_info */); + internal_timing->add_more_info (seq, mono_assembly_name_get_name (mono_assembly_get_name (assembly))); } void MonodroidRuntime::prof_image_loading ([[maybe_unused]] MonoProfiler *prof, MonoImage *image) noexcept { - size_t seq = internal_timing->start_event (TimingEventKind::MonoImageLoad); - // This unfortunately has some overhead - timing_profiler_state->add_sequence (image, seq); + size_t seq = internal_timing->start_event (TimingEventKind::MonoImageLoad); + // This unfortunately has some overhead + timing_profiler_state->add_sequence (image, seq); } void MonodroidRuntime::prof_image_loaded ([[maybe_unused]] MonoProfiler *prof, MonoImage *image) noexcept { - // This unfortunately has some overhead - size_t seq = timing_profiler_state->get_sequence (image); - internal_timing->end_event (seq, true /* uses_more_info */); - internal_timing->add_more_info (seq, utils.strdup_new (mono_image_get_name (image))); + // This unfortunately has some overhead + size_t seq = timing_profiler_state->get_sequence (image); + internal_timing->end_event (seq, true /* uses_more_info */); + internal_timing->add_more_info (seq, mono_image_get_name (image)); } void MonodroidRuntime::prof_class_loading ([[maybe_unused]] MonoProfiler *prof, MonoClass *klass) noexcept { - size_t seq = internal_timing->start_event (TimingEventKind::MonoClassLoad); - // This unfortunately has some overhead - timing_profiler_state->add_sequence (klass, seq); + size_t seq = internal_timing->start_event (TimingEventKind::MonoClassLoad); + // This unfortunately has some overhead + timing_profiler_state->add_sequence (klass, seq); } void MonodroidRuntime::prof_class_loaded ([[maybe_unused]] MonoProfiler *prof, MonoClass *klass) noexcept { - // This unfortunately has some overhead - size_t seq = timing_profiler_state->get_sequence (klass); - internal_timing->end_event (seq, true /* uses_more_info */); - internal_timing->add_more_info (seq, utils.strdup_new (mono_class_get_name (klass))); + // This unfortunately has some overhead + size_t seq = timing_profiler_state->get_sequence (klass); + internal_timing->end_event (seq, true /* uses_more_info */); + + dynamic_local_string info; + info.append (mono_class_get_namespace (klass)); + if (info.length () > 0) { + info.append ("."); + } + info.append (mono_class_get_name (klass)); + internal_timing->add_more_info (seq, info); } force_inline void MonodroidRuntime::timing_ensure_state () noexcept { - if (timing_profiler_state != nullptr) { - return; - } + if (timing_profiler_state != nullptr) { + return; + } - timing_profiler_state = new TimingProfilerState; + timing_profiler_state = new TimingProfilerState; } force_inline void MonodroidRuntime::timing_init_extended () noexcept { - timing_ensure_state (); + timing_ensure_state (); - mono_profiler_set_assembly_loading_callback (profiler_handle, prof_assembly_loading); - mono_profiler_set_assembly_loaded_callback (profiler_handle, prof_assembly_loaded); - mono_profiler_set_image_loading_callback (profiler_handle, prof_image_loading); - mono_profiler_set_image_loaded_callback (profiler_handle, prof_image_loaded); + mono_profiler_set_assembly_loading_callback (profiler_handle, prof_assembly_loading); + mono_profiler_set_assembly_loaded_callback (profiler_handle, prof_assembly_loaded); + mono_profiler_set_image_loading_callback (profiler_handle, prof_image_loading); + mono_profiler_set_image_loaded_callback (profiler_handle, prof_image_loaded); } force_inline void MonodroidRuntime::timing_init_verbose () noexcept { - timing_ensure_state (); + timing_ensure_state (); - std::unique_ptr jit_log_path {utils.path_combine (androidSystem.override_dirs[0], "methods.txt")}; - jit_log = utils.monodroid_fopen (jit_log_path.get (), "a"); - utils.set_world_accessable (jit_log_path.get ()); - jit_time.mark_start (); - mono_profiler_set_jit_begin_callback (profiler_handle, jit_begin); - mono_profiler_set_jit_done_callback (profiler_handle, jit_done); - mono_profiler_set_jit_failed_callback (profiler_handle, jit_failed); + std::unique_ptr jit_log_path {utils.path_combine (androidSystem.override_dirs[0], "methods.txt")}; + jit_log = utils.monodroid_fopen (jit_log_path.get (), "a"); + utils.set_world_accessable (jit_log_path.get ()); + jit_time.mark_start (); + mono_profiler_set_jit_begin_callback (profiler_handle, jit_begin); + mono_profiler_set_jit_done_callback (profiler_handle, jit_done); + mono_profiler_set_jit_failed_callback (profiler_handle, jit_failed); - mono_profiler_set_class_loading_callback (profiler_handle, prof_class_loading); - mono_profiler_set_class_loaded_callback (profiler_handle, prof_class_loaded); + mono_profiler_set_class_loading_callback (profiler_handle, prof_class_loading); + mono_profiler_set_class_loaded_callback (profiler_handle, prof_class_loaded); } force_inline void MonodroidRuntime::timing_init () noexcept { - if (!FastTiming::enabled () || FastTiming::mode () == TimingMode::Bare) { - return; - } + if (!FastTiming::enabled () || FastTiming::mode () == TimingMode::Bare) { + return; + } - // TODO: time this, so that we can subtract it from the cumulative results - switch (FastTiming::mode ()) { - case TimingMode::Verbose: - timing_init_verbose (); - [[fallthrough]]; + // TODO: time this, so that we can subtract it from the cumulative results + switch (FastTiming::mode ()) { + case TimingMode::Verbose: + timing_init_verbose (); + [[fallthrough]]; - case TimingMode::Extended: - timing_init_extended (); - break; + case TimingMode::Extended: + timing_init_extended (); + break; - default: - // ignored - break; - } + default: + // ignored + break; + } } void From 9d4f0cd2411e06cf12a1d1c2d01af5c00c6b5eba Mon Sep 17 00:00:00 2001 From: Marek Habersack Date: Wed, 28 Feb 2024 14:54:12 +0100 Subject: [PATCH 3/8] Update apkdesc files --- .../BuildReleaseArm64SimpleDotNet.apkdesc | 36 ++--- .../BuildReleaseArm64XFormsDotNet.apkdesc | 148 +++++++++--------- 2 files changed, 92 insertions(+), 92 deletions(-) diff --git a/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Resources/Base/BuildReleaseArm64SimpleDotNet.apkdesc b/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Resources/Base/BuildReleaseArm64SimpleDotNet.apkdesc index 7bd5cb51f7c..fb3a68d2e61 100644 --- a/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Resources/Base/BuildReleaseArm64SimpleDotNet.apkdesc +++ b/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Resources/Base/BuildReleaseArm64SimpleDotNet.apkdesc @@ -5,61 +5,61 @@ "Size": 3036 }, "assemblies/_Microsoft.Android.Resource.Designer.dll": { - "Size": 1028 + "Size": 1027 }, "assemblies/Java.Interop.dll": { - "Size": 61587 + "Size": 64193 }, "assemblies/Mono.Android.dll": { - "Size": 90798 + "Size": 90538 }, "assemblies/Mono.Android.Runtime.dll": { - "Size": 5225 + "Size": 5147 }, "assemblies/rc.bin": { "Size": 1512 }, "assemblies/System.Console.dll": { - "Size": 6546 + "Size": 6544 }, "assemblies/System.Linq.dll": { - "Size": 8553 + "Size": 8557 }, "assemblies/System.Private.CoreLib.dll": { - "Size": 553721 + "Size": 565531 }, "assemblies/System.Runtime.dll": { - "Size": 2550 + "Size": 2546 }, "assemblies/System.Runtime.InteropServices.dll": { - "Size": 4026 + "Size": 4022 }, "assemblies/UnnamedProject.dll": { - "Size": 2936 + "Size": 2934 }, "classes.dex": { - "Size": 377856 + "Size": 377748 }, "lib/arm64-v8a/libmono-component-marshal-ilgen.so": { - "Size": 87080 + "Size": 87352 }, "lib/arm64-v8a/libmonodroid.so": { - "Size": 339864 + "Size": 393784 }, "lib/arm64-v8a/libmonosgen-2.0.so": { - "Size": 3186504 + "Size": 3210968 }, "lib/arm64-v8a/libSystem.IO.Compression.Native.so": { "Size": 723560 }, "lib/arm64-v8a/libSystem.Native.so": { - "Size": 94504 + "Size": 94720 }, "lib/arm64-v8a/libSystem.Security.Cryptography.Native.Android.so": { - "Size": 155560 + "Size": 155568 }, "lib/arm64-v8a/libxamarin-app.so": { - "Size": 11680 + "Size": 11648 }, "META-INF/BNDLTOOL.RSA": { "Size": 1223 @@ -95,5 +95,5 @@ "Size": 1904 } }, - "PackageSize": 2783562 + "PackageSize": 2828618 } \ No newline at end of file diff --git a/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Resources/Base/BuildReleaseArm64XFormsDotNet.apkdesc b/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Resources/Base/BuildReleaseArm64XFormsDotNet.apkdesc index ddd5ba9e1b8..f451bc70658 100644 --- a/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Resources/Base/BuildReleaseArm64XFormsDotNet.apkdesc +++ b/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Resources/Base/BuildReleaseArm64XFormsDotNet.apkdesc @@ -5,214 +5,214 @@ "Size": 6652 }, "assemblies/_Microsoft.Android.Resource.Designer.dll": { - "Size": 2281 + "Size": 2279 }, "assemblies/FormsViewGroup.dll": { - "Size": 8100 + "Size": 8090 }, "assemblies/Java.Interop.dll": { - "Size": 69705 + "Size": 72360 }, "assemblies/Mono.Android.dll": { - "Size": 458238 + "Size": 456314 }, "assemblies/Mono.Android.Runtime.dll": { - "Size": 5151 + "Size": 5147 }, "assemblies/mscorlib.dll": { - "Size": 4002 + "Size": 3992 }, "assemblies/netstandard.dll": { - "Size": 5643 + "Size": 5625 }, "assemblies/rc.bin": { "Size": 1512 }, "assemblies/System.Collections.Concurrent.dll": { - "Size": 11530 + "Size": 11520 }, "assemblies/System.Collections.dll": { - "Size": 15430 + "Size": 15411 }, "assemblies/System.Collections.NonGeneric.dll": { - "Size": 7452 + "Size": 7442 }, "assemblies/System.ComponentModel.dll": { - "Size": 1939 + "Size": 1935 }, "assemblies/System.ComponentModel.Primitives.dll": { "Size": 2549 }, "assemblies/System.ComponentModel.TypeConverter.dll": { - "Size": 6033 + "Size": 6084 }, "assemblies/System.Console.dll": { - "Size": 6578 + "Size": 6576 }, "assemblies/System.Core.dll": { - "Size": 1974 + "Size": 1969 }, "assemblies/System.Diagnostics.DiagnosticSource.dll": { - "Size": 9068 + "Size": 9060 }, "assemblies/System.Diagnostics.TraceSource.dll": { - "Size": 6552 + "Size": 6543 }, "assemblies/System.dll": { - "Size": 2328 + "Size": 2326 }, "assemblies/System.Drawing.dll": { - "Size": 1939 + "Size": 1932 }, "assemblies/System.Drawing.Primitives.dll": { - "Size": 11975 + "Size": 11965 }, "assemblies/System.IO.Compression.Brotli.dll": { - "Size": 11196 + "Size": 11187 }, "assemblies/System.IO.Compression.dll": { - "Size": 15880 + "Size": 15864 }, "assemblies/System.IO.IsolatedStorage.dll": { - "Size": 9875 + "Size": 9895 }, "assemblies/System.Linq.dll": { - "Size": 19599 + "Size": 20514 }, "assemblies/System.Linq.Expressions.dll": { - "Size": 165117 + "Size": 164629 }, "assemblies/System.Net.Http.dll": { - "Size": 67653 + "Size": 67561 }, "assemblies/System.Net.Primitives.dll": { - "Size": 22432 + "Size": 22354 }, "assemblies/System.Net.Requests.dll": { - "Size": 3602 + "Size": 3588 }, "assemblies/System.ObjectModel.dll": { - "Size": 8699 + "Size": 8565 }, "assemblies/System.Private.CoreLib.dll": { - "Size": 849922 + "Size": 870644 }, "assemblies/System.Private.DataContractSerialization.dll": { - "Size": 193991 + "Size": 193443 }, "assemblies/System.Private.Uri.dll": { - "Size": 42860 + "Size": 42904 }, "assemblies/System.Private.Xml.dll": { - "Size": 216226 + "Size": 216020 }, "assemblies/System.Private.Xml.Linq.dll": { - "Size": 16639 + "Size": 16622 }, "assemblies/System.Runtime.dll": { - "Size": 2708 + "Size": 2703 }, "assemblies/System.Runtime.InteropServices.dll": { - "Size": 4028 + "Size": 4022 }, "assemblies/System.Runtime.Serialization.dll": { - "Size": 1865 + "Size": 1859 }, "assemblies/System.Runtime.Serialization.Formatters.dll": { - "Size": 2484 + "Size": 2479 }, "assemblies/System.Runtime.Serialization.Primitives.dll": { - "Size": 3758 + "Size": 3751 }, "assemblies/System.Security.Cryptography.dll": { - "Size": 8111 + "Size": 8099 }, "assemblies/System.Text.RegularExpressions.dll": { - "Size": 159112 + "Size": 161328 }, "assemblies/System.Xml.dll": { - "Size": 1758 + "Size": 1754 }, "assemblies/System.Xml.Linq.dll": { - "Size": 1774 + "Size": 1768 }, "assemblies/UnnamedProject.dll": { - "Size": 5015 + "Size": 5007 }, "assemblies/Xamarin.AndroidX.Activity.dll": { - "Size": 16149 + "Size": 16116 }, "assemblies/Xamarin.AndroidX.AppCompat.AppCompatResources.dll": { - "Size": 6225 + "Size": 6216 }, "assemblies/Xamarin.AndroidX.AppCompat.dll": { - "Size": 138721 + "Size": 137971 }, "assemblies/Xamarin.AndroidX.CardView.dll": { - "Size": 6977 + "Size": 6959 }, "assemblies/Xamarin.AndroidX.CoordinatorLayout.dll": { - "Size": 17886 + "Size": 17857 }, "assemblies/Xamarin.AndroidX.Core.dll": { - "Size": 127505 + "Size": 126882 }, "assemblies/Xamarin.AndroidX.CursorAdapter.dll": { - "Size": 8997 + "Size": 8978 }, "assemblies/Xamarin.AndroidX.DrawerLayout.dll": { - "Size": 15319 + "Size": 15286 }, "assemblies/Xamarin.AndroidX.Fragment.dll": { - "Size": 51744 + "Size": 51498 }, "assemblies/Xamarin.AndroidX.Legacy.Support.Core.UI.dll": { - "Size": 6242 + "Size": 6233 }, "assemblies/Xamarin.AndroidX.Lifecycle.Common.dll": { - "Size": 6900 + "Size": 6890 }, "assemblies/Xamarin.AndroidX.Lifecycle.LiveData.Core.dll": { - "Size": 6743 + "Size": 6733 }, "assemblies/Xamarin.AndroidX.Lifecycle.ViewModel.dll": { - "Size": 7011 + "Size": 7002 }, "assemblies/Xamarin.AndroidX.Loader.dll": { - "Size": 13082 + "Size": 13063 }, "assemblies/Xamarin.AndroidX.RecyclerView.dll": { - "Size": 93990 + "Size": 93516 }, "assemblies/Xamarin.AndroidX.SavedState.dll": { - "Size": 5114 + "Size": 5107 }, "assemblies/Xamarin.AndroidX.SwipeRefreshLayout.dll": { - "Size": 13974 + "Size": 13946 }, "assemblies/Xamarin.AndroidX.ViewPager.dll": { - "Size": 19060 + "Size": 19014 }, "assemblies/Xamarin.Forms.Core.dll": { - "Size": 565831 + "Size": 563905 }, "assemblies/Xamarin.Forms.Platform.Android.dll": { - "Size": 374486 + "Size": 373374 }, "assemblies/Xamarin.Forms.Platform.dll": { - "Size": 18767 + "Size": 18753 }, "assemblies/Xamarin.Forms.Xaml.dll": { - "Size": 63655 + "Size": 63542 }, "assemblies/Xamarin.Google.Android.Material.dll": { - "Size": 66417 + "Size": 66088 }, "classes.dex": { - "Size": 9458972 + "Size": 9458896 }, "classes2.dex": { - "Size": 103648 + "Size": 103472 }, "kotlin/annotation/annotation.kotlin_builtins": { "Size": 928 @@ -236,19 +236,19 @@ "Size": 2396 }, "lib/arm64-v8a/libmono-component-marshal-ilgen.so": { - "Size": 87080 + "Size": 87352 }, "lib/arm64-v8a/libmonodroid.so": { - "Size": 339864 + "Size": 393784 }, "lib/arm64-v8a/libmonosgen-2.0.so": { - "Size": 3184512 + "Size": 3210968 }, "lib/arm64-v8a/libSystem.IO.Compression.Native.so": { "Size": 723560 }, "lib/arm64-v8a/libSystem.Native.so": { - "Size": 94504 + "Size": 94720 }, "lib/arm64-v8a/libSystem.Security.Cryptography.Native.Android.so": { "Size": 155568 @@ -407,7 +407,7 @@ "Size": 6 }, "META-INF/BNDLTOOL.RSA": { - "Size": 1223 + "Size": 1221 }, "META-INF/BNDLTOOL.SF": { "Size": 97490 @@ -2477,5 +2477,5 @@ "Size": 812848 } }, - "PackageSize": 10864931 + "PackageSize": 10909987 } \ No newline at end of file From 7036aa53707b9be0b35b964f8d4714c2323853b3 Mon Sep 17 00:00:00 2001 From: Marek Habersack Date: Wed, 28 Feb 2024 16:46:46 +0100 Subject: [PATCH 4/8] Add more events --- src/monodroid/jni/monodroid-glue-internal.hh | 20 ++++ src/monodroid/jni/monodroid-glue.cc | 116 +++++++++++++++++-- src/monodroid/jni/timing-internal.cc | 6 +- src/monodroid/jni/timing-internal.hh | 67 +++++++---- 4 files changed, 174 insertions(+), 35 deletions(-) diff --git a/src/monodroid/jni/monodroid-glue-internal.hh b/src/monodroid/jni/monodroid-glue-internal.hh index aaf3f0c3ce2..c7f30d414d3 100644 --- a/src/monodroid/jni/monodroid-glue-internal.hh +++ b/src/monodroid/jni/monodroid-glue-internal.hh @@ -12,6 +12,7 @@ #include "cpp-util.hh" #include "xxhash.hh" +#include #include #include @@ -239,6 +240,7 @@ namespace xamarin::android::internal void timing_ensure_state () noexcept; void timing_init_extended () noexcept; void timing_init_verbose () noexcept; + void timing_init_extreme () noexcept; void init_android_runtime (JNIEnv *env, jclass runtimeClass, jobject loader); void set_environment_variable_for_directory (const char *name, jstring_wrapper &value, bool createDirectory, mode_t mode); @@ -278,6 +280,24 @@ namespace xamarin::android::internal static void prof_image_loaded (MonoProfiler *prof, MonoImage *assembly) noexcept; static void prof_class_loading (MonoProfiler *prof, MonoClass *klass) noexcept; static void prof_class_loaded (MonoProfiler *prof, MonoClass *klass) noexcept; + static void prof_vtable_loading (MonoProfiler *prof, MonoVTable *vtable) noexcept; + static void prof_vtable_loaded (MonoProfiler *prof, MonoVTable *vtable) noexcept; + static void prof_method_enter (MonoProfiler *prof, MonoMethod *method, MonoProfilerCallContext *context) noexcept; + static void prof_method_leave (MonoProfiler *prof, MonoMethod *method, MonoProfilerCallContext *context) noexcept; + static void prof_method_begin_invoke (MonoProfiler *prof, MonoMethod *method) noexcept; + static void prof_method_end_invoke (MonoProfiler *prof, MonoMethod *method) noexcept; + static void prof_monitor_contention (MonoProfiler *prof, MonoObject *object) noexcept; + static void prof_monitor_acquired (MonoProfiler *prof, MonoObject *object) noexcept; + + template + static void get_full_class_name (MonoClass *klass, internal::dynamic_local_string& info) noexcept + { + info.append (mono_class_get_namespace (klass)); + if (info.length () > 0) { + info.append ("."); + } + info.append (mono_class_get_name (klass)); + } #if !defined (RELEASE) static MonoReflectionType* typemap_java_to_managed (MonoString *java_type_name) noexcept; diff --git a/src/monodroid/jni/monodroid-glue.cc b/src/monodroid/jni/monodroid-glue.cc index f4f7132988f..57127eb6280 100644 --- a/src/monodroid/jni/monodroid-glue.cc +++ b/src/monodroid/jni/monodroid-glue.cc @@ -515,14 +515,12 @@ void MonodroidRuntime::prof_assembly_loading ([[maybe_unused]] MonoProfiler *prof, MonoAssembly *assembly) noexcept { size_t seq = internal_timing->start_event (TimingEventKind::MonoAssemblyLoad); - // This unfortunately has some overhead timing_profiler_state->add_sequence (assembly, seq); } void MonodroidRuntime::prof_assembly_loaded ([[maybe_unused]] MonoProfiler *prof, MonoAssembly *assembly) noexcept { - // This unfortunately has some overhead size_t seq = timing_profiler_state->get_sequence (assembly); internal_timing->end_event (seq, true /* uses_more_info */); internal_timing->add_more_info (seq, mono_assembly_name_get_name (mono_assembly_get_name (assembly))); @@ -532,14 +530,12 @@ void MonodroidRuntime::prof_image_loading ([[maybe_unused]] MonoProfiler *prof, MonoImage *image) noexcept { size_t seq = internal_timing->start_event (TimingEventKind::MonoImageLoad); - // This unfortunately has some overhead timing_profiler_state->add_sequence (image, seq); } void MonodroidRuntime::prof_image_loaded ([[maybe_unused]] MonoProfiler *prof, MonoImage *image) noexcept { - // This unfortunately has some overhead size_t seq = timing_profiler_state->get_sequence (image); internal_timing->end_event (seq, true /* uses_more_info */); internal_timing->add_more_info (seq, mono_image_get_name (image)); @@ -549,23 +545,101 @@ void MonodroidRuntime::prof_class_loading ([[maybe_unused]] MonoProfiler *prof, MonoClass *klass) noexcept { size_t seq = internal_timing->start_event (TimingEventKind::MonoClassLoad); - // This unfortunately has some overhead timing_profiler_state->add_sequence (klass, seq); } void MonodroidRuntime::prof_class_loaded ([[maybe_unused]] MonoProfiler *prof, MonoClass *klass) noexcept { - // This unfortunately has some overhead size_t seq = timing_profiler_state->get_sequence (klass); internal_timing->end_event (seq, true /* uses_more_info */); dynamic_local_string info; - info.append (mono_class_get_namespace (klass)); - if (info.length () > 0) { - info.append ("."); - } - info.append (mono_class_get_name (klass)); + get_full_class_name (klass, info); + internal_timing->add_more_info (seq, info); +} + +void +MonodroidRuntime::prof_vtable_loading ([[maybe_unused]] MonoProfiler *prof, MonoVTable *vtable) noexcept +{ + size_t seq = internal_timing->start_event (TimingEventKind::MonoVTableLoad); + timing_profiler_state->add_sequence (vtable, seq); +} + +void +MonodroidRuntime::prof_vtable_loaded ([[maybe_unused]] MonoProfiler *prof, MonoVTable *vtable) noexcept +{ + size_t seq = timing_profiler_state->get_sequence (vtable); + internal_timing->end_event (seq, true /* uses_more_info */); + + MonoClass *klass = mono_vtable_class (vtable); + dynamic_local_string info; + + get_full_class_name (klass, info); + internal_timing->add_more_info (seq, info); +} + +void +MonodroidRuntime::prof_method_begin_invoke ([[maybe_unused]] MonoProfiler *prof, MonoMethod *method) noexcept +{ + size_t seq = internal_timing->start_event (TimingEventKind::MonoMethodInvoke); + timing_profiler_state->add_sequence (method, seq); +} + +void +MonodroidRuntime::prof_method_end_invoke (MonoProfiler *prof, MonoMethod *method) noexcept +{ + size_t seq = timing_profiler_state->get_sequence (method); + internal_timing->end_event (seq, true /* uses_more_info */); + + MonoClass *klass = mono_method_get_class (method); + dynamic_local_string info; + + get_full_class_name (klass, info); + info.append ("."); + info.append (mono_method_get_name (method)); + internal_timing->add_more_info (seq, info); +} + +void +MonodroidRuntime::prof_method_enter ([[maybe_unused]] MonoProfiler *prof, MonoMethod *method, [[maybe_unused]] MonoProfilerCallContext *context) noexcept +{ + size_t seq = internal_timing->start_event (TimingEventKind::MonoMethodDuration); + timing_profiler_state->add_sequence (method, seq); +} + +void +MonodroidRuntime::prof_method_leave ([[maybe_unused]] MonoProfiler *prof, MonoMethod *method, [[maybe_unused]] MonoProfilerCallContext *context) noexcept +{ + size_t seq = timing_profiler_state->get_sequence (method); + internal_timing->end_event (seq, true /* uses_more_info */); + + MonoClass *klass = mono_method_get_class (method); + dynamic_local_string info; + + get_full_class_name (klass, info); + info.append ("."); + info.append (mono_method_get_name (method)); + internal_timing->add_more_info (seq, info); +} + +void +MonodroidRuntime::prof_monitor_contention ([[maybe_unused]] MonoProfiler *prof, MonoObject *object) noexcept +{ + size_t seq = internal_timing->start_event (TimingEventKind::LockContention); + timing_profiler_state->add_sequence (object, seq); +} + +void +MonodroidRuntime::prof_monitor_acquired ([[maybe_unused]] MonoProfiler *prof, MonoObject *object) noexcept +{ + size_t seq = timing_profiler_state->get_sequence (object); + internal_timing->end_event (seq, true /* uses_more_info */); + + MonoClass *klass = mono_object_get_class (object); + dynamic_local_string info; + + get_full_class_name (klass, info); internal_timing->add_more_info (seq, info); } @@ -602,9 +676,23 @@ MonodroidRuntime::timing_init_verbose () noexcept mono_profiler_set_jit_begin_callback (profiler_handle, jit_begin); mono_profiler_set_jit_done_callback (profiler_handle, jit_done); mono_profiler_set_jit_failed_callback (profiler_handle, jit_failed); - mono_profiler_set_class_loading_callback (profiler_handle, prof_class_loading); mono_profiler_set_class_loaded_callback (profiler_handle, prof_class_loaded); + mono_profiler_set_vtable_loading_callback (profiler_handle, prof_vtable_loading); + mono_profiler_set_vtable_loaded_callback (profiler_handle, prof_vtable_loaded); + mono_profiler_set_monitor_contention_callback (profiler_handle, prof_monitor_contention); + mono_profiler_set_monitor_acquired_callback (profiler_handle, prof_monitor_acquired); +} + +force_inline void +MonodroidRuntime::timing_init_extreme () noexcept +{ + timing_ensure_state (); + + mono_profiler_set_method_begin_invoke_callback (profiler_handle, prof_method_begin_invoke); + mono_profiler_set_method_end_invoke_callback (profiler_handle, prof_method_end_invoke); + mono_profiler_set_method_enter_callback (profiler_handle, prof_method_enter); + mono_profiler_set_method_leave_callback (profiler_handle, prof_method_leave); } force_inline void @@ -616,6 +704,10 @@ MonodroidRuntime::timing_init () noexcept // TODO: time this, so that we can subtract it from the cumulative results switch (FastTiming::mode ()) { + case TimingMode::Extreme: + timing_init_extreme (); + [[fallthrough]]; + case TimingMode::Verbose: timing_init_verbose (); [[fallthrough]]; diff --git a/src/monodroid/jni/timing-internal.cc b/src/monodroid/jni/timing-internal.cc index 1895fab9533..fb72845e4ed 100644 --- a/src/monodroid/jni/timing-internal.cc +++ b/src/monodroid/jni/timing-internal.cc @@ -60,6 +60,11 @@ FastTiming::parse_options (dynamic_local_string const timing_mode = TimingMode::Verbose; continue; } + + if (param.equal (OPT_MODE.length (), OPT_MODE_EXTREME)) { + timing_mode = TimingMode::Extreme; + continue; + } continue; } @@ -193,6 +198,5 @@ FastTiming::dump () noexcept dump_to_file (entries); } else { dump_to_logcat (entries); - } } diff --git a/src/monodroid/jni/timing-internal.hh b/src/monodroid/jni/timing-internal.hh index 8aadbb88642..f75f0a02301 100644 --- a/src/monodroid/jni/timing-internal.hh +++ b/src/monodroid/jni/timing-internal.hh @@ -4,6 +4,7 @@ #include #include #include +#include #include #include "logger.hh" @@ -42,6 +43,8 @@ namespace xamarin::android::internal MonoAssemblyLoad = 15, MonoMethodDuration = 16, MonoMethodInvoke = 17, + MonoVTableLoad = 18, + LockContention = 19, Unspecified = std::numeric_limits>::max (), }; @@ -50,6 +53,7 @@ namespace xamarin::android::internal Bare, Extended, Verbose, + Extreme, }; struct TimingEventPoint @@ -72,6 +76,7 @@ namespace xamarin::android::internal TimingEventPoint end; TimingEventKind kind; const char* more_info; + size_t more_info_length; }; template @@ -113,6 +118,7 @@ namespace xamarin::android::internal static constexpr std::string_view OPT_MODE_BARE { "bare" }; static constexpr std::string_view OPT_MODE_EXTENDED { "extended" }; static constexpr std::string_view OPT_MODE_VERBOSE { "verbose" }; + static constexpr std::string_view OPT_MODE_EXTREME { "extreme" }; static constexpr std::string_view OPT_TO_FILE { "to-file" }; // Results dump stage log markers @@ -241,7 +247,9 @@ namespace xamarin::android::internal return; } - events[event_index].more_info = utils.strdup_new (str.get (), str.length ()); + size_t len = str.length (); + events[event_index].more_info_length = len; + events[event_index].more_info = utils.strdup_new (str.get (), len); log (events[event_index], false /* skip_log_if_more_info_missing */); } @@ -251,7 +259,9 @@ namespace xamarin::android::internal return; } - events[event_index].more_info = utils.strdup_new (str, strlen (str)); + size_t len = strlen (str); + events[event_index].more_info_length = len; + events[event_index].more_info = utils.strdup_new (str, len); log (events[event_index], false /* skip_log_if_more_info_missing */); } @@ -329,73 +339,73 @@ namespace xamarin::android::internal { switch (kind) { case TimingEventKind::AssemblyDecompression: { - constexpr char desc[] = "LZ4 decompression time for "; + constexpr std::string_view desc { "LZ4 decompression time for " }; message.append (desc); return; } case TimingEventKind::AssemblyLoad: { - constexpr char desc[] = "Assembly load"; + constexpr std::string_view desc { "Assembly load" }; message.append (desc); return; } case TimingEventKind::AssemblyPreload: { - constexpr char desc[] = "Finished preloading, number of loaded assemblies: "; + constexpr std::string_view desc { "Finished preloading, number of loaded assemblies: " }; message.append (desc); return; } case TimingEventKind::DebugStart: { - constexpr char desc[] = "Debug::start_debugging_and_profiling: end"; + constexpr std::string_view desc { "Debug::start_debugging_and_profiling: end" }; message.append (desc); return; } case TimingEventKind::Init: { - constexpr char desc[] = "XATiming: init time"; + constexpr std::string_view desc { "XATiming: init time" }; message.append (desc); return; } case TimingEventKind::JavaToManaged: { - constexpr char desc[] = "Typemap.java_to_managed: end, total time"; + constexpr std::string_view desc { "Typemap.java_to_managed: end, total time" }; message.append (desc); return; } case TimingEventKind::ManagedToJava: { - constexpr char desc[] = "Typemap.managed_to_java: end, total time"; + constexpr std::string_view desc { "Typemap.managed_to_java: end, total time" }; message.append (desc); return; } case TimingEventKind::MonoRuntimeInit: { - constexpr char desc[] = "Runtime.init: Mono runtime init"; + constexpr std::string_view desc { "Runtime.init: Mono runtime init" }; message.append (desc); return; } case TimingEventKind::NativeToManagedTransition: { - constexpr char desc[] = "Runtime.init: end native-to-managed transition"; + constexpr std::string_view desc = { "Runtime.init: end native-to-managed transition" }; message.append (desc); return; } case TimingEventKind::RuntimeConfigBlob: { - constexpr char desc[] = "Register runtimeconfig binary blob"; + constexpr std::string_view desc = { "Register runtimeconfig binary blob" }; message.append (desc); return; } case TimingEventKind::RuntimeRegister: { - constexpr char desc[] = "Runtime.register: end time. Registered type: "; + constexpr std::string_view desc = { "Runtime.register: end time. Registered type: " }; message.append (desc); return; } case TimingEventKind::TotalRuntimeInit: { - constexpr char desc[] = "Runtime.init: end, total time"; + constexpr std::string_view desc = { "Runtime.init: end, total time" }; message.append (desc); return; } @@ -436,8 +446,20 @@ namespace xamarin::android::internal return; } + case TimingEventKind::MonoVTableLoad: { + constexpr std::string_view desc { "MonoVM vtable load duration: " }; + message.append (desc); + return; + } + + case TimingEventKind::LockContention: { + constexpr std::string_view desc { "MonoVM lock contention duration: " }; + message.append (desc); + return; + } + default: { - constexpr char desc[] = "Unknown timing event"; + constexpr std::string_view desc = { "Unknown timing event" }; message.append (desc); return; } @@ -462,9 +484,9 @@ namespace xamarin::android::internal template force_inline static void format_and_log (TimingEvent const& event, TimingInterval const& interval, dynamic_local_string& message, bool indent = false) noexcept { - constexpr char INDENT[] = " "; - constexpr char NATIVE_INIT_TAG[] = "[0/"; - constexpr char MANAGED_TAG[] = "[1/"; + constexpr std::string_view INDENT { " " }; + constexpr std::string_view NATIVE_INIT_TAG { "[0/" }; + constexpr std::string_view MANAGED_TAG { "[1/" }; message.clear (); if (indent) { @@ -482,13 +504,14 @@ namespace xamarin::android::internal append_event_kind_description (event.kind, message); if (event.more_info != nullptr && *event.more_info != '\0') { - message.append (event.more_info, strlen (event.more_info)); + message.append (event.more_info, event.more_info_length); } - constexpr char COLON[] = ":"; - constexpr char TWO_COLONS[] = "::"; + constexpr std::string_view COLON { ":" }; + constexpr std::string_view TWO_COLONS { "::" }; + constexpr std::string_view ELAPSED { "; elapsed: " }; - message.append ("; elapsed: "); + message.append (ELAPSED); message.append (static_cast(interval.sec)); message.append (COLON); message.append (interval.ms); From 13cfef86c5b64ac9c53b13c4fc4168019c066afb Mon Sep 17 00:00:00 2001 From: Marek Habersack Date: Thu, 29 Feb 2024 18:27:45 +0100 Subject: [PATCH 5/8] It's obvious it's about duration... --- src/monodroid/jni/monodroid-glue.cc | 2 +- src/monodroid/jni/timing-internal.hh | 6 +++--- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/src/monodroid/jni/monodroid-glue.cc b/src/monodroid/jni/monodroid-glue.cc index 57127eb6280..a2964778f8d 100644 --- a/src/monodroid/jni/monodroid-glue.cc +++ b/src/monodroid/jni/monodroid-glue.cc @@ -587,7 +587,7 @@ MonodroidRuntime::prof_method_begin_invoke ([[maybe_unused]] MonoProfiler *prof, } void -MonodroidRuntime::prof_method_end_invoke (MonoProfiler *prof, MonoMethod *method) noexcept +MonodroidRuntime::prof_method_end_invoke ([[maybe_unused]] MonoProfiler *prof, MonoMethod *method) noexcept { size_t seq = timing_profiler_state->get_sequence (method); internal_timing->end_event (seq, true /* uses_more_info */); diff --git a/src/monodroid/jni/timing-internal.hh b/src/monodroid/jni/timing-internal.hh index f75f0a02301..3e4f61632ef 100644 --- a/src/monodroid/jni/timing-internal.hh +++ b/src/monodroid/jni/timing-internal.hh @@ -441,19 +441,19 @@ namespace xamarin::android::internal } case TimingEventKind::MonoMethodDuration: { - constexpr std::string_view desc { "MonoVM method self duration: " }; + constexpr std::string_view desc { "MonoVM method self: " }; message.append (desc); return; } case TimingEventKind::MonoVTableLoad: { - constexpr std::string_view desc { "MonoVM vtable load duration: " }; + constexpr std::string_view desc { "MonoVM vtable load: " }; message.append (desc); return; } case TimingEventKind::LockContention: { - constexpr std::string_view desc { "MonoVM lock contention duration: " }; + constexpr std::string_view desc { "MonoVM lock contention: " }; message.append (desc); return; } From f78eec15d4e9aff7803a76fc604b09528e0ad2f1 Mon Sep 17 00:00:00 2001 From: Marek Habersack Date: Fri, 1 Mar 2024 14:24:29 +0100 Subject: [PATCH 6/8] WIP for writing to file --- src/monodroid/jni/basic-utilities.cc | 25 +++++- src/monodroid/jni/basic-utilities.hh | 3 + src/monodroid/jni/monodroid-glue.cc | 1 + src/monodroid/jni/timing-internal.cc | 110 +++++++++++++++++++++------ src/monodroid/jni/timing-internal.hh | 33 ++++++-- 5 files changed, 141 insertions(+), 31 deletions(-) diff --git a/src/monodroid/jni/basic-utilities.cc b/src/monodroid/jni/basic-utilities.cc index a84ec879614..7d34268757c 100644 --- a/src/monodroid/jni/basic-utilities.cc +++ b/src/monodroid/jni/basic-utilities.cc @@ -34,7 +34,10 @@ void BasicUtilities::create_public_directory (const char *dir) { mode_t m = umask (0); - mkdir (dir, 0777); + int ret = mkdir (dir, 0777); + if (ret < 0) { + log_warn (LOG_DEFAULT, "Failed to create directory '%s'. %s", dir, std::strerror (errno)); + } umask (m); } @@ -85,6 +88,26 @@ BasicUtilities::set_world_accessable ([[maybe_unused]] const char *path) } } +bool +BasicUtilities::set_world_accessible (int fd) noexcept +{ + if (fd < 0) { + return false; + } + + int r; + do { + r = fchmod (fd, 0664); + } while (r == -1 && errno == EINTR); + + if (r == -1) { + log_error (LOG_DEFAULT, "fchmod(%d, 0664) failed: %s", fd, strerror (errno)); + return false; + } + + return true; +} + void BasicUtilities::set_user_executable ([[maybe_unused]] const char *path) { diff --git a/src/monodroid/jni/basic-utilities.hh b/src/monodroid/jni/basic-utilities.hh index 3ed41659c91..86e245322b7 100644 --- a/src/monodroid/jni/basic-utilities.hh +++ b/src/monodroid/jni/basic-utilities.hh @@ -34,6 +34,9 @@ namespace xamarin::android void create_public_directory (const char *dir); int create_directory (const char *pathname, mode_t mode); void set_world_accessable (const char *path); + + [[nodiscard]] + bool set_world_accessible (int fd) noexcept; void set_user_executable (const char *path); bool file_exists (const char *file); bool directory_exists (const char *directory); diff --git a/src/monodroid/jni/monodroid-glue.cc b/src/monodroid/jni/monodroid-glue.cc index a2964778f8d..b7cb2cb15ab 100644 --- a/src/monodroid/jni/monodroid-glue.cc +++ b/src/monodroid/jni/monodroid-glue.cc @@ -669,6 +669,7 @@ MonodroidRuntime::timing_init_verbose () noexcept { timing_ensure_state (); + utils.create_directory (AndroidSystem::override_dirs [0], 0755); std::unique_ptr jit_log_path {utils.path_combine (androidSystem.override_dirs[0], "methods.txt")}; jit_log = utils.monodroid_fopen (jit_log_path.get (), "a"); utils.set_world_accessable (jit_log_path.get ()); diff --git a/src/monodroid/jni/timing-internal.cc b/src/monodroid/jni/timing-internal.cc index fb72845e4ed..0a34d46c0b1 100644 --- a/src/monodroid/jni/timing-internal.cc +++ b/src/monodroid/jni/timing-internal.cc @@ -74,7 +74,7 @@ FastTiming::parse_options (dynamic_local_string const } if (param.starts_with (OPT_FILE_NAME)) { - output_file_name = utils.strdup_new (param.start () + OPT_FILE_NAME.length (), param.length () - OPT_FILE_NAME.length ()); + output_file_name = new std::string (param.start () + OPT_FILE_NAME.length (), param.length () - OPT_FILE_NAME.length ()); continue; } @@ -108,26 +108,28 @@ FastTiming::no_events_logged (size_t entries) noexcept return true; } -void -FastTiming::dump_to_logcat (size_t entries) noexcept +template< + size_t BufferSize, + void(line_writer)(dynamic_local_string const& buffer), + void(event_writer)(TimingEvent const& event, dynamic_local_string& buffer, uint64_t& total_ns, bool indent) +> +force_inline void +FastTiming::dump (size_t entries, bool indent) noexcept { - log_info_nocheck (LOG_TIMING, "[%s] Performance measurement results", DUMP_STAGE_RESULTS_TAG.data ()); - if (no_events_logged (entries)) { - return; - } - - dynamic_local_string message; + dynamic_local_string message; // Values are in nanoseconds, we don't need to worry about overflow for our needs, when accumulating. uint64_t total_assembly_load_time = 0; uint64_t total_java_to_managed_time = 0; uint64_t total_managed_to_java_time = 0; - uint64_t total_ns; // initialized by `calculate_interval` + uint64_t total_ns; // initialized by `calculate_interval`, via `event_writer` and the `format_*` functions + + format_message (init_time, message, total_ns, indent); + line_writer (message); - format_and_log (init_time, message, total_ns, true /* indent */); for (size_t i = 0; i < entries; i++) { TimingEvent const& event = events[i]; - format_and_log (event, message, total_ns, true /* indent */); + event_writer (event, message, total_ns, indent); switch (event.kind) { case TimingEventKind::AssemblyLoad: @@ -148,34 +150,94 @@ FastTiming::dump_to_logcat (size_t entries) noexcept } } - uint32_t sec, ms, ns; - log_info_nocheck (LOG_TIMING, "[%s] Accumulated performance results", DUMP_STAGE_ACCUMULATED_RESULTS_TAG.data ()); + message.clear (); + message.append ("[") + .append (DUMP_STAGE_RESULTS_TAG) + .append ("]") + .append (" Accumulated performance results"); + + auto make_message = [](dynamic_local_string &buf, std::string_view const& tag, std::string_view const& label, uint32_t sec, uint32_t ms, uint32_t ns) -> void { + buf.clear (); + + buf.append (" [") + .append (tag) + .append ("] ") + .append (label) + .append (": ") + .append (sec) + .append (":") + .append (ms) + .append ("::") + .append (ns); + }; + + message.clear (); + message.append ("[") + .append (DUMP_STAGE_ACCUMULATED_RESULTS_TAG) + .append ("] ") + .append ("Accumulated performance results"); + line_writer (message); + uint32_t sec, ms, ns; ns_to_time (total_assembly_load_time, sec, ms, ns); - log_info_nocheck (LOG_TIMING, " [%s] Assembly load: %u:%u::%u", DUMP_STAGE_ACC_ASSEMBLY_LOAD_TAG.data (), sec, ms, ns); + make_message (message, DUMP_STAGE_ACC_ASSEMBLY_LOAD_TAG, "Assembly load", sec, ms, ns); + line_writer (message); ns_to_time (total_java_to_managed_time, sec, ms, ns); - log_info_nocheck (LOG_TIMING, " [%s] Java to Managed lookup: %u:%u::%u", DUMP_STAGE_ACC_JAVA_TO_MANAGED_TAG.data (), sec, ms, ns); + make_message (message, DUMP_STAGE_ACC_JAVA_TO_MANAGED_TAG, "Java to Managed lookup", sec, ms, ns); + line_writer (message); ns_to_time (total_managed_to_java_time, sec, ms, ns); - log_info_nocheck (LOG_TIMING, " [%s] Managed to Java lookup: %u:%u::%u", DUMP_STAGE_ACC_MANAGED_TO_JAVA_TAG.data (), sec, ms, ns); + make_message (message, DUMP_STAGE_ACC_MANAGED_TO_JAVA_TAG, "Managed to Java lookup", sec, ms, ns); + line_writer (message); } void -FastTiming::dump_to_file (size_t entries) noexcept +FastTiming::dump_to_logcat (size_t entries) noexcept { - std::unique_ptr timing_log_path { - utils.path_combine ( - androidSystem.override_dirs[0], - output_file_name == nullptr ? default_timing_file_name.data () : output_file_name - ) + log_info_nocheck (LOG_TIMING, "[%s] Performance measurement results", DUMP_STAGE_RESULTS_TAG.data ()); + if (no_events_logged (entries)) { + return; + } + + const size_t BufferSize = SharedConstants::MAX_LOGCAT_MESSAGE_LENGTH; + using TBuffer = dynamic_local_string; + TBuffer message; + + auto event_writer = [](TimingEvent const& event, TBuffer& buffer, uint64_t& total_ns, bool indent) { + format_and_log (event, buffer, total_ns, indent); }; - log_info (LOG_TIMING, "[%s] Performance measurement results logged to file: %s", DUMP_STAGE_RESULTS_TAG.data (), timing_log_path.get ()); + auto line_writer = [](TBuffer const& buffer) { + log_info_nocheck (LOG_TIMING, buffer.get ()); + }; + + dump (entries, true /* indent */); +} + +void +FastTiming::dump_to_file (size_t entries) noexcept +{ if (no_events_logged (entries)) { return; } + dynamic_local_string timing_log_path; + timing_log_path.assign_c (androidSystem.override_dirs[0]); + timing_log_path.append (output_file_name == nullptr ? default_timing_file_name : *output_file_name); + utils.create_directory (AndroidSystem::override_dirs [0], 0755); + + FILE *timing_log = utils.monodroid_fopen (timing_log_path.get (), "a"); + if (timing_log == nullptr) { + log_error (LOG_TIMING, "[%s] Unable to create the performance measurements file '%s'", DUMP_STAGE_RESULTS_TAG.data (), timing_log_path.get ()); + return; + } + + if (!utils.set_world_accessible (fileno (timing_log))) { + log_warn (LOG_TIMING, "[%s] Failed to make performance measurements file '%s' world-readable", DUMP_STAGE_RESULTS_TAG.data (), timing_log_path.get ()); + } + + log_info (LOG_TIMING, "[%s] Performance measurement results logged to file: %s", DUMP_STAGE_RESULTS_TAG.data (), timing_log_path.get ()); // TODO: implement } diff --git a/src/monodroid/jni/timing-internal.hh b/src/monodroid/jni/timing-internal.hh index 3e4f61632ef..75218323a5e 100644 --- a/src/monodroid/jni/timing-internal.hh +++ b/src/monodroid/jni/timing-internal.hh @@ -4,6 +4,7 @@ #include #include #include +#include #include #include @@ -319,6 +320,13 @@ namespace xamarin::android::internal void dump_to_logcat (size_t entries) noexcept; void dump_to_file (size_t entries) noexcept; + template< + size_t BufferSize, + void(line_writer)(dynamic_local_string const& buffer), + void(event_writer)(TimingEvent const& event, dynamic_local_string& buffer, uint64_t& total_ns, bool indent) + > + void dump (size_t entries, bool indent) noexcept; + force_inline static void mark (TimingEventPoint &point) noexcept { get_time (point.sec, point.ns); @@ -482,11 +490,11 @@ namespace xamarin::android::internal // having to be kept in sync with the actual wording used for the event message. // template - force_inline static void format_and_log (TimingEvent const& event, TimingInterval const& interval, dynamic_local_string& message, bool indent = false) noexcept + force_inline static void format_message (TimingEvent const& event, TimingInterval const& interval, dynamic_local_string& message, bool indent = false) noexcept { - constexpr std::string_view INDENT { " " }; + constexpr std::string_view INDENT { " " }; constexpr std::string_view NATIVE_INIT_TAG { "[0/" }; - constexpr std::string_view MANAGED_TAG { "[1/" }; + constexpr std::string_view MANAGED_TAG { "[1/" }; message.clear (); if (indent) { @@ -507,9 +515,9 @@ namespace xamarin::android::internal message.append (event.more_info, event.more_info_length); } - constexpr std::string_view COLON { ":" }; + constexpr std::string_view COLON { ":" }; constexpr std::string_view TWO_COLONS { "::" }; - constexpr std::string_view ELAPSED { "; elapsed: " }; + constexpr std::string_view ELAPSED { "; elapsed: " }; message.append (ELAPSED); message.append (static_cast(interval.sec)); @@ -517,7 +525,20 @@ namespace xamarin::android::internal message.append (interval.ms); message.append (TWO_COLONS); message.append (interval.ns); + } + + template + force_inline static void format_message (TimingEvent const& event, dynamic_local_string& message, uint64_t& total_ns, bool indent = false) noexcept + { + TimingInterval interval; + calculate_interval (event.start, event.end, interval, total_ns); + format_message (event, interval, message, indent); + } + template + force_inline static void format_and_log (TimingEvent const& event, TimingInterval const& interval, dynamic_local_string& message, bool indent = false) noexcept + { + format_message (event, interval, message, indent); log_write (LOG_TIMING, LogLevel::Info, message.get ()); } @@ -580,7 +601,7 @@ namespace xamarin::android::internal static inline TimingMode timing_mode = default_timing_mode; static inline bool log_to_file = default_log_to_file; static inline size_t duration_ms = default_duration_milliseconds; - static inline char* output_file_name = nullptr; + static inline std::string* output_file_name = nullptr; }; extern FastTiming *internal_timing; From 3cccaaebfec2136d3904e0ceb921b8834f17fd41 Mon Sep 17 00:00:00 2001 From: Marek Habersack Date: Fri, 1 Mar 2024 18:59:35 +0100 Subject: [PATCH 7/8] Update apkdesc --- .../Base/BuildReleaseArm64SimpleDotNet.apkdesc | 12 ++++++------ .../Base/BuildReleaseArm64XFormsDotNet.apkdesc | 10 +++++----- 2 files changed, 11 insertions(+), 11 deletions(-) diff --git a/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Resources/Base/BuildReleaseArm64SimpleDotNet.apkdesc b/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Resources/Base/BuildReleaseArm64SimpleDotNet.apkdesc index fb3a68d2e61..4e694330690 100644 --- a/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Resources/Base/BuildReleaseArm64SimpleDotNet.apkdesc +++ b/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Resources/Base/BuildReleaseArm64SimpleDotNet.apkdesc @@ -11,10 +11,10 @@ "Size": 64193 }, "assemblies/Mono.Android.dll": { - "Size": 90538 + "Size": 90536 }, "assemblies/Mono.Android.Runtime.dll": { - "Size": 5147 + "Size": 5145 }, "assemblies/rc.bin": { "Size": 1512 @@ -35,7 +35,7 @@ "Size": 4022 }, "assemblies/UnnamedProject.dll": { - "Size": 2934 + "Size": 2932 }, "classes.dex": { "Size": 377748 @@ -44,7 +44,7 @@ "Size": 87352 }, "lib/arm64-v8a/libmonodroid.so": { - "Size": 393784 + "Size": 449192 }, "lib/arm64-v8a/libmonosgen-2.0.so": { "Size": 3210968 @@ -62,7 +62,7 @@ "Size": 11648 }, "META-INF/BNDLTOOL.RSA": { - "Size": 1223 + "Size": 1221 }, "META-INF/BNDLTOOL.SF": { "Size": 3037 @@ -95,5 +95,5 @@ "Size": 1904 } }, - "PackageSize": 2828618 + "PackageSize": 2836810 } \ No newline at end of file diff --git a/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Resources/Base/BuildReleaseArm64XFormsDotNet.apkdesc b/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Resources/Base/BuildReleaseArm64XFormsDotNet.apkdesc index f451bc70658..fc9199e0ab7 100644 --- a/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Resources/Base/BuildReleaseArm64XFormsDotNet.apkdesc +++ b/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Resources/Base/BuildReleaseArm64XFormsDotNet.apkdesc @@ -14,10 +14,10 @@ "Size": 72360 }, "assemblies/Mono.Android.dll": { - "Size": 456314 + "Size": 456313 }, "assemblies/Mono.Android.Runtime.dll": { - "Size": 5147 + "Size": 5145 }, "assemblies/mscorlib.dll": { "Size": 3992 @@ -239,7 +239,7 @@ "Size": 87352 }, "lib/arm64-v8a/libmonodroid.so": { - "Size": 393784 + "Size": 449192 }, "lib/arm64-v8a/libmonosgen-2.0.so": { "Size": 3210968 @@ -407,7 +407,7 @@ "Size": 6 }, "META-INF/BNDLTOOL.RSA": { - "Size": 1221 + "Size": 1223 }, "META-INF/BNDLTOOL.SF": { "Size": 97490 @@ -2477,5 +2477,5 @@ "Size": 812848 } }, - "PackageSize": 10909987 + "PackageSize": 10918179 } \ No newline at end of file From 0a3d18d6a0c9f87cae51c38d6bc23ae037cec578 Mon Sep 17 00:00:00 2001 From: Marek Habersack Date: Mon, 11 Mar 2024 11:31:12 +0100 Subject: [PATCH 8/8] Update apkdesc --- .../BuildReleaseArm64XFormsDotNet.apkdesc | 92 +++++++++---------- 1 file changed, 46 insertions(+), 46 deletions(-) diff --git a/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Resources/Base/BuildReleaseArm64XFormsDotNet.apkdesc b/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Resources/Base/BuildReleaseArm64XFormsDotNet.apkdesc index 58f281d0e0c..0c78ad90c5b 100644 --- a/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Resources/Base/BuildReleaseArm64XFormsDotNet.apkdesc +++ b/src/Xamarin.Android.Build.Tasks/Tests/Xamarin.ProjectTools/Resources/Base/BuildReleaseArm64XFormsDotNet.apkdesc @@ -11,133 +11,133 @@ "Size": 8090 }, "assemblies/Java.Interop.dll": { - "Size": 72297 + "Size": 72369 }, "assemblies/Mono.Android.dll": { - "Size": 456687 + "Size": 456448 }, "assemblies/Mono.Android.Runtime.dll": { - "Size": 5143 + "Size": 5142 }, "assemblies/mscorlib.dll": { - "Size": 3999 + "Size": 3989 }, "assemblies/netstandard.dll": { - "Size": 5632 + "Size": 5623 }, "assemblies/rc.bin": { "Size": 1512 }, "assemblies/System.Collections.Concurrent.dll": { - "Size": 11523 + "Size": 11518 }, "assemblies/System.Collections.dll": { - "Size": 15415 + "Size": 15410 }, "assemblies/System.Collections.NonGeneric.dll": { - "Size": 7445 + "Size": 7440 }, "assemblies/System.ComponentModel.dll": { - "Size": 1941 + "Size": 1933 }, "assemblies/System.ComponentModel.Primitives.dll": { - "Size": 2555 + "Size": 2547 }, "assemblies/System.ComponentModel.TypeConverter.dll": { - "Size": 6089 + "Size": 6082 }, "assemblies/System.Console.dll": { - "Size": 6582 + "Size": 6572 }, "assemblies/System.Core.dll": { - "Size": 1976 + "Size": 1967 }, "assemblies/System.Diagnostics.DiagnosticSource.dll": { - "Size": 9064 + "Size": 9058 }, "assemblies/System.Diagnostics.TraceSource.dll": { - "Size": 6547 + "Size": 6542 }, "assemblies/System.dll": { - "Size": 2333 + "Size": 2324 }, "assemblies/System.Drawing.dll": { - "Size": 1937 + "Size": 1930 }, "assemblies/System.Drawing.Primitives.dll": { - "Size": 11966 + "Size": 11963 }, "assemblies/System.IO.Compression.Brotli.dll": { - "Size": 11192 + "Size": 11185 }, "assemblies/System.IO.Compression.dll": { - "Size": 15868 + "Size": 15860 }, "assemblies/System.IO.IsolatedStorage.dll": { - "Size": 9899 + "Size": 9890 }, "assemblies/System.Linq.dll": { - "Size": 20517 + "Size": 20124 }, "assemblies/System.Linq.Expressions.dll": { - "Size": 164631 + "Size": 164627 }, "assemblies/System.Net.Http.dll": { - "Size": 67564 + "Size": 67562 }, "assemblies/System.Net.Primitives.dll": { - "Size": 22363 + "Size": 22235 }, "assemblies/System.Net.Requests.dll": { - "Size": 3594 + "Size": 3586 }, "assemblies/System.ObjectModel.dll": { - "Size": 8572 + "Size": 8562 }, "assemblies/System.Private.CoreLib.dll": { - "Size": 869622 + "Size": 870760 }, "assemblies/System.Private.DataContractSerialization.dll": { - "Size": 193441 + "Size": 193443 }, "assemblies/System.Private.Uri.dll": { - "Size": 42907 + "Size": 42904 }, "assemblies/System.Private.Xml.dll": { - "Size": 216025 + "Size": 216019 }, "assemblies/System.Private.Xml.Linq.dll": { - "Size": 16627 + "Size": 16621 }, "assemblies/System.Runtime.dll": { - "Size": 2709 + "Size": 2701 }, "assemblies/System.Runtime.InteropServices.dll": { - "Size": 4022 + "Size": 4020 }, "assemblies/System.Runtime.Serialization.dll": { - "Size": 1865 + "Size": 1857 }, "assemblies/System.Runtime.Serialization.Formatters.dll": { - "Size": 2485 + "Size": 2477 }, "assemblies/System.Runtime.Serialization.Primitives.dll": { - "Size": 3757 + "Size": 3750 }, "assemblies/System.Security.Cryptography.dll": { - "Size": 8102 + "Size": 8099 }, "assemblies/System.Text.RegularExpressions.dll": { - "Size": 159848 + "Size": 161337 }, "assemblies/System.Xml.dll": { - "Size": 1760 + "Size": 1752 }, "assemblies/System.Xml.Linq.dll": { - "Size": 1775 + "Size": 1768 }, "assemblies/UnnamedProject.dll": { - "Size": 5007 + "Size": 5006 }, "assemblies/Xamarin.AndroidX.Activity.dll": { "Size": 16116 @@ -239,10 +239,10 @@ "Size": 87352 }, "lib/arm64-v8a/libmonodroid.so": { - "Size": 343896 + "Size": 449192 }, "lib/arm64-v8a/libmonosgen-2.0.so": { - "Size": 3210968 + "Size": 3211192 }, "lib/arm64-v8a/libSystem.IO.Compression.Native.so": { "Size": 723560 @@ -407,7 +407,7 @@ "Size": 6 }, "META-INF/BNDLTOOL.RSA": { - "Size": 1221 + "Size": 1223 }, "META-INF/BNDLTOOL.SF": { "Size": 97490 @@ -2477,5 +2477,5 @@ "Size": 812848 } }, - "PackageSize": 10897699 + "PackageSize": 10918179 } \ No newline at end of file