[native] Improvements to the internal timing infrastructure (#9993)

  * Make timing infrastructure shared between MonoVM and CoreCLR hosts.
  * Use C++ APIs instead of some of our own ones (`std::chrono`)
  * Make it possible to dump timings into a file instead of logcat
  * Timing events no longer require declaring a variable to hold the
    timing sequence ID.  Instead, calls to start and end events are
    now using a thread-local stack.
  * Add a way to time a single function call by wrapping it in a
    `time_call()` timing function.

Author: grendello

src/native/CMakeLists.txt

@@ -254,6 +254,13 @@ if(IS_CLR_RUNTIME)
      )
   endmacro()
 else()
+  macro(xa_add_include_directories TARGET)
+     target_include_directories(
+        ${TARGET}
+        PRIVATE
+        ${RUNTIME_INCLUDE_DIR}
+     )
+  endmacro()
   include_directories(mono)
 endif()
 
@@ -589,6 +596,7 @@ else()
   add_subdirectory(common/libunwind)
   add_subdirectory(common/lz4)
 
+  add_subdirectory(common/runtime-base)
   add_subdirectory(${SOURCES_PREFIX}/runtime-base)
   add_subdirectory(${SOURCES_PREFIX}/shared)
   add_subdirectory(${SOURCES_PREFIX}/xamarin-app-stub)

src/native/clr/host/assembly-store.cc

@@ -9,6 +9,7 @@
 #include <runtime-base/util.hh>
 #include <runtime-base/search.hh>
 #include <runtime-base/startup-aware-lock.hh>
+#include <runtime-base/timing-internal.hh>
 
 using namespace xamarin::android;
 
