diff --git a/src/monodroid/jni/basic-utilities.cc b/src/monodroid/jni/basic-utilities.cc index bfe10dfa922..7d34268757c 100644 --- a/src/monodroid/jni/basic-utilities.cc +++ b/src/monodroid/jni/basic-utilities.cc @@ -88,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 51a42741ed0..e99253416cc 100644 --- a/src/monodroid/jni/basic-utilities.hh +++ b/src/monodroid/jni/basic-utilities.hh @@ -36,6 +36,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/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..c7f30d414d3 100644 --- a/src/monodroid/jni/monodroid-glue-internal.hh +++ b/src/monodroid/jni/monodroid-glue-internal.hh @@ -12,37 +12,16 @@ #include "cpp-util.hh" #include "xxhash.hh" +#include #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 +43,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 +236,11 @@ 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 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); @@ -261,6 +274,31 @@ 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; + 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; static const char* typemap_managed_to_java (MonoReflectionType *type, const uint8_t *mvid) noexcept; @@ -325,6 +363,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 1de65c5c46d..a6631fd99a4 100644 --- a/src/monodroid/jni/monodroid-glue.cc +++ b/src/monodroid/jni/monodroid-glue.cc @@ -531,6 +531,218 @@ 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); + timing_profiler_state->add_sequence (assembly, seq); +} + +void +MonodroidRuntime::prof_assembly_loaded ([[maybe_unused]] MonoProfiler *prof, MonoAssembly *assembly) noexcept +{ + 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); + timing_profiler_state->add_sequence (image, seq); +} + +void +MonodroidRuntime::prof_image_loaded ([[maybe_unused]] MonoProfiler *prof, MonoImage *image) noexcept +{ + 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); + timing_profiler_state->add_sequence (klass, seq); +} + +void +MonodroidRuntime::prof_class_loaded ([[maybe_unused]] MonoProfiler *prof, MonoClass *klass) noexcept +{ + size_t seq = timing_profiler_state->get_sequence (klass); + internal_timing->end_event (seq, true /* uses_more_info */); + + dynamic_local_string info; + 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 ([[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 */); + + 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); +} + +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 (); + + 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 ()); + 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_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 +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::Extreme: + timing_init_extreme (); + [[fallthrough]]; + + 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) { @@ -640,25 +852,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")}; - utils.create_directory (AndroidSystem::override_dirs [0], 0755); - 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..0a34d46c0b1 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,41 +19,117 @@ 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; + } - 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"); - return; + 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; + } + + if (param.equal (OPT_MODE.length (), OPT_MODE_EXTREME)) { + timing_mode = TimingMode::Extreme; + continue; + } + continue; + } + + if (param.equal (OPT_TO_FILE)) { + log_to_file = true; + continue; + } + + if (param.starts_with (OPT_FILE_NAME)) { + output_file_name = new std::string (param.start () + OPT_FILE_NAME.length (), param.length () - OPT_FILE_NAME.length ()); + continue; + } + + 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; + } } - dynamic_local_string message; + 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; +} - // Values are in nanoseconds +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 +{ + 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; + 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: @@ -74,15 +150,115 @@ FastTiming::dump () noexcept } } - uint32_t sec, ms, ns; - log_write (LOG_TIMING, LogLevel::Info, "[2/4] Accumulated performance results"); + 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, " [2/5] Assembly load: %u:%u::%u", 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, " [2/6] Java to Managed lookup: %u:%u::%u", 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, " [2/7] Managed to Java lookup: %u:%u::%u", 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_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; + } + + 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); + }; + + 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 +} + +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..75218323a5e 100644 --- a/src/monodroid/jni/timing-internal.hh +++ b/src/monodroid/jni/timing-internal.hh @@ -4,6 +4,8 @@ #include #include #include +#include +#include #include #include "logger.hh" @@ -36,7 +38,23 @@ namespace xamarin::android::internal RuntimeConfigBlob = 9, RuntimeRegister = 10, TotalRuntimeInit = 11, - Unspecified = 12, + MonoMethodJit = 12, + MonoClassLoad = 13, + MonoImageLoad = 14, + MonoAssemblyLoad = 15, + MonoMethodDuration = 16, + MonoMethodInvoke = 17, + MonoVTableLoad = 18, + LockContention = 19, + Unspecified = std::numeric_limits>::max (), + }; + + enum class TimingMode + { + Bare, + Extended, + Verbose, + Extreme, }; struct TimingEventPoint @@ -59,6 +77,7 @@ namespace xamarin::android::internal TimingEventPoint end; TimingEventKind kind; const char* more_info; + size_t more_info_length; }; template @@ -85,6 +104,33 @@ 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_MODE_EXTREME { "extreme" }; + 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 +150,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]] { @@ -172,7 +248,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 */); } @@ -182,7 +260,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 */); } @@ -234,7 +314,18 @@ 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; + + 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 { @@ -256,79 +347,127 @@ 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; + } + + 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: " }; + message.append (desc); + return; + } + + case TimingEventKind::MonoVTableLoad: { + constexpr std::string_view desc { "MonoVM vtable load: " }; + message.append (desc); + return; + } + + case TimingEventKind::LockContention: { + constexpr std::string_view desc { "MonoVM lock contention: " }; message.append (desc); return; } default: { - constexpr char desc[] = "Unknown timing event"; + constexpr std::string_view desc = { "Unknown timing event" }; message.append (desc); return; } @@ -351,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 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) { @@ -373,19 +512,33 @@ 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); 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 ()); } @@ -443,8 +596,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 std::string* output_file_name = nullptr; }; extern FastTiming *internal_timing;