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

[Java.Interop] apply AggressiveInlining where profiler shows calls #541

Merged
merged 1 commit into from
Dec 18, 2019

Conversation

jonathanpeppers
Copy link
Member

Context: https://github.com/xamarin/xamarin-android/blob/master/Documentation/guides/profiling.md#profiling-managed-code

I noticed the following when profiling startup in the Blank
Xamarin.Forms app template:

Method call summary
Total(ms) Self(ms)      Calls Method name
       2        2       6470 Java.Interop.JniObjectReference:get_Handle ()
       6        4       4043 Java.Interop.JniObjectReference:get_IsValid ()
       1        1       3881 Java.Interop.JniEnvironmentInfo:get_Runtime ()
      12        3       3084 Java.Interop.JniEnvironment:get_CurrentInfo ()
       5        3       3084 Java.Interop.JniEnvironmentInfo:get_IsValid ()
       9        1       1634 Java.Interop.JniEnvironment:get_EnvironmentPointer ()
       4        0        797 Java.Interop.JniEnvironment:get_Runtime ()
       2        0        672 Java.Interop.JniType:AssertValid ()

None of these calls seem to be slow in themselves, but Xamarin.Forms
tends to make many managed-to-java transitions throughout its
startup.

I found I could just sprinkle:

[MethodImpl (MethodImplOptions.AggressiveInlining)]

and I was able to see a performance improvement!

A Debug build of the app:

Before:
12-16 10:23:08.289  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +919ms
12-16 10:23:12.126  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +802ms
12-16 10:23:16.087  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +805ms
12-16 10:23:20.053  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +806ms
12-16 10:23:24.019  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +811ms
12-16 10:23:27.985  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +815ms
12-16 10:23:31.934  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +803ms
12-16 10:23:35.901  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +816ms
12-16 10:23:39.865  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +807ms
12-16 10:23:43.797  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +806ms
Average(ms): 819
Std Err(ms): 11.2111056051082
Std Dev(ms): 35.4526288008222

After:
12-16 10:25:11.825  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +816ms
12-16 10:25:15.758  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +808ms
12-16 10:25:19.692  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +805ms
12-16 10:25:23.656  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +805ms
12-16 10:25:27.605  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +797ms
12-16 10:25:31.574  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +803ms
12-16 10:25:35.555  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +806ms
12-16 10:25:39.490  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +802ms
12-16 10:25:43.437  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +808ms
12-16 10:25:47.383  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +813ms
Average(ms): 806.3
Std Err(ms): 1.71302202100395
Std Dev(ms): 5.41705126839727

A Release build of the app:

Before (Release):
12-16 10:21:23.643  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +574ms
12-16 10:21:27.576  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +557ms
12-16 10:21:31.558  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +567ms
12-16 10:21:35.557  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +557ms
12-16 10:21:39.522  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +572ms
12-16 10:21:43.471  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +555ms
12-16 10:21:47.452  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +558ms
12-16 10:21:51.388  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +553ms
12-16 10:21:55.335  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +560ms
12-16 10:21:59.267  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +554ms
Average(ms): 560.7
Std Err(ms): 2.39467000742157
Std Dev(ms): 7.57261146794449

After:
12-16 10:26:52.042  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +551ms
12-16 10:26:56.023  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +547ms
12-16 10:27:00.038  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +550ms
12-16 10:27:04.004  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +533ms
12-16 10:27:07.953  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +540ms
12-16 10:27:11.917  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +552ms
12-16 10:27:15.869  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +540ms
12-16 10:27:19.832  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +534ms
12-16 10:27:23.815  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +543ms
12-16 10:27:27.765  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +538ms
Average(ms): 542.8
Std Err(ms): 2.19494368442058
Std Dev(ms): 6.94102137857086

These numbers were taken running on a Pixel 3 XL, a Blank
Xamarin.Forms app template using Xamarin.Forms/master.

The project and script used is in this PR:

xamarin/Xamarin.Forms#8867

Copy link
Contributor

@jpobst jpobst left a comment

Choose a reason for hiding this comment

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

Nice! 👍

Context: https://github.com/xamarin/xamarin-android/blob/master/Documentation/guides/profiling.md#profiling-managed-code

