Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Mono.Android] avoid System.Reflection.Emit usage for common calls #6657

Merged
merged 3 commits into from
Jan 28, 2022

Conversation

jonathanpeppers
Copy link
Member

@jonathanpeppers jonathanpeppers commented Jan 21, 2022

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.

.apk size difference for dotnet new android:

> apkdiff -f before.apk after.apk
Size difference in bytes ([*1] apk1 only, [*2] apk2 only):
+       3,390 assemblies/assemblies.blob
+          54 assemblies/assemblies.x86_64.blob
-           4 assemblies/assemblies.arm64_v8a.blob
-          15 assemblies/assemblies.x86.blob
-          65 assemblies/assemblies.armeabi_v7a.blob
Summary:
+       3,360 Other entries 0.03% (of 10,526,432)
+           0 Dalvik executables 0.00% (of 7,816,392)
+           0 Shared libraries 0.00% (of 18,414,404)
+       4,096 Package size difference 0.02% (of 21,006,128)

@jonpryor
Copy link
Member

jonpryor commented Jan 28, 2022

Context: https://github.com/xamarin/xamarin-android/wiki/Blueprint#java-type-registration
Context: b7a368a27667c69117f64be81050403f2d5c8560
Context: https://github.com/xamarin/xamarin-android/pull/4877
Context: https://github.com/xamarin/xamarin-android/pull/4927#issuecomment-875864999

