Skip to content

Conversation

@jonathanpeppers
Copy link
Member

Context: https://github.com/microsoft/dotnet-podcasts

Reviewing a dotnet trace log from the .NET Podcast app, I see:

40.12ms Mono.Android!Java.Interop.TypeManager.n_Activate(intptr,intptr,intptr,intptr,intptr,intptr)

The bulk of this time (~33ms) is spent in System.Reflection.Emit-related code.

Instead of using S.R.E, it appears we can use regular
System.Reflection and call ConstructorInfo.Invoke() to do the work?

The equivalent, non S.R.E code would call:

  • RuntimeHelpers.GetUninitializedObject()
  • Set the field .handle directly, which requires
    Java.Lang.Object.handle to be internal.
  • Invoke the ConstructorInfo, passing the uninitialized object

After these changes, a new dotnet trace of the .NET Podcast app:

17.09ms Mono.Android!Java.Interop.TypeManager.n_Activate(intptr,intptr,intptr,intptr,intptr,intptr)

I see about 6.37ms of the time spent in regular System.Reflection code
instead (ConstructorInfo.Invoke()).

Results

Testing dotnet new maui on a Pixel 5 device, a regular Release
build (without AOT):

Before:
02-16 11:32:15.665  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +970ms
02-16 11:32:16.797  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +940ms
02-16 11:32:17.993  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +943ms
02-16 11:32:19.191  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +949ms
02-16 11:32:20.436  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +963ms
02-16 11:32:21.600  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +940ms
02-16 11:32:22.764  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +934ms
02-16 11:32:23.962  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +959ms
02-16 11:32:25.097  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +942ms
02-16 11:32:26.290  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +941ms
Average(ms): 948.1
Std Err(ms): 3.74892577206384
Std Dev(ms): 11.855144218627

After:
02-16 11:23:01.038  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +918ms
02-16 11:23:02.250  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +929ms
02-16 11:23:03.432  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +926ms
02-16 11:23:04.614  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +942ms
02-16 11:23:05.796  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +937ms
02-16 11:23:07.005  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +948ms
02-16 11:23:08.211  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +955ms
02-16 11:23:09.353  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +932ms
02-16 11:23:10.555  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +954ms
02-16 11:23:11.729  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +946ms
Average(ms): 938.7
Std Err(ms): 3.91875830674292
Std Dev(ms): 12.3922018490124

I suspect this saves ~10ms for this app?

Context: https://github.com/microsoft/dotnet-podcasts

Reviewing a `dotnet trace` log from the .NET Podcast app, I see:

    40.12ms Mono.Android!Java.Interop.TypeManager.n_Activate(intptr,intptr,intptr,intptr,intptr,intptr)

The bulk of this time (~33ms) is spent in System.Reflection.Emit-related code.

Instead of using S.R.E, it appears we can use regular
System.Reflection and call `ConstructorInfo.Invoke()` to do the work?

The equivalent, non S.R.E code would call:

* `RuntimeHelpers.GetUninitializedObject()`
* Set the field `.handle` directly, which requires
  `Java.Lang.Object.handle` to be internal.
* Invoke the `ConstructorInfo`, passing the uninitialized object

After these changes, a new `dotnet trace` of the .NET Podcast app:

    17.09ms Mono.Android!Java.Interop.TypeManager.n_Activate(intptr,intptr,intptr,intptr,intptr,intptr)

I see about 6.37ms of the time spent in regular System.Reflection code
instead (`ConstructorInfo.Invoke()`).

~~ Results ~~