I noticed the following when profiling startup in the Blank
Xamarin.Forms app template:

    Method call summary
    Total(ms) Self(ms)      Calls Method name
           2        2       6470 Java.Interop.JniObjectReference:get_Handle ()
           6        4       4043 Java.Interop.JniObjectReference:get_IsValid ()
           1        1       3881 Java.Interop.JniEnvironmentInfo:get_Runtime ()
          12        3       3084 Java.Interop.JniEnvironment:get_CurrentInfo ()
           5        3       3084 Java.Interop.JniEnvironmentInfo:get_IsValid ()
           9        1       1634 Java.Interop.JniEnvironment:get_EnvironmentPointer ()
           4        0        797 Java.Interop.JniEnvironment:get_Runtime ()
           2        0        672 Java.Interop.JniType:AssertValid ()

None of these calls seem to be slow in themselves, but Xamarin.Forms
tends to make *many* managed-to-java transitions throughout its
startup.

I found I could just sprinkle:

    [MethodImpl (MethodImplOptions.AggressiveInlining)]

and I was able to see a performance improvement!

A `Debug` build of the app:

    Before:
    12-16 10:23:08.289  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +919ms
    12-16 10:23:12.126  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +802ms
    12-16 10:23:16.087  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +805ms
    12-16 10:23:20.053  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +806ms
    12-16 10:23:24.019  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +811ms
    12-16 10:23:27.985  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +815ms
    12-16 10:23:31.934  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +803ms
    12-16 10:23:35.901  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +816ms
    12-16 10:23:39.865  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +807ms
    12-16 10:23:43.797  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +806ms
    Average(ms): 819
    Std Err(ms): 11.2111056051082
    Std Dev(ms): 35.4526288008222

    After:
    12-16 10:25:11.825  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +816ms
    12-16 10:25:15.758  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +808ms
    12-16 10:25:19.692  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +805ms
    12-16 10:25:23.656  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +805ms
    12-16 10:25:27.605  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +797ms
    12-16 10:25:31.574  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +803ms
    12-16 10:25:35.555  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +806ms
    12-16 10:25:39.490  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +802ms
    12-16 10:25:43.437  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +808ms
    12-16 10:25:47.383  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +813ms
    Average(ms): 806.3
    Std Err(ms): 1.71302202100395
    Std Dev(ms): 5.41705126839727

A `Release` build of the app:

    Before (Release):
    12-16 10:21:23.643  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +574ms
    12-16 10:21:27.576  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +557ms
    12-16 10:21:31.558  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +567ms
    12-16 10:21:35.557  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +557ms
    12-16 10:21:39.522  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +572ms
    12-16 10:21:43.471  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +555ms
    12-16 10:21:47.452  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +558ms
    12-16 10:21:51.388  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +553ms
    12-16 10:21:55.335  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +560ms
    12-16 10:21:59.267  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +554ms
    Average(ms): 560.7
    Std Err(ms): 2.39467000742157
    Std Dev(ms): 7.57261146794449

    After:
    12-16 10:26:52.042  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +551ms
    12-16 10:26:56.023  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +547ms
    12-16 10:27:00.038  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +550ms
    12-16 10:27:04.004  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +533ms
    12-16 10:27:07.953  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +540ms
    12-16 10:27:11.917  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +552ms
    12-16 10:27:15.869  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +540ms
    12-16 10:27:19.832  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +534ms
    12-16 10:27:23.815  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +543ms
    12-16 10:27:27.765  1490  1517 I ActivityTaskManager: Displayed com.xamarin.forms.helloforms/crc6450e568c951913723.MainActivity: +538ms
    Average(ms): 542.8
    Std Err(ms): 2.19494368442058
    Std Dev(ms): 6.94102137857086

I would say this is a ~17ms improvement to a Xamarin.Forms app's
startup?

These numbers were taken running on a Pixel 3 XL, a Blank
Xamarin.Forms app template using Xamarin.Forms/master.

The project and script used is in this PR:

xamarin/Xamarin.Forms#8867
@jonpryor jonpryor merged commit 3b24a2c into dotnet:master Dec 18, 2019
@github-actions github-actions bot locked and limited conversation to collaborators Apr 13, 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.

4 participants