Skip to content

Commit

Permalink
[monodroid] Add log timing categories (dotnet#2623)
Browse files Browse the repository at this point in the history
Fixes: dotnet#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.
  • Loading branch information
radekdoulik authored and jonpryor committed Jan 16, 2019
1 parent c22475d commit 1f57040
Show file tree
Hide file tree
Showing 3 changed files with 16 additions and 3 deletions.
6 changes: 6 additions & 0 deletions src/monodroid/jni/logger.c
Original file line number Diff line number Diff line change
Expand Up @@ -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*
Expand Down Expand Up @@ -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;

Expand Down Expand Up @@ -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);
Expand Down
7 changes: 7 additions & 0 deletions src/monodroid/jni/logger.h
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
6 changes: 3 additions & 3 deletions src/monodroid/jni/monodroid-glue.cc
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand All @@ -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<void*> (thread_start), reinterpret_cast<void*> (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 ();
Expand Down Expand Up @@ -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);
Expand Down

0 comments on commit 1f57040

Please sign in to comment.