Testing `dotnet new maui` on a Pixel 5 device, a regular `Release`
build (without AOT):

    Before:
    02-16 11:32:15.665  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +970ms
    02-16 11:32:16.797  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +940ms
    02-16 11:32:17.993  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +943ms
    02-16 11:32:19.191  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +949ms
    02-16 11:32:20.436  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +963ms
    02-16 11:32:21.600  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +940ms
    02-16 11:32:22.764  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +934ms
    02-16 11:32:23.962  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +959ms
    02-16 11:32:25.097  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +942ms
    02-16 11:32:26.290  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +941ms
    Average(ms): 948.1
    Std Err(ms): 3.74892577206384
    Std Dev(ms): 11.855144218627

    After:
    02-16 11:23:01.038  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +918ms
    02-16 11:23:02.250  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +929ms
    02-16 11:23:03.432  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +926ms
    02-16 11:23:04.614  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +942ms
    02-16 11:23:05.796  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +937ms
    02-16 11:23:07.005  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +948ms
    02-16 11:23:08.211  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +955ms
    02-16 11:23:09.353  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +932ms
    02-16 11:23:10.555  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +954ms
    02-16 11:23:11.729  1980  2259 I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +946ms
    Average(ms): 938.7
    Std Err(ms): 3.91875830674292
    Std Dev(ms): 12.3922018490124

I suspect this saves ~10ms for this app?
jonathanpeppers added a commit to jonathanpeppers/xamarin-android that referenced this pull request Feb 16, 2022
Context: https://github.com/microsoft/dotnet-podcasts

In working on dotnet#6766 and reviewing `dotnet trace` output, I found time
being spent in `JNIEnv.GetObjectArray()`:

    17.09ms Mono.Android!Java.Interop.TypeManager.n_Activate(intptr,intptr,intptr,intptr,intptr,intptr)
    ...
     4.96ms Mono.Android!Android.Runtime.JNIEnv.GetObjectArray

In this case, it is taking an array of parameters and calling a
constructor. A lot of the time we are calling empty constructors!

Reviewing `JNIEnv.GetObjectArray()` we could add a check if the array
is of length 0 and return `Array.Empty<object>()`. I also found one
other place doing `new Type[0]` we can fix while we're at it.

After the change, I instead get:

    2.56ms Mono.Android!Android.Runtime.JNIEnv.GetObjectArray

I'm not able to see a noticeable difference in `dotnet new maui`,
likely as this is such as small improvement.
@jonathanpeppers jonathanpeppers marked this pull request as ready for review February 16, 2022 20:56
jonpryor pushed a commit that referenced this pull request Feb 16, 2022
Context: https://github.com/microsoft/dotnet-podcasts
Context: #6766

While working on #6766 and reviewing `dotnet trace` output, I found
time was being spent in `JNIEnv.GetObjectArray()`:

	17.09ms Mono.Android!Java.Interop.TypeManager.n_Activate(intptr,intptr,intptr,intptr,intptr,intptr)
	…
	 4.96ms Mono.Android!Android.Runtime.JNIEnv.GetObjectArray

In this case, it is taking an array of parameters and calling a
constructor.  A lot of the time we are calling empty constructors!

Reviewing `JNIEnv.GetObjectArray()` we could add a check if the array
is of length 0 and return `Array.Empty<object>()`.  I also found one
other place doing `new Type[0]` we can fix while we're at it.

After the change, I instead get:

	 2.56ms Mono.Android!Android.Runtime.JNIEnv.GetObjectArray

I'm not able to see a noticeable difference in `dotnet new maui`,
likely as this is such as small improvement.
@jonpryor
Copy link
Contributor

Context: https://github.com/microsoft/dotnet-podcasts
Context: https://github.com/xamarin/monodroid/commit/0c29e9a1eb6572082dd478f34bad092049974a00

Reviewing a `dotnet trace` log from the .NET Podcast app, I see:

	40.12ms Mono.Android!Java.Interop.TypeManager.n_Activate(intptr,intptr,intptr,intptr,intptr,intptr)

The bulk of this time (~33ms) is spent in `System.Reflection.Emit`-
related code.

Instead of using `System.Reflection.Emit`, it appears we can instead
use regular `System.Reflection` and instead call
[`MethodBase.Invoke(object?, object?[]?)`][0] on a `ConstructorInfo`
instance to invoke a constructor on an already created instance.

The equivalent, non-`System.Reflection.Emit` code would call:

 1. `RuntimeHelpers.GetUninitializedObject()`

 2. Set the field `.handle` directly, which requires
    `Java.Lang.Object.handle` and `Java.Lang.Throwable.handle` to be
    `internal`.

 3. Invoke "`ConstructorInfo.Invoke()`", *but actually* the
    `MethodBase.Invoke(object?, object?[]?)` overload, providing the
    uninitialzied object as the first `obj` parameter.