@@ -29,6 +30,11 @@ auto AssemblyStore::get_assembly_data (AssemblyStoreSingleAssemblyRuntimeData co
 	auto header = reinterpret_cast<const CompressedAssemblyHeader*>(e.image_data);
 	if (header->magic == COMPRESSED_DATA_MAGIC) {
 		log_debug (LOG_ASSEMBLY, "Decompressing assembly '{}' from the assembly store", name);
+
+		if (FastTiming::enabled ()) [[unlikely]] {
+			internal_timing.start_event (TimingEventKind::AssemblyDecompression);
+		}
+
 		if (compressed_assemblies.descriptors == nullptr) [[unlikely]] {
 			Helpers::abort_application (LOG_ASSEMBLY, "Compressed assembly found but no descriptor defined"sv);
 		}
@@ -49,6 +55,15 @@ auto AssemblyStore::get_assembly_data (AssemblyStoreSingleAssemblyRuntimeData co
 
 			if (cad.loaded) {
 				set_assembly_data_and_size (reinterpret_cast<uint8_t*>(cad.data), cad.uncompressed_file_size, assembly_data, assembly_data_size);
+
+				if (FastTiming::enabled ()) [[unlikely]] {
+					internal_timing.end_event (true /* uses_more_info */);
+
+					dynamic_local_string<SENSIBLE_TYPE_NAME_LENGTH> msg;
+					msg.append (name);
+					msg.append (" (decompressed in another thread)"sv);
+					internal_timing.add_more_info (msg);
+				}
 				return {assembly_data, assembly_data_size};
 			}
 
@@ -105,6 +120,10 @@ auto AssemblyStore::get_assembly_data (AssemblyStoreSingleAssemblyRuntimeData co
 				);
 			}
 			cad.loaded = true;
+			if (FastTiming::enabled ()) [[unlikely]] {
+				internal_timing.end_event (true /* uses_more_info */);
+				internal_timing.add_more_info (name);
+			}
 		}
 
 		set_assembly_data_and_size (reinterpret_cast<uint8_t*>(cad.data), cad.uncompressed_file_size, assembly_data, assembly_data_size);
@@ -117,8 +136,23 @@ auto AssemblyStore::get_assembly_data (AssemblyStoreSingleAssemblyRuntimeData co
 		// Currently, MAUI crashes when we return a pointer to read-only data, so we must copy
 		// the assembly data to a read-write area.
 		log_debug (LOG_ASSEMBLY, "Copying assembly data to an r/w memory area");
+
+		if (FastTiming::enabled ()) [[unlikely]] {
+			internal_timing.start_event (TimingEventKind::AssemblyLoad);
+		}
+
 		uint8_t *rw_pointer = static_cast<uint8_t*>(malloc (e.descriptor->data_size));
 		memcpy (rw_pointer, e.image_data, e.descriptor->data_size);
+
+		if (FastTiming::enabled ()) [[unlikely]] {
+			internal_timing.end_event (true /* uses more info */);
+
+			dynamic_local_string<SENSIBLE_TYPE_NAME_LENGTH> msg;
+			msg.append (name);
+			msg.append (" (memcpy to r/w area, part of assembly load time)"sv);
+			internal_timing.add_more_info (msg);
+		}
+
 		set_assembly_data_and_size (rw_pointer, e.descriptor->data_size, assembly_data, assembly_data_size);
 		// HACK! END
 		// 	set_assembly_data_and_size (e.image_data, e.descriptor->data_size, assembly_data, assembly_data_size);

src/native/clr/host/host.cc

@@ -42,7 +42,17 @@ bool Host::clr_external_assembly_probe (const char *path, void **data_start, int
 		return false; // TODO: abort instead?
 	}
 
+	if (FastTiming::enabled ()) [[unlikely]] {
+		internal_timing.start_event (TimingEventKind::AssemblyLoad);
+	}
+
 	*data_start = AssemblyStore::open_assembly (path, *size);
+
+	if (FastTiming::enabled ()) [[unlikely]] {
+		internal_timing.end_event (true /* uses_more_info */);
+		internal_timing.add_more_info (path);
+	}
+
 	log_debug (
 		LOG_ASSEMBLY,
 		"Assembly data {}mapped ({:p}, {} bytes)",
@@ -263,10 +273,9 @@ void Host::Java_mono_android_Runtime_initInternal (JNIEnv *env, jclass runtimeCl
 	// If fast logging is disabled, log messages immediately
 	FastTiming::initialize ((Logger::log_timing_categories() & LogTimingCategories::FastBare) != LogTimingCategories::FastBare);
 
-	size_t total_time_index;
 	if (FastTiming::enabled ()) [[unlikely]] {
 		_timing = std::make_shared<Timing> ();
-		total_time_index = internal_timing.start_event (TimingEventKind::TotalRuntimeInit);
+		internal_timing.start_event (TimingEventKind::TotalRuntimeInit);
 	}
 
 	jstring_array_wrapper applicationDirs (env, appDirs);
@@ -292,9 +301,8 @@ void Host::Java_mono_android_Runtime_initInternal (JNIEnv *env, jclass runtimeCl
 
 	gather_assemblies_and_libraries (runtimeApks, haveSplitApks);
 
-	size_t clr_init_time_index;
 	if (FastTiming::enabled ()) [[unlikely]] {
-		clr_init_time_index = internal_timing.start_event (TimingEventKind::MonoRuntimeInit);
+		internal_timing.start_event (TimingEventKind::ManagedRuntimeInit);
 	}
 
 	coreclr_set_error_writer (clr_error_writer);
@@ -304,7 +312,7 @@ void Host::Java_mono_android_Runtime_initInternal (JNIEnv *env, jclass runtimeCl
 	// The first entry in the property arrays is for the host contract pointer. Application build makes sure
 	// of that.
 	init_runtime_property_values[0] = host_contract_ptr_buffer.data ();
-	int hr = coreclr_initialize (
+	int hr = FastTiming::time_call ("coreclr_initialize", coreclr_initialize,
 		application_config.android_package_name,
 		"Xamarin.Android",
 		(int)application_config.number_of_runtime_properties,
@@ -315,7 +323,7 @@ void Host::Java_mono_android_Runtime_initInternal (JNIEnv *env, jclass runtimeCl
 	);
 
 	if (FastTiming::enabled ()) [[unlikely]] {
-		internal_timing.end_event (clr_init_time_index);
+		internal_timing.end_event ();
 	}
 
 	// TODO: make S_OK & friends known to us
@@ -372,14 +380,13 @@ void Host::Java_mono_android_Runtime_initInternal (JNIEnv *env, jclass runtimeCl
 
 	OSBridge::initialize_on_runtime_init (env, runtimeClass);
 
-	size_t native_to_managed_index;
 	if (FastTiming::enabled ()) [[unlikely]] {
-		native_to_managed_index = internal_timing.start_event (TimingEventKind::NativeToManagedTransition);
+		internal_timing.start_event (TimingEventKind::NativeToManagedTransition);
 	}
 
 	void *delegate = nullptr;
-	log_debug (LOG_ASSEMBLY, "Creating UCO delegate to {}.RegisterJniNatives", Constants::JNIENVINIT_FULL_TYPE_NAME);
-	delegate = create_delegate (Constants::MONO_ANDROID_ASSEMBLY_NAME, Constants::JNIENVINIT_FULL_TYPE_NAME, "RegisterJniNatives"sv);
+	log_debug (LOG_ASSEMBLY, "Creating UCO delegate to {}.RegisterJniNatives"sv, Constants::JNIENVINIT_FULL_TYPE_NAME);
+	delegate = FastTiming::time_call ("create_delegate for RegisterJniNatives"sv, create_delegate, Constants::MONO_ANDROID_ASSEMBLY_NAME, Constants::JNIENVINIT_FULL_TYPE_NAME, "RegisterJniNatives"sv);
 	jnienv_register_jni_natives = reinterpret_cast<jnienv_register_jni_natives_fn> (delegate);
 	abort_unless (
 		jnienv_register_jni_natives != nullptr,
@@ -392,8 +399,8 @@ void Host::Java_mono_android_Runtime_initInternal (JNIEnv *env, jclass runtimeCl
 		}
 	);
 
-	log_debug (LOG_ASSEMBLY, "Creating UCO delegate to {}.Initialize", Constants::JNIENVINIT_FULL_TYPE_NAME);
-	delegate = create_delegate (Constants::MONO_ANDROID_ASSEMBLY_NAME, Constants::JNIENVINIT_FULL_TYPE_NAME, "Initialize"sv);
+	log_debug (LOG_ASSEMBLY, "Creating UCO delegate to {}.Initialize"sv, Constants::JNIENVINIT_FULL_TYPE_NAME);
+	delegate = FastTiming::time_call ("create_delegate for Initialize"sv, create_delegate, Constants::MONO_ANDROID_ASSEMBLY_NAME, Constants::JNIENVINIT_FULL_TYPE_NAME, "Initialize"sv);
 	auto initialize = reinterpret_cast<jnienv_initialize_fn> (delegate);
 	abort_unless (
 		initialize != nullptr,
@@ -407,19 +414,18 @@ void Host::Java_mono_android_Runtime_initInternal (JNIEnv *env, jclass runtimeCl
 	);
 
 	log_debug (LOG_DEFAULT, "Calling into managed runtime init"sv);
-	initialize (&init);
+	FastTiming::time_call ("JNIEnv.Initialize UCO"sv, initialize, &init);
 
 	if (FastTiming::enabled ()) [[unlikely]] {
-		internal_timing.end_event (native_to_managed_index);
-		internal_timing.end_event (total_time_index);
+		internal_timing.end_event (); // native to managed
+		internal_timing.end_event (); // total init time
 	}
 }
 
 void Host::Java_mono_android_Runtime_register (JNIEnv *env, jstring managedType, jclass nativeClass, jstring methods) noexcept
 {
-	size_t total_time_index;
 	if (FastTiming::enabled ()) [[unlikely]] {
-		total_time_index = internal_timing.start_event (TimingEventKind::RuntimeRegister);
+		internal_timing.start_event (TimingEventKind::RuntimeRegister);
 	}
 
 	jsize managedType_len = env->GetStringLength (managedType);
@@ -434,14 +440,14 @@ void Host::Java_mono_android_Runtime_register (JNIEnv *env, jstring managedType,
 	env->ReleaseStringChars (managedType, managedType_ptr);
 
 	if (FastTiming::enabled ()) [[unlikely]] {
-		internal_timing.end_event (total_time_index, true /* uses_more_info */);
+		internal_timing.end_event (true /* uses_more_info */);
 
 		dynamic_local_string<SENSIBLE_TYPE_NAME_LENGTH> type;
 		const char *mt_ptr = env->GetStringUTFChars (managedType, nullptr);
 		type.assign (mt_ptr, strlen (mt_ptr));
 		env->ReleaseStringUTFChars (managedType, mt_ptr);
 
-		internal_timing.add_more_info (total_time_index, type);
+		internal_timing.add_more_info (type);
 	}
 }
 

src/native/clr/host/internal-pinvokes.cc

@@ -105,7 +105,7 @@ managed_timing_sequence* monodroid_timing_start (const char *message)
 	if (message != nullptr) {
 		log_write (LOG_TIMING, LogLevel::Info, message);
 	}
-	ret->period.mark_start ();
+	ret->start = FastTiming::get_time ();
 	return ret;
 }
 
@@ -121,8 +121,8 @@ void monodroid_timing_stop (managed_timing_sequence *sequence, const char *messa
 		return;
 	}
 
-	sequence->period.mark_end ();
-	Timing::info (sequence->period, message == nullptr ? DEFAULT_MESSAGE : message);
+	sequence->end = FastTiming::get_time ();
+	Timing::info (sequence, message == nullptr ? DEFAULT_MESSAGE : message);
 	timing->release_sequence (sequence);
 }
 

src/native/clr/host/typemap.cc

@@ -210,9 +210,8 @@ auto TypeMapper::typemap_managed_to_java_release (const char *typeName, const ui
 [[gnu::flatten]]
 auto TypeMapper::typemap_managed_to_java (const char *typeName, const uint8_t *mvid) noexcept -> const char*
 {
-	size_t total_time_index;
 	if (FastTiming::enabled ()) [[unlikely]] {
-		total_time_index = internal_timing.start_event (TimingEventKind::ManagedToJava);
+		internal_timing.start_event (TimingEventKind::ManagedToJava);
 	}
 
 	if (typeName == nullptr) [[unlikely]] {
@@ -228,7 +227,7 @@ auto TypeMapper::typemap_managed_to_java (const char *typeName, const uint8_t *m
 #endif
 
 	if (FastTiming::enabled ()) [[unlikely]] {
-		internal_timing.end_event (total_time_index);
+		internal_timing.end_event ();
 	}
 
 	return ret;
@@ -256,9 +255,8 @@ auto TypeMapper::find_java_to_managed_entry (hash_t name_hash) noexcept -> const
 [[gnu::flatten]]
 auto TypeMapper::typemap_java_to_managed (const char *java_type_name, char const** assembly_name, uint32_t *managed_type_token_id) noexcept -> bool
 {
-	size_t total_time_index;
 	if (FastTiming::enabled ()) [[unlikely]] {
-		total_time_index = internal_timing.start_event (TimingEventKind::JavaToManaged);
+		internal_timing.start_event (TimingEventKind::JavaToManaged);
 	}
 
 	if (java_type_name == nullptr || assembly_name == nullptr || managed_type_token_id == nullptr) [[unlikely]] {
@@ -319,7 +317,7 @@ auto TypeMapper::typemap_java_to_managed (const char *java_type_name, char const
 	);
 
 	if (FastTiming::enabled ()) [[unlikely]] {
-		internal_timing.end_event (total_time_index);
+		internal_timing.end_event ();
 	}
 
 	return true;

src/native/clr/include/constants.hh

@@ -39,6 +39,9 @@ namespace xamarin::android {
 		static constexpr auto RUNTIME_CONFIG_BLOB_NAME_ARRAY                  = concat_string_views<runtime_config_blob_name_size> (RUNTIME_CONFIG_BLOB_BASE_NAME, MANGLED_ASSEMBLY_NAME_EXT);
 
 	public:
+		static constexpr std::string_view NEWLINE { "\n" };
+		static constexpr std::string_view EMPTY { "" };
+
 		// .data() must be used otherwise string_view length will include the trailing \0 in the array
 		static constexpr std::string_view RUNTIME_CONFIG_BLOB_NAME            { RUNTIME_CONFIG_BLOB_NAME_ARRAY.data () };
 		static constexpr std::string_view OVERRIDE_DIRECTORY_NAME             { ".__override__" };
@@ -57,6 +60,7 @@ namespace xamarin::android {
 		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_WREF_PROPERTY         { "debug.mono.wref" };
+		static constexpr std::string_view DEBUG_MONO_TIMING                       { "debug.mono.timing" };
 
 		static constexpr std::string_view LOG_CATEGORY_NAME_NONE                  { "*none*" };
 		static constexpr std::string_view LOG_CATEGORY_NAME_MONODROID             { "monodroid" };

src/native/clr/include/host/host.hh

@@ -7,7 +7,7 @@
 #include <host_runtime_contract.h>
 
 #include <runtime-base/jni-wrappers.hh>
-#include "../runtime-base/timing.hh"
+#include <runtime-base/timing.hh>
 #include "../shared/log_types.hh"
 #include "managed-interface.hh"
 

src/native/clr/include/runtime-base/android-system.hh

@@ -85,22 +85,22 @@ namespace xamarin::android {
 				 * However, if any logging is enabled (which should _not_ happen with
 				 * pre-loaded apps!), we need the .__override__ directory...
 				 */
-				dynamic_local_string<Constants::PROPERTY_VALUE_BUFFER_LEN> value;
+				dynamic_local_property_string value;
 				if (log_categories == 0 && monodroid_get_system_property (Constants::DEBUG_MONO_PROFILE_PROPERTY, value) == 0) [[likely]] {
 					return;
 				}
 			}
 
-			Util::create_public_directory (override_dir);
 			log_warn (LOG_DEFAULT, "Creating public update directory: `{}`", override_dir);
+			Util::create_public_directory (override_dir);
 		}
 
 		static auto is_embedded_dso_mode_enabled () noexcept -> bool
 		{
 			return embedded_dso_mode_enabled;
 		}
 
-		static auto monodroid_get_system_property (std::string_view const& name, dynamic_local_string<Constants::PROPERTY_VALUE_BUFFER_LEN> &value) noexcept -> int;
+		static auto monodroid_get_system_property (std::string_view const& name, dynamic_local_property_string &value) noexcept -> int;
 		static void detect_embedded_dso_mode (jstring_array_wrapper& appDirs) noexcept;
 		static void setup_environment () noexcept;
 		static void setup_app_library_directories (jstring_array_wrapper& runtimeApks, jstring_array_wrapper& appDirs, bool have_split_apks) noexcept;

src/native/clr/include/runtime-base/internal-pinvokes.hh

@@ -5,7 +5,7 @@
 
 #include <xamarin-app.hh>
 #include "logger.hh"
-#include "timing.hh"
+#include <runtime-base/timing.hh>
 
 extern "C" {
 	int _monodroid_gref_get () noexcept;