Skip to content

Commit 747041d

Browse files
grendellogrendello
authored
[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.
1 parent 325330a commit 747041d

Some content is hidden

Large Commits have some content hidden by default. Use the searchbox below for content that may be hidden.

43 files changed

+1179
-1553
lines changed

‎src/native/CMakeLists.txt

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -254,6 +254,13 @@ if(IS_CLR_RUNTIME)
254254
)
255255
endmacro()
256256
else()
257+
macro(xa_add_include_directories TARGET)
258+
target_include_directories(
259+
${TARGET}
260+
PRIVATE
261+
${RUNTIME_INCLUDE_DIR}
262+
)
263+
endmacro()
257264
include_directories(mono)
258265
endif()
259266

@@ -589,6 +596,7 @@ else()
589596
add_subdirectory(common/libunwind)
590597
add_subdirectory(common/lz4)
591598

599+
add_subdirectory(common/runtime-base)
592600
add_subdirectory(${SOURCES_PREFIX}/runtime-base)
593601
add_subdirectory(${SOURCES_PREFIX}/shared)
594602
add_subdirectory(${SOURCES_PREFIX}/xamarin-app-stub)

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

Lines changed: 34 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@
99
#include <runtime-base/util.hh>
1010
#include <runtime-base/search.hh>
1111
#include <runtime-base/startup-aware-lock.hh>
12+
#include <runtime-base/timing-internal.hh>
1213

1314
using namespace xamarin::android;
1415