After these changes, a new `dotnet trace` of the .NET Podcast app:

	17.09ms Mono.Android!Java.Interop.TypeManager.n_Activate(intptr,intptr,intptr,intptr,intptr,intptr)

I see about 6.37ms of the time spent in regular `System.Reflection`
code (`ConstructorInfo.Invoke()`) instead of `DynamicMethod` code.

~~ Results ~~

Testing `dotnet new maui` on a Pixel 5 device, a regular `Release`
build (without AOT):

  * Before:

        I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +970ms
        I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +940ms
        I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +943ms
        I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +949ms
        I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +963ms
        I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +940ms
        I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +934ms
        I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +959ms
        I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +942ms
        I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +941ms

      * Average(ms): 948.1
      * Std Err(ms): 3.74892577206384
      * Std Dev(ms): 11.855144218627

  * After:

        I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +918ms
        I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +929ms
        I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +926ms
        I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +942ms
        I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +937ms
        I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +948ms
        I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +955ms
        I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +932ms
        I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +954ms
        I ActivityTaskManager: Displayed com.companyname.foo/crc64808a40cc7e533249.MainActivity: +946ms

      * Average(ms): 938.7
      * Std Err(ms): 3.91875830674292
      * Std Dev(ms): 12.3922018490124

I suspect this saves ~10ms for this app?

~~ Meta Question ~~

This change necessitates asking why `DynamicMethod` was used in
the first place.  The [commit which introduced the change][1] states:

> Implement a DynamicMethod based constructor trampoline for Java 
> based activation
> 
> We need to guard against reentrancy of java-activated objects, so
> we build a small dynamic method which creates the uninitialized
> object, sets the handle field and then runs the constructor.
> This allows us to guard against calling NewObject based on the
> value of the IntPtr field.

[`JNIEnv::NewObject()`][2] is Bad™; [`JNIEnv::AllocObject()`][3] and
[`JNIEnv::CallNonvirtualVoidMethod()`][4] should be used instead.
See [xamarin/java.interop@972c5bc6][5] for details.

However, Xamarin.Android's use of `JNIEnv::AllocObject()` +
`JNIEnv::CallNonvirtualVoidMethod()` wasn't introduced [until 2013][6],
while the initial use of `DynamicMethod` began in 2010.

Thus, two theories for why `DynamicMethod` was used:

 1. We didn't realize that `ConstructorInfo` inherited from
    `MethodBase`, that `MethodBase.Invoke(object, object[])` existed,
    and thus we avoid `DynamicMethod` entirely, *or*

 2. `DynamicMethod` was an attempt to work around the limitations of
    `JNIEnv::NewObject()`, before all the pitfalls of using
    `JNIEnv::NewObject()` were fully understood.  (Additionally,
    `JNIEnv::NewObject()` use was *required* before Android 3.0!)

Either way, it doesn't look like we need to use `DynamicMethod` to
invoke C# constructors anymore.

[0]: https://docs.microsoft.com/en-us/dotnet/api/system.reflection.methodbase.invoke?view=net-6.0#system-reflection-methodbase-invoke(system-object-system-object())
[1]: https://github.com/xamarin/monodroid/commit/0c29e9a1eb6572082dd478f34bad092049974a00
[2]: https://docs.oracle.com/javase/8/docs/technotes/guides/jni/spec/functions.html#NewObject
[3]: https://docs.oracle.com/javase/8/docs/technotes/guides/jni/spec/functions.html#AllocObject
[4]: https://docs.oracle.com/javase/8/docs/technotes/guides/jni/spec/functions.html#CallNonvirtual_type_Method_routines
[5]: https://github.com/xamarin/Java.Interop/commit/972c5bc605bd87526f3ddd7735d21f47d9f2d4aa
[6]: https://github.com/xamarin/monodroid/commit/326509e56d4e582c53bbe5dfe6d5c741a27f1af5

@jonpryor jonpryor merged commit 25e0eef into dotnet:main Feb 17, 2022
@jonathanpeppers jonathanpeppers deleted the RemoveConstructorBuilder branch February 17, 2022 02:18
@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