From 1f570406ed6b0a496ef5d5d7db4d444128ba8193 Mon Sep 17 00:00:00 2001 From: Radek Doulik Date: Wed, 16 Jan 2019 23:20:09 +0100 Subject: [PATCH] [monodroid] Add log timing categories (#2623) Fixes: https://github.com/xamarin/xamarin-android/issues/2610 Allow the `debug.mono.log` system property to contain a value of `timing=bar` so that Mono's performance counters can be *avoided*, as `counters.txt` and `methods.txt` -- normally generated when the `timing` value is used -- contribute to additional startup time, making it hard to get accurate/usable startup numbers that don't inordinately impact startup time. Example: adb shell setprop debug.mono.log timing=bare Comparison of XF test on Pixel XL 2: Startup times when `debug.mono.log=timing`: Time: 328ms Message: monodroid-timing: Runtime.init: end, total time; elapsed: 0s.18432517441218359126::16774850937603807740 Time: 329ms Message: monodroid-timing: Runtime.init: end, total time; elapsed: 0s.18432517441218787043::16774850937603807745 Time: 337ms Message: monodroid-timing: Runtime.init: end, total time; elapsed: 0s.18432517441219141783::16774850937603807750 Time: 320ms Message: monodroid-timing: Runtime.init: end, total time; elapsed: 0s.18432517441218515064::16774850937603807755 Time: 327ms Message: monodroid-timing: Runtime.init: end, total time; elapsed: 0s.18432517441218450741::16774850937603807760 Startup times when `debug.mono.log=timing=bare`: Time: 321ms Message: monodroid-timing: Runtime.init: end, total time; elapsed: 0s.18432517441219032407::16774850937603807703 Time: 314ms Message: monodroid-timing: Runtime.init: end, total time; elapsed: 0s.18432517441219071678::16774850937603807708 Time: 314ms Message: monodroid-timing: Runtime.init: end, total time; elapsed: 0s.18432517441218700949::16774850937603807713 Time: 313ms Message: monodroid-timing: Runtime.init: end, total time; elapsed: 0s.18432517441218922616::16774850937603807718 Time: 326ms Message: monodroid-timing: Runtime.init: end, total time; elapsed: 0s.18432517441218974960::16774850937603807723 Writing to `counters.txt` and `methods.txt` contributes ~10.6ms to startup time, on average, for this app. --- src/monodroid/jni/logger.c | 6 ++++++ src/monodroid/jni/logger.h | 7 +++++++ src/monodroid/jni/monodroid-glue.cc | 6 +++--- 3 files changed, 16 insertions(+), 3 deletions(-) diff --git a/src/monodroid/jni/logger.c b/src/monodroid/jni/logger.c index 24a57a00920..b0eb191cfaa 100644 --- a/src/monodroid/jni/logger.c +++ b/src/monodroid/jni/logger.c @@ -58,6 +58,7 @@ __android_log_vprint (int prio, const char* tag, const char* fmt, va_list ap) #endif unsigned int log_categories; +unsigned int log_timing_categories; int gc_spew_enabled; static FILE* @@ -125,6 +126,7 @@ init_logging_categories () #if !ANDROID log_categories = LOG_DEFAULT; #endif + log_timing_categories = LOG_TIMING_DEFAULT; if (monodroid_get_namespaced_system_property (DEBUG_MONO_LOG_PROPERTY, &value) == 0) return; @@ -171,6 +173,10 @@ init_logging_categories () log_categories |= LOG_LREF; light_lref = 1; } + + if (!strncmp (arg, "timing=bare", 11)) { + log_timing_categories |= LOG_TIMING_BARE; + } } monodroid_strfreev (args); diff --git a/src/monodroid/jni/logger.h b/src/monodroid/jni/logger.h index 3a65d6517b4..75ee3f4a705 100644 --- a/src/monodroid/jni/logger.h +++ b/src/monodroid/jni/logger.h @@ -21,6 +21,13 @@ void init_logging_categories (); void init_reference_logging (const char *override_dir); +typedef enum _LogTimingCategories { + LOG_TIMING_DEFAULT = 0, + LOG_TIMING_BARE = 1 << 0, +} LogTimingCategories; + +extern unsigned int log_timing_categories; + #if DEBUG extern int gc_spew_enabled; #endif diff --git a/src/monodroid/jni/monodroid-glue.cc b/src/monodroid/jni/monodroid-glue.cc index 9a95d9d15ca..5b28ec54f5a 100644 --- a/src/monodroid/jni/monodroid-glue.cc +++ b/src/monodroid/jni/monodroid-glue.cc @@ -862,7 +862,7 @@ mono_runtime_init (char *runtime_args) #endif profile_events = MonoProfileFlags::MONO_PROFILE_THREADS; - if (XA_UNLIKELY (utils.should_log (LOG_TIMING))) { + if (XA_UNLIKELY (utils.should_log (LOG_TIMING)) && !(log_timing_categories & LOG_TIMING_BARE)) { char *jit_log_path = utils.path_combine (androidSystem.get_override_dir (0), "methods.txt"); jit_log = utils.monodroid_fopen (jit_log_path, "a"); utils.set_world_accessable (jit_log_path); @@ -873,7 +873,7 @@ mono_runtime_init (char *runtime_args) monoFunctions.profiler_install ((MonoProfiler*)&monodroid_profiler, nullptr); monoFunctions.profiler_set_events (profile_events); monoFunctions.profiler_install_thread (reinterpret_cast (thread_start), reinterpret_cast (thread_end)); - if (XA_UNLIKELY (utils.should_log (LOG_TIMING))) + if (XA_UNLIKELY (utils.should_log (LOG_TIMING)) && !(log_timing_categories & LOG_TIMING_BARE)) monoFunctions.profiler_install_jit_end (jit_end); parse_gdb_options (); @@ -1885,7 +1885,7 @@ Java_mono_android_Runtime_init (JNIEnv *env, jclass klass, jstring lang, jobject } androidSystem.setup_process_args (env, runtimeApks); - if (XA_UNLIKELY (utils.should_log (LOG_TIMING))) { + if (XA_UNLIKELY (utils.should_log (LOG_TIMING)) && !(log_timing_categories & LOG_TIMING_BARE)) { monoFunctions.counters_enable (XA_LOG_COUNTERS); char *counters_path = utils.path_combine (androidSystem.get_override_dir (0), "counters.txt"); log_info_nocheck (LOG_TIMING, "counters path: %s", counters_path);