@@ -29,6 +30,11 @@ auto AssemblyStore::get_assembly_data (AssemblyStoreSingleAssemblyRuntimeData co
2930
auto header = reinterpret_cast<const CompressedAssemblyHeader*>(e.image_data);
3031
if (header->magic == COMPRESSED_DATA_MAGIC) {
3132
log_debug (LOG_ASSEMBLY, "Decompressing assembly '{}' from the assembly store", name);
33+
34+
if (FastTiming::enabled ()) [[unlikely]] {
35+
internal_timing.start_event (TimingEventKind::AssemblyDecompression);
36+
}
37+
3238
if (compressed_assemblies.descriptors == nullptr) [[unlikely]] {
3339
Helpers::abort_application (LOG_ASSEMBLY, "Compressed assembly found but no descriptor defined"sv);
3440
}
@@ -49,6 +55,15 @@ auto AssemblyStore::get_assembly_data (AssemblyStoreSingleAssemblyRuntimeData co
4955

5056
if (cad.loaded) {
5157
set_assembly_data_and_size (reinterpret_cast<uint8_t*>(cad.data), cad.uncompressed_file_size, assembly_data, assembly_data_size);
58+
59+
if (FastTiming::enabled ()) [[unlikely]] {
60+
internal_timing.end_event (true /* uses_more_info */);
61+
62+
dynamic_local_string<SENSIBLE_TYPE_NAME_LENGTH> msg;
63+
msg.append (name);
64+
msg.append (" (decompressed in another thread)"sv);
65+
internal_timing.add_more_info (msg);
66+
}
5267
return {assembly_data, assembly_data_size};
5368
}
5469

@@ -105,6 +120,10 @@ auto AssemblyStore::get_assembly_data (AssemblyStoreSingleAssemblyRuntimeData co
105120
);
106121
}
107122
cad.loaded = true;
123+
if (FastTiming::enabled ()) [[unlikely]] {
124+
internal_timing.end_event (true /* uses_more_info */);
125+
internal_timing.add_more_info (name);
126+
}
108127
}
109128

110129
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
117136
// Currently, MAUI crashes when we return a pointer to read-only data, so we must copy
118137
// the assembly data to a read-write area.
119138
log_debug (LOG_ASSEMBLY, "Copying assembly data to an r/w memory area");
139+
140+
if (FastTiming::enabled ()) [[unlikely]] {
141+
internal_timing.start_event (TimingEventKind::AssemblyLoad);
142+
}
143+
120144
uint8_t *rw_pointer = static_cast<uint8_t*>(malloc (e.descriptor->data_size));
121145
memcpy (rw_pointer, e.image_data, e.descriptor->data_size);
146+
147+
if (FastTiming::enabled ()) [[unlikely]] {
148+
internal_timing.end_event (true /* uses more info */);
149+
150+
dynamic_local_string<SENSIBLE_TYPE_NAME_LENGTH> msg;
151+
msg.append (name);
152+
msg.append (" (memcpy to r/w area, part of assembly load time)"sv);
153+
internal_timing.add_more_info (msg);
154+
}
155+
122156
set_assembly_data_and_size (rw_pointer, e.descriptor->data_size, assembly_data, assembly_data_size);
123157
// HACK! END
124158
// set_assembly_data_and_size (e.image_data, e.descriptor->data_size, assembly_data, assembly_data_size);

‎src/native/clr/host/host.cc

Lines changed: 25 additions & 19 deletions
Original file line numberDiff line numberDiff line change
@@ -42,7 +42,17 @@ bool Host::clr_external_assembly_probe (const char *path, void **data_start, int
4242
return false; // TODO: abort instead?
4343
}
4444

45+
if (FastTiming::enabled ()) [[unlikely]] {
46+
internal_timing.start_event (TimingEventKind::AssemblyLoad);
47+
}
48+
4549
*data_start = AssemblyStore::open_assembly (path, *size);
50+
51+
if (FastTiming::enabled ()) [[unlikely]] {
52+
internal_timing.end_event (true /* uses_more_info */);
53+
internal_timing.add_more_info (path);
54+
}
55+
4656
log_debug (
4757
LOG_ASSEMBLY,
4858
"Assembly data {}mapped ({:p}, {} bytes)",
@@ -263,10 +273,9 @@ void Host::Java_mono_android_Runtime_initInternal (JNIEnv *env, jclass runtimeCl
263273
// If fast logging is disabled, log messages immediately
264274
FastTiming::initialize ((Logger::log_timing_categories() & LogTimingCategories::FastBare) != LogTimingCategories::FastBare);
265275

266-
size_t total_time_index;
267276
if (FastTiming::enabled ()) [[unlikely]] {
268277
_timing = std::make_shared<Timing> ();
269-
total_time_index = internal_timing.start_event (TimingEventKind::TotalRuntimeInit);
278+
internal_timing.start_event (TimingEventKind::TotalRuntimeInit);
270279
}
271280

272281
jstring_array_wrapper applicationDirs (env, appDirs);
@@ -292,9 +301,8 @@ void Host::Java_mono_android_Runtime_initInternal (JNIEnv *env, jclass runtimeCl
292301

293302
gather_assemblies_and_libraries (runtimeApks, haveSplitApks);
294303

295-
size_t clr_init_time_index;
296304
if (FastTiming::enabled ()) [[unlikely]] {
297-
clr_init_time_index = internal_timing.start_event (TimingEventKind::MonoRuntimeInit);
305+
internal_timing.start_event (TimingEventKind::ManagedRuntimeInit);
298306
}
299307

300308
coreclr_set_error_writer (clr_error_writer);
@@ -304,7 +312,7 @@ void Host::Java_mono_android_Runtime_initInternal (JNIEnv *env, jclass runtimeCl
304312
// The first entry in the property arrays is for the host contract pointer. Application build makes sure
305313
// of that.
306314
init_runtime_property_values[0] = host_contract_ptr_buffer.data ();
307-
int hr = coreclr_initialize (
315+
int hr = FastTiming::time_call ("coreclr_initialize", coreclr_initialize,
308316
application_config.android_package_name,
309317
"Xamarin.Android",
310318
(int)application_config.number_of_runtime_properties,
@@ -315,7 +323,7 @@ void Host::Java_mono_android_Runtime_initInternal (JNIEnv *env, jclass runtimeCl
315323
);
316324

317325
if (FastTiming::enabled ()) [[unlikely]] {
318-
internal_timing.end_event (clr_init_time_index);
326+
internal_timing.end_event ();
319327
}
320328

321329
// TODO: make S_OK & friends known to us
@@ -372,14 +380,13 @@ void Host::Java_mono_android_Runtime_initInternal (JNIEnv *env, jclass runtimeCl
372380

373381
OSBridge::initialize_on_runtime_init (env, runtimeClass);
374382

375-
size_t native_to_managed_index;
376383
if (FastTiming::enabled ()) [[unlikely]] {
377-
native_to_managed_index = internal_timing.start_event (TimingEventKind::NativeToManagedTransition);
384+
internal_timing.start_event (TimingEventKind::NativeToManagedTransition);
378385
}
379386

380387
void *delegate = nullptr;
381-
log_debug (LOG_ASSEMBLY, "Creating UCO delegate to {}.RegisterJniNatives", Constants::JNIENVINIT_FULL_TYPE_NAME);
382-
delegate = create_delegate (Constants::MONO_ANDROID_ASSEMBLY_NAME, Constants::JNIENVINIT_FULL_TYPE_NAME, "RegisterJniNatives"sv);
388+
log_debug (LOG_ASSEMBLY, "Creating UCO delegate to {}.RegisterJniNatives"sv, Constants::JNIENVINIT_FULL_TYPE_NAME);
389+
delegate = FastTiming::time_call ("create_delegate for RegisterJniNatives"sv, create_delegate, Constants::MONO_ANDROID_ASSEMBLY_NAME, Constants::JNIENVINIT_FULL_TYPE_NAME, "RegisterJniNatives"sv);
383390
jnienv_register_jni_natives = reinterpret_cast<jnienv_register_jni_natives_fn> (delegate);
384391
abort_unless (
385392
jnienv_register_jni_natives != nullptr,
@@ -392,8 +399,8 @@ void Host::Java_mono_android_Runtime_initInternal (JNIEnv *env, jclass runtimeCl
392399
}
393400
);
394401

395-
log_debug (LOG_ASSEMBLY, "Creating UCO delegate to {}.Initialize", Constants::JNIENVINIT_FULL_TYPE_NAME);
396-
delegate = create_delegate (Constants::MONO_ANDROID_ASSEMBLY_NAME, Constants::JNIENVINIT_FULL_TYPE_NAME, "Initialize"sv);
402+
log_debug (LOG_ASSEMBLY, "Creating UCO delegate to {}.Initialize"sv, Constants::JNIENVINIT_FULL_TYPE_NAME);
403+
delegate = FastTiming::time_call ("create_delegate for Initialize"sv, create_delegate, Constants::MONO_ANDROID_ASSEMBLY_NAME, Constants::JNIENVINIT_FULL_TYPE_NAME, "Initialize"sv);
397404
auto initialize = reinterpret_cast<jnienv_initialize_fn> (delegate);
398405
abort_unless (
399406
initialize != nullptr,
@@ -407,19 +414,18 @@ void Host::Java_mono_android_Runtime_initInternal (JNIEnv *env, jclass runtimeCl
407414
);
408415

409416
log_debug (LOG_DEFAULT, "Calling into managed runtime init"sv);
410-
initialize (&init);
417+
FastTiming::time_call ("JNIEnv.Initialize UCO"sv, initialize, &init);
411418

412419
if (FastTiming::enabled ()) [[unlikely]] {
413-
internal_timing.end_event (native_to_managed_index);
414-
internal_timing.end_event (total_time_index);
420+
internal_timing.end_event (); // native to managed
421+
internal_timing.end_event (); // total init time
415422
}
416423
}
417424

418425
void Host::Java_mono_android_Runtime_register (JNIEnv *env, jstring managedType, jclass nativeClass, jstring methods) noexcept
419426
{
420-
size_t total_time_index;
421427
if (FastTiming::enabled ()) [[unlikely]] {
422-
total_time_index = internal_timing.start_event (TimingEventKind::RuntimeRegister);
428+
internal_timing.start_event (TimingEventKind::RuntimeRegister);
423429
}
424430

425431
jsize managedType_len = env->GetStringLength (managedType);
@@ -434,14 +440,14 @@ void Host::Java_mono_android_Runtime_register (JNIEnv *env, jstring managedType,
434440
env->ReleaseStringChars (managedType, managedType_ptr);
435441

436442
if (FastTiming::enabled ()) [[unlikely]] {
437-
internal_timing.end_event (total_time_index, true /* uses_more_info */);
443+
internal_timing.end_event (true /* uses_more_info */);
438444

439445
dynamic_local_string<SENSIBLE_TYPE_NAME_LENGTH> type;
440446
const char *mt_ptr = env->GetStringUTFChars (managedType, nullptr);
441447
type.assign (mt_ptr, strlen (mt_ptr));
442448
env->ReleaseStringUTFChars (managedType, mt_ptr);
443449

444-
internal_timing.add_more_info (total_time_index, type);
450+
internal_timing.add_more_info (type);
445451
}
446452
}
447453

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

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -105,7 +105,7 @@ managed_timing_sequence* monodroid_timing_start (const char *message)
105105
if (message != nullptr) {
106106
log_write (LOG_TIMING, LogLevel::Info, message);
107107
}
108-
ret->period.mark_start ();
108+
ret->start = FastTiming::get_time ();
109109
return ret;
110110
}
111111

@@ -121,8 +121,8 @@ void monodroid_timing_stop (managed_timing_sequence *sequence, const char *messa
121121
return;
122122
}
123123

124-
sequence->period.mark_end ();
125-
Timing::info (sequence->period, message == nullptr ? DEFAULT_MESSAGE : message);
124+
sequence->end = FastTiming::get_time ();
125+
Timing::info (sequence, message == nullptr ? DEFAULT_MESSAGE : message);
126126
timing->release_sequence (sequence);
127127
}
128128

‎src/native/clr/host/typemap.cc

Lines changed: 4 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -210,9 +210,8 @@ auto TypeMapper::typemap_managed_to_java_release (const char *typeName, const ui
210210
[[gnu::flatten]]
211211
auto TypeMapper::typemap_managed_to_java (const char *typeName, const uint8_t *mvid) noexcept -> const char*
212212
{
213-
size_t total_time_index;
214213
if (FastTiming::enabled ()) [[unlikely]] {
215-
total_time_index = internal_timing.start_event (TimingEventKind::ManagedToJava);
214+
internal_timing.start_event (TimingEventKind::ManagedToJava);
216215
}
217216

218217
if (typeName == nullptr) [[unlikely]] {
@@ -228,7 +227,7 @@ auto TypeMapper::typemap_managed_to_java (const char *typeName, const uint8_t *m
228227
#endif
229228

230229
if (FastTiming::enabled ()) [[unlikely]] {
231-
internal_timing.end_event (total_time_index);
230+
internal_timing.end_event ();
232231
}
233232

234233
return ret;
@@ -256,9 +255,8 @@ auto TypeMapper::find_java_to_managed_entry (hash_t name_hash) noexcept -> const
256255
[[gnu::flatten]]
257256
auto TypeMapper::typemap_java_to_managed (const char *java_type_name, char const** assembly_name, uint32_t *managed_type_token_id) noexcept -> bool
258257
{
259-
size_t total_time_index;
260258
if (FastTiming::enabled ()) [[unlikely]] {
261-
total_time_index = internal_timing.start_event (TimingEventKind::JavaToManaged);
259+
internal_timing.start_event (TimingEventKind::JavaToManaged);
262260
}
263261

264262
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
319317
);
320318

321319
if (FastTiming::enabled ()) [[unlikely]] {
322-
internal_timing.end_event (total_time_index);
320+
internal_timing.end_event ();
323321
}
324322

325323
return true;

‎src/native/clr/include/constants.hh

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -39,6 +39,9 @@ namespace xamarin::android {
3939
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);
4040

4141
public:
42+
static constexpr std::string_view NEWLINE { "\n" };
43+
static constexpr std::string_view EMPTY { "" };
44+
4245
// .data() must be used otherwise string_view length will include the trailing \0 in the array
4346
static constexpr std::string_view RUNTIME_CONFIG_BLOB_NAME { RUNTIME_CONFIG_BLOB_NAME_ARRAY.data () };
4447
static constexpr std::string_view OVERRIDE_DIRECTORY_NAME { ".__override__" };
@@ -57,6 +60,7 @@ namespace xamarin::android {
5760
static inline constexpr std::string_view DEBUG_MONO_SOFT_BREAKPOINTS { "debug.mono.soft_breakpoints" };
5861
static inline constexpr std::string_view DEBUG_MONO_TRACE_PROPERTY { "debug.mono.trace" };
5962
static inline constexpr std::string_view DEBUG_MONO_WREF_PROPERTY { "debug.mono.wref" };
63+
static constexpr std::string_view DEBUG_MONO_TIMING { "debug.mono.timing" };
6064

6165
static constexpr std::string_view LOG_CATEGORY_NAME_NONE { "*none*" };
6266
static constexpr std::string_view LOG_CATEGORY_NAME_MONODROID { "monodroid" };

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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,7 @@
77
#include <host_runtime_contract.h>
88

99
#include <runtime-base/jni-wrappers.hh>
10-
#include "../runtime-base/timing.hh"
10+
#include <runtime-base/timing.hh>
1111
#include "../shared/log_types.hh"
1212
#include "managed-interface.hh"
1313

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

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -85,22 +85,22 @@ namespace xamarin::android {
8585
* However, if any logging is enabled (which should _not_ happen with
8686
* pre-loaded apps!), we need the .__override__ directory...
8787
*/
88-
dynamic_local_string<Constants::PROPERTY_VALUE_BUFFER_LEN> value;
88+
dynamic_local_property_string value;
8989
if (log_categories == 0 && monodroid_get_system_property (Constants::DEBUG_MONO_PROFILE_PROPERTY, value) == 0) [[likely]] {
9090
return;
9191
}
9292
}
9393

94-
Util::create_public_directory (override_dir);
9594
log_warn (LOG_DEFAULT, "Creating public update directory: `{}`", override_dir);
95+
Util::create_public_directory (override_dir);
9696
}
9797

9898
static auto is_embedded_dso_mode_enabled () noexcept -> bool
9999
{
100100
return embedded_dso_mode_enabled;
101101
}
102102

103-
static auto monodroid_get_system_property (std::string_view const& name, dynamic_local_string<Constants::PROPERTY_VALUE_BUFFER_LEN> &value) noexcept -> int;
103+
static auto monodroid_get_system_property (std::string_view const& name, dynamic_local_property_string &value) noexcept -> int;
104104
static void detect_embedded_dso_mode (jstring_array_wrapper& appDirs) noexcept;
105105
static void setup_environment () noexcept;
106106
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

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,7 @@
55

66
#include <xamarin-app.hh>
77
#include "logger.hh"
8-
#include "timing.hh"
8+
#include <runtime-base/timing.hh>
99

1010
extern "C" {
1111
int _monodroid_gref_get () noexcept;

0 commit comments

Comments
 (0)