In order for Java code to call C# code,
[`JNIEnv::RegisterNatives()][0] must be invoked, providing an array
of `JNINativeMethod` structures, each of which contains a function
pointer to invoke, kept in `JNINativeMethod::fnPtr`.

Fortunately, delegates marshal as function pointers, and there is a
bunch of `generator`-emitted infrastructure and coordination with
Java Callable Wrappers to eventually obtain a Delegate instance to
provide `JNIEnv::RegisterNatives()`.

There is one deficiency in the `generator`-emitted infrastructure:
it doesn't deal with C# exceptions.  However, exceptions "can't"
cross the JNI boundary (see b7a368a2 for an example of the breakage
that results when exceptions do cross the boundary!), except when we
*do* want exceptions to cross the JNI boundary ("improved" IDE first
chance exception experience; see xamarin/xamarin-android#4877).

This "we want to catch exceptions, except when we don't" scenario has
existed since the very beginning.  As "the very beginning" predates
[C# 4 exception filters][1], there wasn't a way for `generator`
output to "selectively `catch` exceptions".

We squared this circle by using `System.Reflection.Emit`:

 1. During Java Callable Wrapper registration, we lookup the
    "marshal method getter" as provided to the `Runtime.register()`
    invocation, e.g.
    `Android.App.Activity.GetOnCreate_Landroid_os_Bundle_Handler()`.

 2. `GetOnCreate_Landroid_os_Bundle_Handler()` is `generator` output,
    and contains a `JNINativeWrapper.CreateDelegate()` invocation:

        cb_onCreate_Landroid_os_Bundle_ = JNINativeWrapper.CreateDelegate ((_JniMarshal_PPL_V) n_OnCreate_Landroid_os_Bundle_);

 3. `JNINativeWrapper.CreateDelegate()` uses `System.Reflection.Emit`
    to create a new delegate instance which *wraps* the marshal
    method `Activity.n_OnCreate_Landroid_os_Bundle()` in a
    `try`/*filtered* `catch` block and marshals the exception to Java;
    `JNINativeWrapper.CreateDelegate()` effectively returns:

        bool _run_catch_if_debugger_not_attached (Exception e)
        {
            if (Debugger.IsAttached || !JNIEnv.PropagateExceptions) {
                JNIEnv.mono_unhandled_exception (e);
                return false;
            }
            return true;
        }

        _JniMarshal_PPL_V result = (jnienv, native__this, native_savedInstanceState) => {
            JNIEnv.WaitForBridgeProcessing ();
            try {
                Activity.n_OnCreate_Landroid_os_Bundle_ (jnienv, native__this, native_savedInstanceState);
            } catch (Exception e) when (_run_catch_if_debugger_not_attached (e)) {
                AndroidEnvironment.UnhandledException (e);
                if (Debugger.IsAttached || !JNIEnv.PropagateExceptions)
                    throw;
            }
        };
        return result;

    Again, this was C# 2.0 at the time, so C# 4 exception filters
    couldn't be used, thus the need for `System.Reflection.Emit`, so
    that [`ILGenerator.BeginExceptionFilterBLock()`][2] could be used
    (the support for which is a Mono extension).

After this point, use of `System.Reflection.Emit` was part of the
implicit ABI between Xamarin.Android and binding assemblies.  While
`generator` *could* be updated to *itself* emit the `try`/`catch`
block with exception filters, that would only work for binding
assemblies released *after* that `generator` fix.
The `System.Reflection.Emit` wrapper *can't* be skipped without
breaking semantic compatibility, *or* without allowing C# exceptions
to always pass through a JNI boundary, which would be Bad™.

The use of `System.Refleciton.Emit` is a Known Problem™, and
something we'd *like* to remove.
(Hence the [`jnimarshalmethod-gen`][3] explorations…)

With that background out of the way…

Let us turn our attention to the `dotnet new maui` template.
The default MAUI template hits `JNINativeWrapper.CreateDelegate()`
58 times during process startup, and we were wondering if we could
selectively improve these particular invocations, without needing to
re-think the entire "marshal method" infrastructure.

*Partially specialize* `JNINativeWrapper.CreateDelegate()` for the
following delegate types:

  * `_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`

This is done via use of a T4 template, which generates
`JNINativeWrapper.CreateBuiltInDelegate()`, and
`JNINativeWrapper.CreateDelegate()` is updated to call
`CreateBuiltInDelegate()`:

	partial class JNINativeWrapper {
	    static Delegate? CreateBuiltInDelegate (Delegate dlg, Type delegateType)
	    {
	        switch (delegateType.Name) {
	        case "_JniMarshal_PP_V":    return …
	        case "_JniMarshal_PPI_V":   return …
	
	        }
	        return null;
	    }

	    public static Delegate CreateDelegate (Delegate dlg)
	    {
	
	        var builtin = CreateBuiltInDelegate (dlg, dlg.GetType ();
	        if (builtin != null)
	            return builtin;
	
	    }
	}

This avoids use of `System.Reflection.Emit` for the specified types.

Other changes:

  * Update `TypeManager.GetActivateHandler()` 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 `adb shell septprop 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:

| Startup   |  Average (ms) |  Std Err (ms) |  Std Dev (ms) |
| --------- | ------------: | ------------: | ------------: | 
| Before    |        1106.3 |         6.919 |        21.879 |
| After     |        1070.8 |         5.686 |        17.980 |

This might save ~35ms on average?

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

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

The result is:

| One Call  |  Average (ms) |  Std Err (ms) |  Std Dev (ms) |
| --------- | ------------: | ------------: | ------------: | 
| Before    |        23.925 |         0.050 |         0.159 |
| After     |        18.101 |         0.107 |         0.339 |

Saving ~5.8ms for this one call.

`.apk` size difference for `dotnet new android`:

	% apkdiff -f before.apk after.apk
	Size difference in bytes ([*1] apk1 only, [*2] apk2 only):Context: https://github.com/xamarin/xamarin-android/wiki/Blueprint#java-type-registration
Context: b7a368a27667c69117f64be81050403f2d5c8560
Context: https://github.com/xamarin/xamarin-android/pull/4877
Context: https://github.com/xamarin/xamarin-android/pull/4927#issuecomment-875864999

In order for Java code to call C# code,
[`JNIEnv::RegisterNatives()][0] must be invoked, providing an array
of `JNINativeMethod` structures, each of which contains a function
pointer to invoke, kept in `JNINativeMethod::fnPtr`.

Fortunately, delegates marshal as function pointers, and there is a
bunch of `generator`-emitted infrastructure and coordination with
Java Callable Wrappers to eventually obtain a Delegate instance to
provide `JNIEnv::RegisterNatives()`.

There is one deficiency in the `generator`-emitted infrastructure:
it doesn't deal with C# exceptions.  However, exceptions "can't"
cross the JNI boundary (see b7a368a2 for an example of the breakage
that results when exceptions do cross the boundary!), except when we
*do* want exceptions to cross the JNI boundary ("improved" IDE first
chance exception experience; see xamarin/xamarin-android#4877).

This "we want to catch exceptions, except when we don't" scenario has
existed since the very beginning.  As "the very beginning" predates
[C# 4 exception filters][1], there wasn't a way for `generator`
output to "selectively `catch` exceptions".

We squared this circle by using `System.Reflection.Emit`:

 1. During Java Callable Wrapper registration, we lookup the
    "marshal method getter" as provided to the `Runtime.register()`
    invocation, e.g.
    `Android.App.Activity.GetOnCreate_Landroid_os_Bundle_Handler()`.

 2. `GetOnCreate_Landroid_os_Bundle_Handler()` is `generator` output,
    and contains a `JNINativeWrapper.CreateDelegate()` invocation:

        cb_onCreate_Landroid_os_Bundle_ = JNINativeWrapper.CreateDelegate ((_JniMarshal_PPL_V) n_OnCreate_Landroid_os_Bundle_);

 3. `JNINativeWrapper.CreateDelegate()` uses `System.Reflection.Emit`
    to create a new delegate instance which *wraps* the marshal
    method `Activity.n_OnCreate_Landroid_os_Bundle()` in a
    `try`/*filtered* `catch` block and marshals the exception to Java;
    `JNINativeWrapper.CreateDelegate()` effectively returns:

        bool _run_catch_if_debugger_not_attached (Exception e)
        {
            if (Debugger.IsAttached || !JNIEnv.PropagateExceptions) {
                JNIEnv.mono_unhandled_exception (e);
                return false;
            }
            return true;
        }

        _JniMarshal_PPL_V result = (jnienv, native__this, native_savedInstanceState) => {
            JNIEnv.WaitForBridgeProcessing ();
            try {
                Activity.n_OnCreate_Landroid_os_Bundle_ (jnienv, native__this, native_savedInstanceState);
            } catch (Exception e) when (_run_catch_if_debugger_not_attached (e)) {
                AndroidEnvironment.UnhandledException (e);
                if (Debugger.IsAttached || !JNIEnv.PropagateExceptions)
                    throw;
            }
        };
        return result;

    Again, this was C# 2.0 at the time, so C# 4 exception filters
    couldn't be used, thus the need for `System.Reflection.Emit`, so
    that [`ILGenerator.BeginExceptionFilterBLock()`][2] could be used
    (the support for which is a Mono extension).

After this point, use of `System.Reflection.Emit` was part of the
implicit ABI between Xamarin.Android and binding assemblies.  While
`generator` *could* be updated to *itself* emit the `try`/`catch`
block with exception filters, that would only work for binding
assemblies released *after* that `generator` fix.
The `System.Reflection.Emit` wrapper *can't* be skipped without
breaking semantic compatibility, *or* without allowing C# exceptions
to always pass through a JNI boundary, which would be Bad™.

The use of `System.Refleciton.Emit` is a Known Problem™, and
something we'd *like* to remove.
(Hence the [`jnimarshalmethod-gen`][3] explorations…)

With that background out of the way…

Let us turn our attention to the `dotnet new maui` template.
The default MAUI template hits `JNINativeWrapper.CreateDelegate()`
58 times during process startup, and we were wondering if we could
selectively improve these particular invocations, without needing to
re-think the entire "marshal method" infrastructure.

*Partially specialize* `JNINativeWrapper.CreateDelegate()` for the
following delegate types:

  * `_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`

This is done via use of a T4 template, which generates
`JNINativeWrapper.CreateBuiltInDelegate()`, and
`JNINativeWrapper.CreateDelegate()` is updated to call
`CreateBuiltInDelegate()`:

	partial class JNINativeWrapper {
	    static Delegate? CreateBuiltInDelegate (Delegate dlg, Type delegateType)
	    {
	        switch (delegateType.Name) {
	        case "_JniMarshal_PP_V":    return …
	        case "_JniMarshal_PPI_V":   return …
	
	        }
	        return null;
	    }

	    public static Delegate CreateDelegate (Delegate dlg)
	    {
	
	        var builtin = CreateBuiltInDelegate (dlg, dlg.GetType ();
	        if (builtin != null)
	            return builtin;
	
	    }
	}

This avoids use of `System.Reflection.Emit` for the specified types.

Other changes:

  * Update `TypeManager.GetActivateHandler()` 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 `adb shell septprop 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:

| Startup   |  Average (ms) |  Std Err (ms) |  Std Dev (ms) |
| --------- | ------------: | ------------: | ------------: | 
| Before    |        1106.3 |         6.919 |        21.879 |
| After     |        1078.8 |         5.438 |        17.197 |

This might save ~35ms on average?

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

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

The result is:

| One Call  |  Average (ms) |  Std Err (ms) |  Std Dev (ms) |
| --------- | ------------: | ------------: | ------------: | 
| Before    |        23.925 |         0.050 |         0.159 |
| After     |        18.723 |         0.094 |         0.298 |

Saving ~5.8ms for this one call.

`.apk` size difference for `dotnet new android`:

	% apkdiff -f before.apk after.apk
	Size difference in bytes ([*1] apk1 only, [*2] apk2 only):
	+       3,390 assemblies/assemblies.blob
	+          54 assemblies/assemblies.x86_64.blob
	-           4 assemblies/assemblies.arm64_v8a.blob
	-          15 assemblies/assemblies.x86.blob
	-          65 assemblies/assemblies.armeabi_v7a.blob
	Summary:
	+       3,360 Other entries 0.03% (of 10,526,432)
	+           0 Dalvik executables 0.00% (of 7,816,392)
	+           0 Shared libraries 0.00% (of 18,414,404)
	+       4,096 Package size difference 0.02% (of 21,006,128)

We're looking at a ~4KB size increase for this partial specialization.

[0]: https://docs.oracle.com/javase/8/docs/technotes/guides/jni/spec/functions.html#RegisterNatives
[1]: https://docs.microsoft.com/en-us/dotnet/csharp/fundamentals/exceptions/exception-handling#catch-blocks
[2]: https://docs.microsoft.com/is-is/dotnet/api/system.reflection.emit.ilgenerator.beginexceptfilterblock?view=net-6.0
[3]: http://github.com/xamarin/Java.Interop/commit/c8f3e51a6cfd78bdce89e2429efae4495481f57b
[4]: https://github.com/dotnet/maui/blob/bfba62ed796d3416c4fcaa7cfbea86dc8d5e04c2/src/Compatibility/ControlGallery/src/Android/MainApplication.cs

jonathanpeppers and others added 2 commits January 28, 2022 11:55
`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.

`.apk` size difference for `dotnet new android`:

    > apkdiff -f before.apk after.apk
    Size difference in bytes ([*1] apk1 only, [*2] apk2 only):
    +       3,390 assemblies/assemblies.blob
    +          54 assemblies/assemblies.x86_64.blob
    -           4 assemblies/assemblies.arm64_v8a.blob
    -          15 assemblies/assemblies.x86.blob
    -          65 assemblies/assemblies.armeabi_v7a.blob
    Summary:
    +       3,360 Other entries 0.03% (of 10,526,432)
    +           0 Dalvik executables 0.00% (of 7,816,392)
    +           0 Shared libraries 0.00% (of 18,414,404)
    +       4,096 Package size difference 0.02% (of 21,006,128)
JNIEnv.WaitForBridgeProcessing ();
try {
<#= info.Return ? "return " : "" #>callback <#= info.Signature #>;
} catch (Exception e) {
Copy link
Member

@jonpryor jonpryor Jan 28, 2022

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This catch should be updated to:

catch (Exception e) when (_unhandled_exception (e)) {
    AndroidEnvironment.UnhandledException (e);
    if (Debugger.IsAttached || !JNIEnv.PropagateExceptions)
        throw;
}

@jonathanpeppers
Copy link
Member Author

I think the performance with the latest changes is still probably the same (or very close):

01-28 14:06:52.645 25275 25275 I monodroid-timing: Runtime.register: end time; elapsed: 0s:18::556772
01-28 14:06:54.854 25349 25349 I monodroid-timing: Runtime.register: end time; elapsed: 0s:18::667189
01-28 14:06:57.063 25425 25425 I monodroid-timing: Runtime.register: end time; elapsed: 0s:18::700887
01-28 14:06:59.253 25494 25494 I monodroid-timing: Runtime.register: end time; elapsed: 0s:18::666356
01-28 14:07:01.459 25564 25564 I monodroid-timing: Runtime.register: end time; elapsed: 0s:18::959117
01-28 14:07:03.660 25632 25632 I monodroid-timing: Runtime.register: end time; elapsed: 0s:18::748179
01-28 14:07:05.902 25733 25733 I monodroid-timing: Runtime.register: end time; elapsed: 0s:19::445210
01-28 14:07:08.156 25836 25836 I monodroid-timing: Runtime.register: end time; elapsed: 0s:18::415835
01-28 14:07:10.392 25942 25942 I monodroid-timing: Runtime.register: end time; elapsed: 0s:18::425575
01-28 14:07:12.598 26026 26026 I monodroid-timing: Runtime.register: end time; elapsed: 0s:18::644324
Average(ms): 18.7229444
Std Err(ms): 0.0943644528736206
Std Dev(ms): 0.298406601236262

Then full displayed:

01-28 14:10:18.465  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s92ms
01-28 14:10:20.660  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s70ms
01-28 14:10:22.881  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s86ms
01-28 14:10:25.108  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s112ms
01-28 14:10:27.270  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s58ms
01-28 14:10:29.462  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s81ms
01-28 14:10:31.665  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s93ms
01-28 14:10:33.859  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s71ms
01-28 14:10:36.063  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s66ms
01-28 14:10:38.296  1867  2226 I ActivityTaskManager: Displayed com.companyname.bar/crc6474063b540de74d1e.MainActivity: +1s59ms
Average(ms): 1078.8
Std Err(ms): 5.4381369358755
Std Dev(ms): 17.1968989452556

@jonpryor jonpryor merged commit 32cff43 into dotnet:main Jan 28, 2022
@jonathanpeppers jonathanpeppers deleted the wip-jninativewrapper-sre branch January 28, 2022 22:15
@github-actions github-actions bot locked and limited conversation to collaborators Jan 24, 2024
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants