Spiffing up method JIT logging

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:
+
+    <method name="Java.Lang.Object:GetObject (intptr,Android.Runtime.JniHandleOwnership,System.Type)" invocation_count="1" jit_time="0:0::20915" jit_status="success" />
+
+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

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
 

src/Xamarin.Android.Build.Tasks/Xamarin.Android.Common.targets

@@ -1,4 +1,4 @@
-<!--
+<!--
 ***********************************************************************************************
 Xamarin.Android.Common.targets
 
@@ -1540,7 +1540,7 @@ because xbuild doesn't support framework reference assemblies.
   <ItemGroup>
     <AndroidManifestOverlay
         Include="$(MSBuildThisFileDirectory)\ManifestOverlays\Timing.xml"
-        Condition=" '$(_AndroidFastTiming)' == 'True' "
+        Condition=" '$(_AndroidFastTiming)' == 'True' Or '$(_AndroidMethodsStats)' == 'True' "
     />
   </ItemGroup>
   <ManifestMerger

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

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,8 +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 +288,9 @@ namespace xamarin::android::internal
 
 		static MonoCoreRuntimeProperties monovm_core_properties;
 		MonovmRuntimeConfigArguments  runtime_config_args;
+
+		std::unique_ptr<method_event_map_t> method_event_map{};
+		static inline std::unique_ptr<xamarin::android::mutex> method_event_map_write_lock;
 	};
 }
 #endif

src/native/monodroid/monodroid-glue.cc

@@ -102,37 +102,92 @@ 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));
+
+	lock_guard write_lock { *method_event_map_write_lock.get () };
+
+	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,
+		};
+	}
+
+	MethodEventRecord &record = method_event_map->at (name_hash);
+	switch (event) {
+		case MethodEvent::JitBegin:
+			record.jit_elapsed.mark_start ();
+			record.state |= MethodEventRecord::JitStateStarted;
+			break;
 
-	char* name = mono_method_full_name (method, 1);
+		case MethodEvent::JitDone:
+			record.state |= MethodEventRecord::JitStateSuccess;
+			[[fallthrough]];
 
-	timing_diff diff (jit_time);
-	fprintf (jit_log, "JIT method %6s: %s elapsed: %lis:%u::%u\n", event_name, name, static_cast<long>(diff.sec), diff.ms, diff.ns);
+		case MethodEvent::JitFailed:
+			record.jit_elapsed.mark_end ();
+			record.state |= MethodEventRecord::JitStateCompleted;
+			break;
 
-	free (name);
+		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
+{
+	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
@@ -629,23 +684,36 @@ 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<char> jit_log_path {Util::path_combine (AndroidSystem::override_dirs [0], "methods.txt")};
-		Util::create_directory (AndroidSystem::override_dirs [0], 0755);
-		jit_log = Util::monodroid_fopen (jit_log_path.get (), "a");
-		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]]{
-		jit_time.mark_start ();
+	if (FastTiming::enabled () && !FastTiming::is_bare_mode ()) [[unlikely]]{
+		method_event_map_write_lock = std::make_unique<mutex> ();
+		method_event_map = std::make_unique<method_event_map_t> ();
+
 		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 +1695,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