Skip to content

Commit

Permalink
[Mono.Android] avoid System.Reflection.Emit usage for common calls
Browse files Browse the repository at this point in the history 
`dotnet new android` calls `JNINativeWrapper.CreateDelegate()` twice,
while `dotnet new maui` ends up calling it 58 times during startup.

This code path calls System.Reflection.Emit to generate a
`System.Delegate` at runtime to be invoked. After some thought, it is
possible to "hard code" common delegate types and avoid SRE:

    private static Delegate CreateBuiltInDelegate (Delegate dlg, Type delegateType)
    {
        switch (delegateType.Name) {
            case nameof (_JniMarshal_PP_V): {
                    _JniMarshal_PP_V callback = (_JniMarshal_PP_V) Delegate.CreateDelegate (typeof (_JniMarshal_PP_V), dlg.Target, dlg.Method);
                    _JniMarshal_PP_V result = (jnienv, klazz) => {
                        JNIEnv.WaitForBridgeProcessing ();
                        try {
                            callback (jnienv, klazz);
                        } catch (Exception e) {
                            bool filter = Debugger.IsAttached || !JNIEnv.PropagateExceptions;
                            if (filter && JNIEnv.mono_unhandled_exception != null) {
                                JNIEnv.mono_unhandled_exception (e);
                            }
                            AndroidEnvironment.UnhandledException (e);
                            if (filter)
                                throw;

                        }
                    };
                    return result;
                }
        // etc.

`dotnet new maui`'s startup can be covered if we hardcoded:

    _JniMarshal_PP_V
    _JniMarshal_PPI_V
    _JniMarshal_PPL_L
    _JniMarshal_PPL_V
    _JniMarshal_PPL_Z
    _JniMarshal_PPII_V
    _JniMarshal_PPLI_V
    _JniMarshal_PPLL_V
    _JniMarshal_PPLL_Z
    _JniMarshal_PPIIL_V
    _JniMarshal_PPILL_V
    _JniMarshal_PPLIL_Z
    _JniMarshal_PPLLL_L
    _JniMarshal_PPLLL_Z
    _JniMarshal_PPIIII_V
    _JniMarshal_PPLLLL_V
    _JniMarshal_PPLIIII_V
    _JniMarshal_PPZIIII_V
    _JniMarshal_PPLIIIIIIII_V

Then System.Reflection.Emit isn't used at all.

Other changes:

* `TypeManager.GetActivateHandler()` needs to use
  `_JniMarshal_PPLLLL_V` instead of `Action<IntPtr, IntPtr, IntPtr,
  IntPtr, IntPtr, IntPtr>`, so the fast path can be used.

* Added a log message for `debug.mono.log assembly`:

    Falling back to System.Reflection.Emit for delegate type '{delegateType}': {dlg.Method}

* I was also able to remove `mono_unhandled_exception_method` from
  `JNINativeWrapper` as we already has this value in `JNIEnv`.

~~ Results ~~

Testing `dotnet new maui` with version:

    msbuild Xamarin.Android.sln -t:InstallMaui -bl -p:MauiVersion=6.0.200-preview.13.2536

A `Release` build on a Pixel 5 device, total startup time:

    Before:
    01-21 11:58:39.030  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s83ms
    01-21 11:58:41.297  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s127ms
    01-21 11:58:43.429  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s68ms
    01-21 11:58:45.702  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s113ms
    01-21 11:58:47.906  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s125ms
    01-21 11:58:50.082  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s92ms
    01-21 11:58:52.297  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s133ms
    01-21 11:58:54.465  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s102ms
    01-21 11:58:56.673  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s126ms
    01-21 11:58:58.848  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s94ms
    Average(ms): 1106.3
    Std Err(ms): 6.91865433287267
    Std Dev(ms): 21.8787060352704

    After:
    01-21 12:00:33.312  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s61ms
    01-21 12:00:35.513  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s79ms
    01-21 12:00:37.724  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s85ms
    01-21 12:00:39.928  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s83ms
    01-21 12:00:42.117  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s60ms
    01-21 12:00:44.337  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s59ms
    01-21 12:00:46.612  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s106ms
    01-21 12:00:48.782  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s47ms
    01-21 12:00:51.018  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s75ms
    01-21 12:00:53.200  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s53ms
    Average(ms): 1070.8
    Std Err(ms): 5.68584988272544
    Std Dev(ms): 17.9802360632137

This might save ~35ms on average?

If I time the message for one call, such as:

    01-21 12:14:01.132 29819 29819 I monodroid-timing: Runtime.register: registering type `Microsoft.Maui.MauiApplication, Microsoft.Maui, Version=1.0.0.0,
    Culture=neutral, PublicKeyToken=null`
    01-21 12:14:01.150 29819 29819 I monodroid-timing: Runtime.register: end time; elapsed: 0s:17::794845

https://github.com/dotnet/maui/blob/bfba62ed796d3416c4fcaa7cfbea86dc8d5e04c2/src/Compatibility/ControlGallery/src/Android/MainApplication.cs

The result is:

    Before:
    01-21 13:21:22.261  9359  9359 I monodroid-timing: Runtime.register: end time; elapsed: 0s:23::868440
    01-21 13:21:24.446  9424  9424 I monodroid-timing: Runtime.register: end time; elapsed: 0s:23::875159
    01-21 13:21:26.639  9497  9497 I monodroid-timing: Runtime.register: end time; elapsed: 0s:23::829742
    01-21 13:21:28.842  9570  9570 I monodroid-timing: Runtime.register: end time; elapsed: 0s:24::165211
    01-21 13:21:31.021  9631  9631 I monodroid-timing: Runtime.register: end time; elapsed: 0s:23::976721
    01-21 13:21:33.221  9697  9697 I monodroid-timing: Runtime.register: end time; elapsed: 0s:24::237034
    01-21 13:21:35.418  9759  9759 I monodroid-timing: Runtime.register: end time; elapsed: 0s:23::857346
    01-21 13:21:37.585  9821  9821 I monodroid-timing: Runtime.register: end time; elapsed: 0s:23::872138
    01-21 13:21:39.805  9884  9884 I monodroid-timing: Runtime.register: end time; elapsed: 0s:23::840107
    01-21 13:21:42.014  9952  9952 I monodroid-timing: Runtime.register: end time; elapsed: 0s:23::723805
    Average(ms): 23.9245703
    Std Err(ms): 0.0502830551065224
    Std Dev(ms): 0.159008981848371

    After:
    01-21 13:22:28.004 10226 10226 I monodroid-timing: Runtime.register: end time; elapsed: 0s:18::12345
    01-21 13:22:30.261 10298 10298 I monodroid-timing: Runtime.register: end time; elapsed: 0s:18::338022
    01-21 13:22:32.443 10362 10362 I monodroid-timing: Runtime.register: end time; elapsed: 0s:18::56251
    01-21 13:22:34.664 10427 10427 I monodroid-timing: Runtime.register: end time; elapsed: 0s:17::997397
    01-21 13:22:36.902 10497 10497 I monodroid-timing: Runtime.register: end time; elapsed: 0s:17::787554
    01-21 13:22:39.117 10563 10563 I monodroid-timing: Runtime.register: end time; elapsed: 0s:17::801772
    01-21 13:22:41.306 10630 10630 I monodroid-timing: Runtime.register: end time; elapsed: 0s:18::28752
    01-21 13:22:43.552 10695 10695 I monodroid-timing: Runtime.register: end time; elapsed: 0s:18::75522
    01-21 13:22:45.761 10759 10759 I monodroid-timing: Runtime.register: end time; elapsed: 0s:17::958075
    01-21 13:22:47.978 10823 10823 I monodroid-timing: Runtime.register: end time; elapsed: 0s:18::961773
    Average(ms): 18.1017463
    Std Err(ms): 0.107071213504746
    Std Dev(ms): 0.338588906513177

Saving ~5.8ms for this one call.
  • Loading branch information
@jonathanpeppers
jonathanpeppers committed Jan 21, 2022
1 parent 98d243e commit 3991f63
Show file tree
Hide file tree
Showing 6 changed files with 481 additions and 24 deletions.
18 changes: 11 additions & 7 deletions src/Mono.Android/Android.Runtime/JNIEnv.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -56,7 +56,7 @@ public static partial class JNIEnv {
internal static bool PropagateExceptions;

internal static bool IsRunningOnDesktop;
internal static bool LogTypemapMissStackTrace;
internal static bool LogAssemblyCategory;

static AndroidRuntime? androidRuntime;
static BoundExceptionType BoundExceptionType;
Expand All @@ -67,7 +67,7 @@ public static partial class JNIEnv {
internal static AndroidValueManager? AndroidValueManager;

[DllImport (AndroidRuntime.InternalDllName, CallingConvention = CallingConvention.Cdecl)]
extern static void monodroid_log (LogLevel level, LogCategories category, string message);
internal extern static void monodroid_log (LogLevel level, LogCategories category, string message);

[DllImport (AndroidRuntime.InternalDllName, CallingConvention = CallingConvention.Cdecl)]
internal extern static IntPtr monodroid_timing_start (string? message);
Expand Down Expand Up @@ -149,7 +149,7 @@ internal static unsafe void Initialize (JnienvInitializeArgs* args)
partial_timing_sequence = monodroid_timing_start (null);
}

LogTypemapMissStackTrace = (args->logCategories & (uint)LogCategories.Assembly) != 0;
LogAssemblyCategory = (args->logCategories & (uint)LogCategories.Assembly) != 0;

gref_gc_threshold = args->grefGcThreshold;

Expand Down Expand Up @@ -246,6 +246,7 @@ static void ManualJavaObjectDispose (Java.Lang.Object obj)
#else // NETCOREAPP
internal static Action<Exception> mono_unhandled_exception = null!;
#endif // NETCOREAPP
internal static MethodInfo? mono_unhandled_exception_method = null;

#if !NETCOREAPP
static Action<AppDomain, UnhandledExceptionEventArgs> AppDomain_DoUnhandledException = null!;
Expand All @@ -254,10 +255,13 @@ static void ManualJavaObjectDispose (Java.Lang.Object obj)
static void Initialize ()
{
if (mono_unhandled_exception == null) {
var mono_UnhandledException = typeof (System.Diagnostics.Debugger)
mono_unhandled_exception_method = typeof (System.Diagnostics.Debugger)
.GetMethod ("Mono_UnhandledException", BindingFlags.NonPublic | BindingFlags.Static);
if (mono_UnhandledException != null)
mono_unhandled_exception = (Action<Exception>) Delegate.CreateDelegate (typeof(Action<Exception>), mono_UnhandledException);
if (mono_unhandled_exception_method != null)
mono_unhandled_exception = (Action<Exception>) Delegate.CreateDelegate (typeof(Action<Exception>), mono_unhandled_exception_method);
}
if (mono_unhandled_exception_method == null && mono_unhandled_exception != null) {
mono_unhandled_exception_method = mono_unhandled_exception.Method;
}

#if !NETCOREAPP
Expand Down Expand Up @@ -737,7 +741,7 @@ internal static void LogTypemapTrace (StackTrace st)
}

if (ret == IntPtr.Zero) {
if (LogTypemapMissStackTrace) {
if (LogAssemblyCategory) {
monodroid_log (LogLevel.Warn, LogCategories.Default, $"typemap: failed to map managed type to Java type: {type.AssemblyQualifiedName} (Module ID: {type.Module.ModuleVersionId}; Type token: {type.MetadataToken})");
LogTypemapTrace (new StackTrace (true));
}
Expand Down
26 changes: 13 additions & 13 deletions src/Mono.Android/Android.Runtime/JNINativeWrapper.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -5,25 +5,16 @@
using System.Threading;

namespace Android.Runtime {
public static class JNINativeWrapper {
public static partial class JNINativeWrapper {

static MethodInfo? mono_unhandled_exception_method;
static MethodInfo? exception_handler_method;
static MethodInfo? wait_for_bridge_processing_method;

static void get_runtime_types ()
{
if (exception_handler_method != null)
return;
#if MONOANDROID1_0
mono_unhandled_exception_method = typeof (System.Diagnostics.Debugger).GetMethod (
"Mono_UnhandledException", BindingFlags.NonPublic | BindingFlags.Static);
if (mono_unhandled_exception_method == null)
AndroidEnvironment.FailFast ("Cannot find System.Diagnostics.Debugger.Mono_UnhandledException");
#endif
#if NETCOREAPP
mono_unhandled_exception_method = JNIEnv.mono_unhandled_exception.Method;
#endif // NETCOREAPP

exception_handler_method = typeof (AndroidEnvironment).GetMethod (
"UnhandledException", BindingFlags.NonPublic | BindingFlags.Static);
if (exception_handler_method == null)
Expand All @@ -45,6 +36,15 @@ public static Delegate CreateDelegate (Delegate dlg)

get_runtime_types ();

var delegateType = dlg.GetType ();
var result = CreateBuiltInDelegate (dlg, delegateType);
if (result != null)
return result;

if (JNIEnv.LogAssemblyCategory) {
JNIEnv.monodroid_log (LogLevel.Warn, LogCategories.Default, $"Falling back to System.Reflection.Emit for delegate type '{delegateType}': {dlg.Method}");
}

var ret_type = dlg.Method.ReturnType;
var parameters = dlg.Method.GetParameters ();
var param_types = new Type [parameters.Length];
Expand Down Expand Up @@ -73,10 +73,10 @@ public static Delegate CreateDelegate (Delegate dlg)
ig.Emit (OpCodes.Leave, label);

bool filter = Debugger.IsAttached || !JNIEnv.PropagateExceptions;
if (filter && mono_unhandled_exception_method != null) {
if (filter && JNIEnv.mono_unhandled_exception_method != null) {
ig.BeginExceptFilterBlock ();

ig.Emit (OpCodes.Call, mono_unhandled_exception_method);
ig.Emit (OpCodes.Call, JNIEnv.mono_unhandled_exception_method);
ig.Emit (OpCodes.Ldc_I4_1);
ig.BeginCatchBlock (null!);
} else {
Expand Down
Loading

0 comments on commit 3991f63

Please sign in to comment.