From ec3e32efb86e3c286e142797b033eff1c86b2c6d Mon Sep 17 00:00:00 2001 From: Marek Habersack Date: Tue, 5 Nov 2024 22:45:51 +0100 Subject: [PATCH 1/4] Spiff up method JIT tracing a bit --- src/native/monodroid/CMakeLists.txt | 1 + .../monodroid/monodroid-glue-internal.hh | 22 +++- src/native/monodroid/monodroid-glue.cc | 111 +++++++++++++++--- src/native/monodroid/performance-methods.cc | 77 ++++++++++++ src/native/monodroid/performance-methods.hh | 22 ++++ .../pinvoke-override/pinvoke-override-api.hh | 25 +--- src/native/runtime-base/robin_map.hh | 25 ++++ 7 files changed, 241 insertions(+), 42 deletions(-) create mode 100644 src/native/monodroid/performance-methods.cc create mode 100644 src/native/monodroid/performance-methods.hh create mode 100644 src/native/runtime-base/robin_map.hh diff --git a/src/native/monodroid/CMakeLists.txt b/src/native/monodroid/CMakeLists.txt index 8a5ebc0ec12..def500a6df1 100644 --- a/src/native/monodroid/CMakeLists.txt +++ b/src/native/monodroid/CMakeLists.txt @@ -108,6 +108,7 @@ set(XAMARIN_MONODROID_SOURCES monodroid-tracing.cc monovm-properties.cc osbridge.cc + performance-methods.cc runtime-util.cc timezones.cc xamarin_getifaddrs.cc diff --git a/src/native/monodroid/monodroid-glue-internal.hh b/src/native/monodroid/monodroid-glue-internal.hh index abbd8a8d4c6..ea209b91b77 100644 --- a/src/native/monodroid/monodroid-glue-internal.hh +++ b/src/native/monodroid/monodroid-glue-internal.hh @@ -10,6 +10,7 @@ #include "osbridge.hh" #include "timing.hh" #include "cpp-util.hh" +#include "performance-methods.hh" #include "xxhash.hh" #include "monodroid-dl.hh" @@ -59,6 +60,14 @@ namespace xamarin::android::internal Signals = 0x08, }; + enum class MethodEvent + { + JitBegin, + JitFailed, + JitDone, + Enter, + }; + class MonodroidRuntime { using load_assemblies_context_type = MonoAssemblyLoadContextGCHandle; @@ -146,6 +155,7 @@ namespace xamarin::android::internal void propagate_uncaught_exception (JNIEnv *env, jobject javaThread, jthrowable javaException); char* get_java_class_name_for_TypeManager (jclass klass); void log_traces (JNIEnv *env, TraceKind kind, const char *first_line) noexcept; + void dump_method_events (); private: static void mono_log_handler (const char *log_domain, const char *log_level, const char *message, mono_bool fatal, void *user_data); @@ -212,12 +222,18 @@ namespace xamarin::android::internal void set_trace_options (); void set_profile_options (); - void log_jit_event (MonoMethod *method, const char *event_name); + void log_method_event (MonoMethod *method, MethodEvent event); static void jit_begin (MonoProfiler *prof, MonoMethod *method); static void jit_failed (MonoProfiler *prof, MonoMethod *method); 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_method_begin_invoke (MonoProfiler *prof, MonoMethod *method) noexcept; + static void prof_method_end_invoke (MonoProfiler *prof, MonoMethod *method) 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 MonoProfilerCallInstrumentationFlags prof_method_filter (MonoProfiler *prof, MonoMethod *method) 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; @@ -252,7 +268,6 @@ namespace xamarin::android::internal jmethodID java_System_identityHashCode; jmethodID Class_getName; jclass java_TimeZone; - timing_period jit_time; FILE *jit_log; MonoProfilerHandle profiler_handle; @@ -274,6 +289,9 @@ namespace xamarin::android::internal static MonoCoreRuntimeProperties monovm_core_properties; MonovmRuntimeConfigArguments runtime_config_args; + + std::unique_ptr method_event_map{}; + static inline std::unique_ptr method_event_map_write_lock; }; } #endif diff --git a/src/native/monodroid/monodroid-glue.cc b/src/native/monodroid/monodroid-glue.cc index cd8d899a35d..60631699e88 100644 --- a/src/native/monodroid/monodroid-glue.cc +++ b/src/native/monodroid/monodroid-glue.cc @@ -102,37 +102,93 @@ MonodroidRuntime::thread_end ([[maybe_unused]] MonoProfiler *prof, [[maybe_unuse } inline void -MonodroidRuntime::log_jit_event (MonoMethod *method, const char *event_name) +MonodroidRuntime::log_method_event (MonoMethod *method, MethodEvent event) { - jit_time.mark_end (); - - if (jit_log == nullptr) + if (!method_event_map) [[unlikely]] { return; + } + + char* name = mono_method_full_name (method, TRUE); + hash_t name_hash = xxhash::hash (name, strlen (name)); - char* name = mono_method_full_name (method, 1); + lock_guard write_lock { *method_event_map_write_lock.get () }; - timing_diff diff (jit_time); - fprintf (jit_log, "JIT method %6s: %s elapsed: %lis:%u::%u\n", event_name, name, static_cast(diff.sec), diff.ms, diff.ns); + auto iter = method_event_map->find (name_hash); + if (iter == method_event_map->end ()) { + (*method_event_map)[name_hash] = MethodEventRecord { + .method_name_hash = name_hash, + .method_name = name, + }; + } - free (name); + MethodEventRecord &record = method_event_map->at (name_hash); + switch (event) { + case MethodEvent::JitBegin: + record.jit_elapsed.mark_start (); + record.state |= MethodEventRecord::JitStateStarted; + break; + + case MethodEvent::JitDone: + record.state |= MethodEventRecord::JitStateSuccess; + [[fallthrough]]; + + case MethodEvent::JitFailed: + record.jit_elapsed.mark_end (); + record.state |= MethodEventRecord::JitStateCompleted; + break; + + case MethodEvent::Enter: + record.invocation_count++; + break; + } } void MonodroidRuntime::jit_begin ([[maybe_unused]] MonoProfiler *prof, MonoMethod *method) { - monodroidRuntime.log_jit_event (method, "begin"); + monodroidRuntime.log_method_event (method, MethodEvent::JitBegin); } void MonodroidRuntime::jit_failed ([[maybe_unused]] MonoProfiler *prof, MonoMethod *method) { - monodroidRuntime.log_jit_event (method, "failed"); + monodroidRuntime.log_method_event (method, MethodEvent::JitFailed); } void MonodroidRuntime::jit_done ([[maybe_unused]] MonoProfiler *prof, MonoMethod *method, [[maybe_unused]] MonoJitInfo* jinfo) { - monodroidRuntime.log_jit_event (method, "done"); + monodroidRuntime.log_method_event (method, MethodEvent::JitDone); +} + +// This is called only for `mono_runtime_invoke` +void +MonodroidRuntime::prof_method_begin_invoke ([[maybe_unused]] MonoProfiler *prof, MonoMethod *method) noexcept +{ + monodroidRuntime.log_method_event (method, MethodEvent::Enter); +} + +void +MonodroidRuntime::prof_method_end_invoke ([[maybe_unused]] MonoProfiler *prof, MonoMethod *method) noexcept +{} + +// This is called only when the interpreter is used +void +MonodroidRuntime::prof_method_enter ([[maybe_unused]] MonoProfiler *prof, MonoMethod *method, [[maybe_unused]] MonoProfilerCallContext *context) noexcept +{ + log_debug (LOG_ASSEMBLY, "prof_method_enter"); + monodroidRuntime.log_method_event (method, MethodEvent::Enter); +} + +void +MonodroidRuntime::prof_method_leave ([[maybe_unused]] MonoProfiler *prof, MonoMethod *method, [[maybe_unused]] MonoProfilerCallContext *context) noexcept +{} + +MonoProfilerCallInstrumentationFlags +MonodroidRuntime::prof_method_filter ([[maybe_unused]] MonoProfiler *prof, [[maybe_unused]] MonoMethod *method) noexcept +{ + return MONO_PROFILER_CALL_INSTRUMENTATION_ENTER | + MONO_PROFILER_CALL_INSTRUMENTATION_LEAVE; } #ifndef RELEASE @@ -631,9 +687,11 @@ MonodroidRuntime::mono_runtime_init ([[maybe_unused]] JNIEnv *env, [[maybe_unuse bool log_methods = FastTiming::enabled () && !FastTiming::is_bare_mode (); if (log_methods) [[unlikely]] { + log_debug (LOG_ASSEMBLY, "Enabling method logging"); std::unique_ptr jit_log_path {Util::path_combine (AndroidSystem::override_dirs [0], "methods.txt")}; + log_debug (LOG_ASSEMBLY, "JIT log path: %s", jit_log_path.get ()); Util::create_directory (AndroidSystem::override_dirs [0], 0755); - jit_log = Util::monodroid_fopen (jit_log_path.get (), "a"); + jit_log = Util::monodroid_fopen (jit_log_path.get (), "w"); Util::set_world_accessable (jit_log_path.get ()); } @@ -642,10 +700,31 @@ MonodroidRuntime::mono_runtime_init ([[maybe_unused]] JNIEnv *env, [[maybe_unuse mono_profiler_set_thread_stopped_callback (profiler_handle, thread_end); if (log_methods) [[unlikely]]{ - jit_time.mark_start (); + method_event_map_write_lock = std::make_unique (); + method_event_map = std::make_unique (); + 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_method_begin_invoke_callback (profiler_handle, prof_method_begin_invoke); + mono_profiler_set_method_end_invoke_callback (profiler_handle, prof_method_end_invoke); + + // The method enter/leave callbacks are supported only when the interpreter is used. + switch (AndroidSystem::get_mono_aot_mode ()) { + case MonoAotMode::MONO_AOT_MODE_INTERP: + case MonoAotMode::MONO_AOT_MODE_INTERP_ONLY: + case MonoAotMode::MONO_AOT_MODE_INTERP_LLVMONLY: + case MonoAotMode::MONO_AOT_MODE_LLVMONLY_INTERP: + log_debug (LOG_ASSEMBLY, "Enabling method enter/leave profiler callbacks"); + mono_profiler_set_call_instrumentation_filter_callback (profiler_handle, prof_method_filter); + mono_profiler_set_method_enter_callback (profiler_handle, prof_method_enter); + mono_profiler_set_method_leave_callback (profiler_handle, prof_method_leave); + break; + + default: + // Other AOT modes are ignored + break; + } } parse_gdb_options (); @@ -1627,11 +1706,11 @@ MonodroidRuntime::Java_mono_android_Runtime_register (JNIEnv *env, jstring manag JNIEXPORT void JNICALL Java_mono_android_Runtime_dumpTimingData ([[maybe_unused]] JNIEnv *env, [[maybe_unused]] jclass klass) { - if (internal_timing == nullptr) { - return; + if (internal_timing != nullptr) { + internal_timing->dump (); } - internal_timing->dump (); + monodroidRuntime.dump_method_events (); } JNIEXPORT void diff --git a/src/native/monodroid/performance-methods.cc b/src/native/monodroid/performance-methods.cc new file mode 100644 index 00000000000..0473639e8b9 --- /dev/null +++ b/src/native/monodroid/performance-methods.cc @@ -0,0 +1,77 @@ +#include +#include + +#include "cppcompat.hh" +#include "logger.hh" +#include "monodroid-glue-internal.hh" +#include "performance-methods.hh" + +using namespace xamarin::android::internal; + +namespace { + const char *jit_state_description (uint32_t status) noexcept + { + if ((status & MethodEventRecord::JitStateStarted) != MethodEventRecord::JitStateStarted) { + return "never JIT-ed"; + } + + if ((status & MethodEventRecord::JitStateCompleted) != MethodEventRecord::JitStateCompleted) { + return "started but not completed"; + } + + if ((status & MethodEventRecord::JitStateSuccess) == MethodEventRecord::JitStateSuccess) { + return "success"; + } + + return "failure"; + } +} + +void +MonodroidRuntime::dump_method_events () +{ + if (!method_event_map) { + return; + } + + log_debug (LOG_ASSEMBLY, "Dumping method events"); + lock_guard write_mutex { *method_event_map_write_lock.get () }; + + mono_profiler_set_jit_begin_callback (profiler_handle, nullptr); + mono_profiler_set_jit_done_callback (profiler_handle, nullptr); + mono_profiler_set_jit_failed_callback (profiler_handle, nullptr); + + fprintf ( + jit_log, + R"() + +)", + method_event_map->size () + ); + + for (auto item : *method_event_map.get ()) { + MethodEventRecord &record = item.second; + bool was_jited = (record.state & MethodEventRecord::JitStateStarted) == MethodEventRecord::JitStateStarted; + timing_diff diff { record.jit_elapsed }; + + fprintf ( + jit_log, + R"( +)", + record.method_name, + record.invocation_count, + was_jited ? static_cast(diff.sec) : 0, + was_jited ? diff.ms : 0, + was_jited ? diff.ns : 0, + jit_state_description (record.state) + ); + ::free (static_cast(const_cast(record.method_name))); + record.method_name = nullptr; + } + + method_event_map->clear (); + fprintf (jit_log, "\n"); + fflush (jit_log); + fclose (jit_log); + jit_log = nullptr; +} diff --git a/src/native/monodroid/performance-methods.hh b/src/native/monodroid/performance-methods.hh new file mode 100644 index 00000000000..2c27aa49015 --- /dev/null +++ b/src/native/monodroid/performance-methods.hh @@ -0,0 +1,22 @@ +#pragma once + +#include "timing.hh" +#include "xxhash.hh" +#include "robin_map.hh" + +namespace xamarin::android::internal { + struct MethodEventRecord + { + static inline constexpr uint32_t JitStateStarted = 0x01u; + static inline constexpr uint32_t JitStateCompleted = 0x02u; + static inline constexpr uint32_t JitStateSuccess = 0x04u; + + uint32_t state = 0u; + uint64_t invocation_count = 0u; + hash_t method_name_hash = 0u; + const char* method_name = nullptr; + timing_period jit_elapsed {}; + }; + + using method_event_map_t = tsl::robin_map; +} diff --git a/src/native/pinvoke-override/pinvoke-override-api.hh b/src/native/pinvoke-override/pinvoke-override-api.hh index 445f8cccf0b..3f1d91c272a 100644 --- a/src/native/pinvoke-override/pinvoke-override-api.hh +++ b/src/native/pinvoke-override/pinvoke-override-api.hh @@ -3,32 +3,9 @@ #include #include "cppcompat.hh" +#include "robin_map.hh" #include "xxhash.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 - namespace xamarin::android { struct PinvokeEntry { diff --git a/src/native/runtime-base/robin_map.hh b/src/native/runtime-base/robin_map.hh new file mode 100644 index 00000000000..d8c845c8b12 --- /dev/null +++ b/src/native/runtime-base/robin_map.hh @@ -0,0 +1,25 @@ +#pragma once + +// 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 From a7a8f9104d16028089810fd83609f91a0bb4becc Mon Sep 17 00:00:00 2001 From: Marek Habersack Date: Tue, 5 Nov 2024 22:56:02 +0100 Subject: [PATCH 2/4] No need to log that --- src/native/monodroid/monodroid-glue.cc | 1 - 1 file changed, 1 deletion(-) diff --git a/src/native/monodroid/monodroid-glue.cc b/src/native/monodroid/monodroid-glue.cc index 60631699e88..97836d286ec 100644 --- a/src/native/monodroid/monodroid-glue.cc +++ b/src/native/monodroid/monodroid-glue.cc @@ -176,7 +176,6 @@ MonodroidRuntime::prof_method_end_invoke ([[maybe_unused]] MonoProfiler *prof, M void MonodroidRuntime::prof_method_enter ([[maybe_unused]] MonoProfiler *prof, MonoMethod *method, [[maybe_unused]] MonoProfilerCallContext *context) noexcept { - log_debug (LOG_ASSEMBLY, "prof_method_enter"); monodroidRuntime.log_method_event (method, MethodEvent::Enter); } From 0048d707a5f15c4515ce3884a57d0b886d631c1b Mon Sep 17 00:00:00 2001 From: Marek Habersack Date: Wed, 6 Nov 2024 21:45:34 +0100 Subject: [PATCH 3/4] Try as I might, can't get counts working without the interpreter Will probably require a custom build of the MonoVM runtime :( --- .../monodroid/monodroid-glue-internal.hh | 1 - src/native/monodroid/monodroid-glue.cc | 12 +----- src/native/monodroid/performance-methods.cc | 41 ++++++++++++++++--- 3 files changed, 36 insertions(+), 18 deletions(-) diff --git a/src/native/monodroid/monodroid-glue-internal.hh b/src/native/monodroid/monodroid-glue-internal.hh index ea209b91b77..4a27a57bba8 100644 --- a/src/native/monodroid/monodroid-glue-internal.hh +++ b/src/native/monodroid/monodroid-glue-internal.hh @@ -268,7 +268,6 @@ namespace xamarin::android::internal jmethodID java_System_identityHashCode; jmethodID Class_getName; jclass java_TimeZone; - FILE *jit_log; MonoProfilerHandle profiler_handle; /* diff --git a/src/native/monodroid/monodroid-glue.cc b/src/native/monodroid/monodroid-glue.cc index 97836d286ec..7aef3fe3577 100644 --- a/src/native/monodroid/monodroid-glue.cc +++ b/src/native/monodroid/monodroid-glue.cc @@ -684,21 +684,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]] { - log_debug (LOG_ASSEMBLY, "Enabling method logging"); - std::unique_ptr jit_log_path {Util::path_combine (AndroidSystem::override_dirs [0], "methods.txt")}; - log_debug (LOG_ASSEMBLY, "JIT log path: %s", jit_log_path.get ()); - Util::create_directory (AndroidSystem::override_dirs [0], 0755); - jit_log = Util::monodroid_fopen (jit_log_path.get (), "w"); - Util::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]]{ + if (FastTiming::enabled () && !FastTiming::is_bare_mode ()) [[unlikely]]{ method_event_map_write_lock = std::make_unique (); method_event_map = std::make_unique (); diff --git a/src/native/monodroid/performance-methods.cc b/src/native/monodroid/performance-methods.cc index 0473639e8b9..89daa8d7e2f 100644 --- a/src/native/monodroid/performance-methods.cc +++ b/src/native/monodroid/performance-methods.cc @@ -1,6 +1,11 @@ #include +#include +#include + #include +#include +#include "android-system.hh" #include "cppcompat.hh" #include "logger.hh" #include "monodroid-glue-internal.hh" @@ -40,8 +45,34 @@ MonodroidRuntime::dump_method_events () mono_profiler_set_jit_begin_callback (profiler_handle, nullptr); mono_profiler_set_jit_done_callback (profiler_handle, nullptr); mono_profiler_set_jit_failed_callback (profiler_handle, nullptr); + mono_profiler_set_method_begin_invoke_callback (profiler_handle, nullptr); + mono_profiler_set_method_end_invoke_callback (profiler_handle, nullptr); + + switch (AndroidSystem::get_mono_aot_mode ()) { + case MonoAotMode::MONO_AOT_MODE_INTERP: + case MonoAotMode::MONO_AOT_MODE_INTERP_ONLY: + case MonoAotMode::MONO_AOT_MODE_INTERP_LLVMONLY: + case MonoAotMode::MONO_AOT_MODE_LLVMONLY_INTERP: + mono_profiler_set_call_instrumentation_filter_callback (profiler_handle, nullptr); + mono_profiler_set_method_enter_callback (profiler_handle, nullptr); + mono_profiler_set_method_leave_callback (profiler_handle, nullptr); + break; + + default: + // Other AOT modes are ignored + break; + } + + std::unique_ptr jit_log_path {Util::path_combine (AndroidSystem::override_dirs [0], "methods.xml")}; + Util::create_directory (AndroidSystem::override_dirs [0], 0755); + int jit_log = open (jit_log_path.get (), O_CREAT | O_WRONLY | O_TRUNC | O_SYNC, 0644); + if (jit_log < 0) { + log_error (LOG_DEFAULT, "Failed to open '%s' for writing: %s", jit_log_path.get (), strerror (errno)); + return; + } + Util::set_world_accessable (jit_log_path.get ()); - fprintf ( + dprintf ( jit_log, R"() @@ -54,7 +85,7 @@ MonodroidRuntime::dump_method_events () bool was_jited = (record.state & MethodEventRecord::JitStateStarted) == MethodEventRecord::JitStateStarted; timing_diff diff { record.jit_elapsed }; - fprintf ( + dprintf ( jit_log, R"( )", @@ -70,8 +101,6 @@ MonodroidRuntime::dump_method_events () } method_event_map->clear (); - fprintf (jit_log, "\n"); - fflush (jit_log); - fclose (jit_log); - jit_log = nullptr; + dprintf (jit_log, "\n"); + close (jit_log); } From 56d091e02e4c22d25e761b9ecf9ba316c76c030a Mon Sep 17 00:00:00 2001 From: Marek Habersack Date: Thu, 7 Nov 2024 09:42:47 +0100 Subject: [PATCH 4/4] Update docs and tests Removed documentation about `counters.txt`, since the file is no longer generated. Added info on how to get `methods.xml` generated. TODO: `jit-times` --- Documentation/guides/profiling.md | 75 +++++++------------ Documentation/workflow/SystemProperties.md | 6 +- .../Xamarin.Android.Common.targets | 4 +- .../monodroid/monodroid-glue-internal.hh | 2 +- src/native/monodroid/performance-methods.cc | 4 +- .../Tests/InstallTests.cs | 8 +- 6 files changed, 41 insertions(+), 58 deletions(-) diff --git a/Documentation/guides/profiling.md b/Documentation/guides/profiling.md index db6d86a2291..2b0c5c611c8 100644 --- a/Documentation/guides/profiling.md +++ b/Documentation/guides/profiling.md @@ -174,72 +174,53 @@ If profiling a Release build, you'll need to edit your Debug builds already set this value by default. +In order to save method JIT statistics, the application has to be built +with the `$(_AndroidMethodsStats)` MSBuild property set to `true`. + Next, run the `adb` command: > adb shell setprop debug.mono.log timing,default -After launching the app, you can find a file that was recorded during -startup: +After launching the app, wait for the desired period of time and then send +an Android intent to the application in order to actually save data into +the `methods.xml` file: + + > adb shell am broadcast -a mono.android.app.DUMP_TIMING_DATA com.xamarin.android.helloworld + +After this is done, you can find a file that was recorded during startup: > adb shell run-as com.xamarin.android.helloworld ls files/.__override__ - counters.txt - methods.txt + methods.xml -Make sure to use your app's package name instead of -`com.xamarin.android.helloworld`. +Make sure to use your app's package name instead of `com.xamarin.android.helloworld`. You can pull these files to your machine by doing: - > adb shell run-as com.xamarin.android.helloworld cat files/.__override__/counters.txt > counters.txt - > adb shell run-as com.xamarin.android.helloworld cat files/.__override__/methods.txt > methods.txt + > adb shell run-as com.xamarin.android.helloworld cat files/.__override__/methods.xml > methods.xml If you ever need to reset/clear these directories, you can uninstall/reinstall the app or merely: - > adb shell run-as com.xamarin.android.helloworld rm -r files/.__override__/ - -`counters.txt` has some interesting summary information provided by -Mono: - - ## Runtime.register: type=HelloWorld.MainActivity, HelloWorld - JIT statistics - Discarded method code : 1 - Time spent JITting discarded code : 0.82 ms - Try holes memory size : 896 - Dynamic code allocs : 3 - Dynamic code bytes : 584 - Dynamic code frees : 0 - Unwind info size : 5985 - Calls to trampolines : 1994 - JIT trampolines : 952 - Unbox trampolines : 2 - Static rgctx trampolines : 7 - Async JIT info size : 0 - Max native code in a domain : 0 - Max code space allocated in a domain: 0 - Total code space allocated : 0 - Hazardous pointers : 0 - Compiled methods : 921 - Methods from AOT : 0 - Methods JITted using mono JIT : 921 - Methods JITted using LLVM : 0 - Methods using the interpreter : 0 - -_NOTE: that `counters.txt` is not available in .NET 6 projects._ - -`methods.txt` has the individual JIT times of each method: - - JIT method begin: System.OutOfMemoryException:.ctor (string) elapsed: 0s:20::136721 - JIT method done: System.OutOfMemoryException:.ctor (string) elapsed: 0s:20::605627 + > adb shell run-as com.xamarin.android.helloworld rm files/.__override__/methods.xml + +`methods.xml` has the individual JIT times of each method: + + + +If methods statistics were gathered in `Release` mode, the `invocation_count` attribute of most entries +will be `0`. This is due to the fact that the Mono runtime allows us to gather call statistics only +when running with the interpreter instead of JIT. In order to properly count calls to each method, the +application needs to be built with the `$(UseInterpreter)` MSBuild property set to `true` (it works both in +`Debug` and `Release` modes). This is not particularly readable, so you can use our [jit-times][jit_times] command-line tool to get better/sorted output: # Windows / .NET - jit-times.exe methods.txt > methods-sorted.txt + jit-times.exe methods.xml > methods-sorted.txt # Mac / Mono - mono jit-times.exe methods.txt > methods-sorted.txt + mono jit-times.exe methods.xml > methods-sorted.txt Which outputs: @@ -441,7 +422,7 @@ target: Project Evaluation Performance Summary: 12 ms samples\HelloWorld\HelloLibrary\HelloLibrary.csproj 1 calls 98 ms samples\HelloWorld\HelloWorld.csproj 1 calls - + Target Performance Summary: 275 ms _UpdateAndroidResgen 2 calls 354 ms _GenerateJavaStubs 1 calls @@ -450,7 +431,7 @@ target: 865 ms _ResolveSdks 2 calls 953 ms ResolveProjectReferences 2 calls 1219 ms _CompileToDalvikWithD8 1 calls - + Task Performance Summary: 681 ms Csc 2 calls 809 ms ValidateJavaVersion 2 calls diff --git a/Documentation/workflow/SystemProperties.md b/Documentation/workflow/SystemProperties.md index 8fc1e6ba188..fd9dc74b07f 100644 --- a/Documentation/workflow/SystemProperties.md +++ b/Documentation/workflow/SystemProperties.md @@ -169,8 +169,10 @@ categories: * `timing` Enable logging of native code performance information, including method execution timing which is written to a file named - `methods.txt`. `timing=bare` should be used in preference to this - category. + `methods.xml` (see [profiling][profiling] for more information). + `timing=bare` should be used in preference to this category. + +[profiling]: ../guides/profiling.md #### Timing events format diff --git a/src/Xamarin.Android.Build.Tasks/Xamarin.Android.Common.targets b/src/Xamarin.Android.Build.Tasks/Xamarin.Android.Common.targets index 3649e4f962c..791c4cc32aa 100644 --- a/src/Xamarin.Android.Build.Tasks/Xamarin.Android.Common.targets +++ b/src/Xamarin.Android.Build.Tasks/Xamarin.Android.Common.targets @@ -1,4 +1,4 @@ -