dotnet / android

.NET for Android provides open-source bindings of the Android SDK for use with .NET managed languages such as C#
MIT License
1.94k stars 533 forks source link

Weird performance behaviour differences in my app between the Xamarin.Android build as compared to the Net7 build #8285

Open gmck opened 1 year ago

gmck commented 1 year ago

Android application type

.NET Android (net7.0-android, etc.)

Affected platform version

VS 2022 17.7.0 Prev 6.0

Description

I have the following results of start-up time (displayed value) via LogCat.

X.A. Build Net7 Build

  1. 512ms 1. 497ms
  2. 421ms 2. 441ms
  3. 440ms 3. 434ms
  4. 417ms 4. 440ms Average 447ms Average 453ms

At this point, you’d have to say the start-up performance of both apps is about the same. When navigating from fragment to fragment and generally just exploring the features of the app, they appear to be very similar with good performance.

However, until a user is signed in via a GoogleSignIn fragment, there isn’t any real functionality that can be tested because until the user is signed in, they can’t really do much other than explore the various screens (fragments) via the NavigationView and the 3 dot menu of the StartDestination fragment.

The following are the results after the completion of the GoogleSignIn. After a successful sign in the relevant data is saved to SharedPreferences. The code of the GoogleSignIn fragment is identical in each build.

Pixel 7 X.A. Build Net7 Build

  1. 618ms 1.419
  2. 467ms 1.335
  3. 623ms 1.332
  4. 611ms 1.341 Average 579ms 1.356

That’s a difference of nearly 0.8 sec, which is extremely noticeable when navigating between fragments etc. as compared to the X.A. version. There is a general feeling of sluggishness in the Net7 app after selecting any menuItem of NavigationView and then waiting for the new fragment to appear.

If you refer to my final comment in #8239 you’ll find the aab sizes and build times listed there. The displayed times there are very similar to this latest test. The only downer there is that the Build time for the release version takes considerably longer for the Net7 build – close to 2 minutes longer than the X.A. build.

I’ve also run the same test on a Pixel 6 and Samsung S7 tablet and the behaviour of the Net7 build is the same as above. I’m hoping you guys may have an explanation or suggestions for improving the Net7 build. If you need any build logs etc I’ll attach them here, but it seems like some type of runtime problem and I’m wondering what could be used to help track this problem.

Steps to Reproduce

N/A

Did you find any workaround?

No

Relevant log output

No response

jonathanpeppers commented 1 year ago

To find out what actually changed in .NET 7, we should profile and see what is taking time:

There are changes in .NET 7, like RegexOptions.Compiled, for example. That were faster in Xamarin because the setting didn't do anything. Now the setting actually does something and spends the time to actually compile the Regex.

Second idea

Are you using Profiled AOT in both Xamarin.Android and .NET 7? By default .NET 7 has a built-in AOT profile, that wouldn't include some parts of your application.

microsoft-github-policy-service[bot] commented 1 year ago

Hi @gmck. We have added the "need-info" label to this issue, which indicates that we have an open question for you before we can take further action. This issue will be closed automatically in 7 days if we do not hear back from you by then - please feel free to re-open it if you come back to this issue after that time.

gmck commented 1 year ago

@jonathanpeppers Wow, I just had a quick read of that doc - I think that may have changed my plans for the day!

Re your Second Idea. Below you'll find the relevant bits from both projects. I hope they are both as they should be.

X.A.

<PropertyGroup Condition=" '$(Configuration)|$(Platform)' == 'Release|AnyCPU' ">
  <DebugSymbols>true</DebugSymbols>
  <DebugType>portable</DebugType>
  <Optimize>True</Optimize>
  <OutputPath>bin\Release\</OutputPath>
  <DefineConstants>TRACE</DefineConstants>
  <ErrorReport>prompt</ErrorReport>
  <WarningLevel>2</WarningLevel>
  <JavaMaximumHeapSize>1G</JavaMaximumHeapSize>
  <AndroidManagedSymbols>true</AndroidManagedSymbols>
  <AndroidUseSharedRuntime>False</AndroidUseSharedRuntime>
  <AndroidLinkMode>Full</AndroidLinkMode>
  <EmbedAssembliesIntoApk>True</EmbedAssembliesIntoApk>
  <EnableLLVM>false</EnableLLVM>
  <AndroidEnablePreloadAssemblies>false</AndroidEnablePreloadAssemblies>
  <AndroidDexTool>d8</AndroidDexTool>
  <AndroidPackageFormat>aab</AndroidPackageFormat>
  <AndroidKeyStore>true</AndroidKeyStore>
  <AndroidSigningKeyStore>C:\glmkeystore\upload_key.keystore</AndroidSigningKeyStore>
  <AndroidSigningKeyAlias>upload_key</AndroidSigningKeyAlias>
  <AndroidSigningStorePass>file:c:\glmkeystore\KeyStorePassword.txt</AndroidSigningStorePass>
  <AndroidSigningKeyPass>file:c:\glmkeystore\KeyPassword.txt</AndroidSigningKeyPass>
  <AndroidSupportedAbis>
  </AndroidSupportedAbis>
  <AndroidUseAapt2>true</AndroidUseAapt2>
  <AndroidLinkTool>r8</AndroidLinkTool>
  <AndroidCreatePackagePerAbi>false</AndroidCreatePackagePerAbi>
  <BundleAssemblies>false</BundleAssemblies>
  <AndroidEnableProfiledAot>true</AndroidEnableProfiledAot>
  <AndroidAotAdditionalArguments>no-write-symbols,nodebug</AndroidAotAdditionalArguments>
  <AotAssemblies>false</AotAssemblies>

Net 7

<PropertyGroup>
    <TargetFramework>net7.0-android</TargetFramework>
    <SupportedOSPlatformVersion>24</SupportedOSPlatformVersion>
    <OutputType>Exe</OutputType>
    <Nullable>enable</Nullable>
    <ImplicitUsings>disable</ImplicitUsings>
    <ApplicationId>com.glmsoftware.obdnowpros</ApplicationId>
    <ApplicationVersion>1</ApplicationVersion>
    <ApplicationDisplayVersion>1.0</ApplicationDisplayVersion>
    <RootNamespace>com.glmsoftware.obdnowpros</RootNamespace>
    <RuntimeIdentifiers Condition=" '$(Configuration)' == 'Release' ">android-arm;android-arm64</RuntimeIdentifiers>
</PropertyGroup>

<PropertyGroup Condition="'$(Configuration)|$(Platform)'=='Release|AnyCPU'">
    <EmbedAssembliesIntoApk>True</EmbedAssembliesIntoApk>
    <AndroidLinkTool>r8</AndroidLinkTool>
    <PublishTrimmed>true</PublishTrimmed>

    <!--<RunAOTCompilation>false</RunAOTCompilation>
    <AndroidEnableProfiledAot>false</AndroidEnableProfiledAot>
    <PublishTrimmed>true</PublishTrimmed>
    <TrimMode>copyused</TrimMode>-->

    <AndroidKeyStore>True</AndroidKeyStore>
    <AndroidSigningKeyStore>C:\glmkeystore\upload_key.keystore</AndroidSigningKeyStore>
    <AndroidSigningKeyAlias>upload_key</AndroidSigningKeyAlias>
    <AndroidSigningKeyPass>file:c:\glmkeystore\KeyPassword.txt</AndroidSigningKeyPass>
    <AndroidSigningStorePass>file:c:\glmkeystore\KeyStorePassword.txt</AndroidSigningStorePass>

</PropertyGroup>

What I'm struggling to understand is why the apk appears to take a permanent hit, just because the code of the GoogleSignInFragment is run. It only ever runs once and then that menu option is removed. You can even reboot the device and the displayed times are forever slow, and the app is really sluggish until you redeploy the app again. I don't recall ever seeing any app act like that.

jonathanpeppers commented 1 year ago

It seems like both apps are using Profiled AOT, and nothing seems out of the ordinary.

So, I think a speedscope file is the next step. It should give us an approximation of every C# method and how long they take. Hopefully, you are able to follow that doc. Thanks!

gmck commented 1 year ago

@jonathanpeppers, @grendello

I apologise for taking so long to get back to you here. But I must have killed a chinaman in my sleep last week because everything that could go wrong with my new internet provider has gone wrong and has taken 4 days to sort out, hence no Internet.

However, before that stupid decision, I had managed to pin down the routine that is causing the delay in the Net7 version of my app after the user has used Google Sign-In. As previously mentioned in signing in, the app saves the encrypted values of the user’s email, name and userid to SharedPreferences.

Then in the OnResume of the MainActivity right at the top, there is a test for an empty email value. If it is empty as it would be before the user has signed in then it just returns. Hence the fast displayed times under that condition.

However, if the user is already signed in we have been forced to use inAppBilling’s QueryPurchaseHistoryAsync as we continue in the code of OnResume. This gives us back among other things the purchase token of the latest purchase for the user, which then allows us to call Google’s servers to first verify the purchase token using Google.Apis.AndroidPublisher.v3 and get back info as to whether the user is a beta tester or not i.e. SubscriptionPurchase.PurchaseType=0. If I remember correctly it was a blog post from you many years ago, where I picked up on the method to verify a purchaseToken.

Google’s recommendation is to use QueryPurchasesAsync which is very quick as it comes from the cache of Google Play services. There are problems with that though – you do get a purchaseToken if there is a subscription. However, if there is no active subscription, then you get nothing, so that sort of screws it for the beta tester.

Beta testers' subscriptions have a very limited life, depending on the subscription length. They get renewals at either 5 mins, 15 mins or 30 mins. When all the renewals are done, their subscription is automatically cancelled (not available via QueryPurchaseAsync) however it is still valid via the QueryPurchaseHistoryAsync route for between 40-60 days (Google don’t quote how long) but those are my results over the last couple of years. When the beta tester subscription expires the app shows a special dialog indicating that the subscription has expired and a message to carry on using the app as usual for the next approx. 40-60 days when it really does expire (you get 404 when you query it). I instruct them to then just purchase a new subscription. The period they choose has no bearing on the 40-60 day period, so I suggest the 5 mins renewals, so they can get on with testing the app as quickly as possible. Once they get the 7th email (your subscription has been cancelled) from Google they know that they can then continue using the app in the regular way for another 40-60 days etc. Some guys drop out, but most of them think that is a workable solution. I’m quite sure Google would agree, that beta testers don’t sign up to test an app’s subscription performance and the testing of subscriptions should be left entirely with the developer.

Since the QueryPurchasesAsync method won't work for beta testers we are kind of stuck with the slower QueryPurchaseHistoryAsync method followed by the VerifyGoogleSubscriptionPurchaseAsync(inAppBillingPurchaseResult) to get whether a subscriber or beta tester.

The peculiarity of using subscriptions is that you start the subscription process from a fragment. Here the user picks a subscription from a drop-down of SKUs or ProductIds as they are now known in Xamarin.Android.Google.BillingClient Version=6.0.1.1. They then click on the purchase button and you then have to establish if this user is a new user or an existing user. If an existing user, (maybe purchasing a new subscription) use the existing ObsfuscatedAccountId or generate a new one for a new user. You’ve now got all you need to start the BillingFlow via Billing’s PurchaseAsync. This is where it gets complex because when Google’s SubscriptionActivity finishes up you end up back in the app’s MainActivty’s OnResume which means you need to trap if it is a new subscription and not a renewal and then if a new subscription return to the fragment to continue the Acknowledgement of the purchase and update your server records etc. If a renewal continue on in the OnResume.

Before the loss of the internet, I was working my way through your documentation on aot and aotprofiles etc. As I’ve no experience using MSBuild and dotnew etc. I thought, why not save some time and try a full Aot build (AOT everything) within Visual Studio and compare the results with the previous results, ignoring the unavoidable extra size of apk.

<RunAOTCompilation>true</RunAOTCompilation>
<AndroidEnableProfiledAot>false</AndroidEnableProfiledAot>

After doing that test I still get the same slow down, the diff average figure now being 0.930 sec, which compares (although slower) to the previous tests where it was 0.777 sec. The performance is then still just as terrible when navigating in the app as it was in the last tests.

So my first question is was that a reasonable test to try? I thought, that may have fixed the problem, and confirmed that creating a custom aot profile would result in a fix but with an acceptable sized apk, but it would appear that it is not.

As a further comparison, I did some timing with the X.A. build on an old Pixel 4a (this is set up with my wife’s email address and credit card), so that I can test real-time subscriptions where the user is actually charged.

Obviously, the 4a device is not as performant as the Pixel 6 and Pixel 7 that the above tests were done on, but the X.A. build on the 4a only shows a difference of 0.268 sec for the same test. Cold start average time is 702.7 sec which is what you would probably expect for a device of that age. From my point of view, that difference is not noticeable and it certainly does not affect the performance of the app concerning navigating the fragments.

It therefore appears that there is something very different going on with the Net7 build as compared to the X.A. build.

After doing these tests, I’m not all that keen to start on something new with the MSBuild / DotNew/PowerShell route or whatever you want to call it, as that would be a considerable learning curve for me that I’d rather not have to undertake, considering other restraints I’m under right now.

Is there any other way of solving this problem?

If necessary I’d be willing to share the app if that would be of any assistance.

None of the Net7 test apps that are publicly available on my GitHub display poor performance they are always better than the identical X.A. versions from which they were created. I just don’t understand how one call to verify a purchase token, can have such a performance hit on the rest of the app. It's like the whole apk is affected which doesn’t make much sense.

jonathanpeppers commented 1 year ago

Regarding my comment:

So, I think a speedscope file is the next step. It should give us an approximation of every C# method and how long they take. Hopefully, you are able to follow that doc. Thanks!

Are you able to profile the app with dotnet-trace? It doesn't sound like you tried that.

This is really the best approach: understand every method at startup and how long they take.

gmck commented 1 year ago

@jonathanpeppers

I haven't got PowerShell installed, so I used the Android Adb Comand Prompt from Visual Studio 2022.

I got through the first couple of steps of the Profiling Startup doc and have included two files here. InitialRun.txt and then another after I completed the Google Sign-In. AfterGoogleSignIn.txt

They appear to show what is going on. I hope this is what you want. I cleared the log between the runs, I presume that is what you are meant to do.

Is it of any value to do the same with the XA build?

AotTestJonPeppers.zip

After I posted earlier I was having another look at the code and found a line in the OnResume of the MainActivity InAppBilling inAppBilling = new(); that didn't need to be there as it was never referenced other than at the end with inAppBilling.Disconnect(). So I've removed it. So there is a new file AfterGooleSignIn2.txt in this latest zip.

After studying these files, everything is familiar to me, except that there is no reference to the code await BillingProcess.VerifyGoogleSubscriptionPurchaseAsync(inAppBillingPurchaseResult);
It must have been executed because the HelperExplanationDialogFragment at the end of the file is the dialog that tells the beta tester that the subscription is expired. It is called right after await BillingProcess.GetPurchaseHistorysAsync(); where I get the correct purchaseHistoryRecord and its PurchaseToken.

AotTestJonPeppers1.zip

jonathanpeppers commented 1 year ago

Maybe we gave you the wrong link before?

https://github.com/xamarin/xamarin-android/blob/main/Documentation/guides/tracing.md

Should get you a .nettrace and/or .speedscope file you can open in: https://speedscope.app

This will let us see every method at startup in your .NET 7 app and how long it takes.

grendello commented 1 year ago

@gmck your description of the issue suggests that there's a network request involved, is it done using the .NET's HttpClient? If yes, then part of the slowdown might be caused by this issue.

gmck commented 1 year ago

@grendello

Yes, the network requests in the Net7 app are now all NET’s HttpClient. The X.A. build was and still is using HttpWebRequest to get the same results. That was the first thing I had to change for the net7 version as HttpWebRequest is now obsolete. All the changes I had to make are mentioned in #8211 and #8239. There is still one problem with my AES class, which seems minor and can be worked around with an #if debug, which I’ll report later.

With the completion of changes re #8239, I finally got a build that was built without warnings, a reasonable size apk and good startup performance (Displayed).

As previously demonstrated, the slowdown only occurs after the user has used GoogleSignIn and we have saved their email address. This results in both QueryPurchaseHistoryAsync (returns the PurchaseToken) of the most recent subscription and VerifyGoogleSubscriptionPurchaseAsync(inAppBillingPurchaseResult) being called in the OnResume of the MainActivity. We have to use QueryPurchaseHistoryAsync in conjunction with VerifyGoogleSubscriptionPurchaseAsync which is the only way we can determine if the user is a beta tester as GetPurchaseHistorysAsync will not do it.

I’m still trying to work my way through the documentation to get the info for the speedscope file as requested by Jonathan. If you haven’t done this type of thing it is time-consuming work as the documentation is such that it assumes you already know how to use dotnet, PowerShell etc. which obviously I don’t know.

I’ve got to the stage where I’ve done adb shell setprop debug.mono.log timing=bare and got the results. But those results don’t include any reference to VerifyGoogleSubscriptionPurchaseAsync. So that immediately gives me doubts that I’m moving in the right direction. Why isn’t VerifyGoogleSubscriptionPurchaseAsync in the output if the HelpExplanationDialogFragment (which is the special dialog shown only to beta testers on expiry) is in the output? You can’t get the dialog, without VerifyGoogleSubscriptionPurchaseAsync being run. So, what happened to it?

Just as puzzling is the fact that there is a NavigationBarView+IOnItemSelectedListenerImplementor, but no equivalent for the NavigationView OnNavigationItemSelected. The NavigationBarView is not even visible on the Start Destination Fragment. It only comes into play when a particular Fragment is navigated to via the NavigationView.

How does the Aot process decide what should be included/excluded? Has that process changed in the Net7 build as compared to the X.A. build?

I also use VerifyGoogleSubscriptionPurchaseAsync in the SubscriptionFragment. Initially, I created an additional fragment off the SubscriptionFragment so that I could view the result of VerifyGoogleSubscriptionPurchaseAsync to see the various values of the properties of a subscription so that I could study the values returned while testing all the various properties to see them change during the renewals process. I then decided that it could also be a useful window to display to a user as it presents all the info about the state of the subscription e.g. Active, Cancelled, In Grace Period, On Hold, Paused, Order Number, StartTime, Expiry Date etc. Then when Google decided that subscriptions must be cancellable from within the app, it was an ideal window to Add a menu option to cancel the subscription, so I cleaned it up and made it presentable to a user and added the code for the subscription cancellation. All they need to do is tap on the most recent subscription in the SubscriptionFragment and it opens another window with all the information. My point is that it is very obvious that the method is time-consuming as it takes a couple of seconds to return the result, hence it needs a spinning progress bar.

So, the startup time difference between the X.A and Net7 build is approx. 0.800ms worse. Jonathon suggests that it may be improved via the speedscope file method. However, my other question is how does that explain the really poor performance of the Net7 build as compared to the X.A. build when navigating between fragments etc?

To me that is the most important issue, you either have a high-performance app or you haven’t. When navigating the app OnResume is never called unless you rotate the device, so those two methods QueryPurchaseHistoryAsync and VerifyGoogleSubscriptionPurchaseAsync can’t be called and therefore can’t be responsible for the sluggishness it displays as compared to the X.A. build.

Further, when the app is connected to a scan tool and there is a connection between the vehicle’s Ecu and the app, the code in the OnResume is prevented from executing, so if the device is rotated – skips right past it.

Earlier today I did a test on a low-end device Samsung Tablet Galaxy Tab A, Android 7.1.1. The X.A. Build before and after tests of GoogleSignIn were 2.912 and 4.495 sec – on the Net7 build 2.904 and 10.388 sec – Hot start 8.389. Absolutely pathetic.

Since I’m struggling so much with getting this speedscope file to you, is there any chance you guys could write a script that I can just execute here?

gmck commented 1 year ago

@jonathanpeppers I’m following the instructions at https://github.com/xamarin/xamarin-android/blob/main/Documentation/guides/tracing.md

Unfortunately, I’m having no luck with using PowerShell after installing it and updating, I change to the project directory and enter $ adb reverse tcp:9000 tcp:9001 and get back $: The term '$' is not recognized as a name of a cmdlet. etc. So, I gave up on that and used the ADB Command Prompt from VS2022.

I completed the following successfully adb reverse tcp:9000 tcp:9001 adb shell setprop debug.mono.profile '127.0.0.1:9000,suspend'

I install - Install dotnet-dsrouter successfully.

However, I get stuck at the next bit. dotnet-dsrouter client-server -tcps 127.0.0.1:9001 -ipcc /tmp/android-app --verbose debug WARNING: dotnet-dsrouter is an experimental development tool not intended for production environments.

The following is the output info: dotnet-dsrouter[0] Starting dotnet-dsrouter using pid=25028 info: dotnet-dsrouter[0] Starting IPC client (/tmp/android-app) <--> TCP server (127.0.0.1:9001) router. dbug: dotnet-dsrouter[0] Trying to create a new router instance. dbug: dotnet-dsrouter[0] Waiting for a new TCP connection at endpoint "127.0.0.1:9001". dbug: dotnet-dsrouter[0] No runtime instance connected before timeout. dbug: dotnet-dsrouter[0] Failed creating new router instance. dbug: dotnet-dsrouter[0] Trying to create a new router instance.

Continues but fails each time.

Skipping past that I can successfully run the command below. That is very fast 8.69 seconds if the release build is up to date. I gather that is just a copy operation to the device. dotnet build -f net7.0-android -t:Run -c Release -p:AndroidEnableProfiler=true

I have experienced problems the last couple of days with Building and Deploying with VS2022. If I make any changes to the code, I find that if I just Deploy the resulting build will either crash on start-up or just hang on the splash screen if using dotnet build. If I then clean the project and build/deploy it runs okay again and so does dotnet build.

Could you please advise how to get around the problem of starting dotnet-dsrouter?

@grendello I gather from reading that thread you referred to, that we would not see any improvement until Net8 and that would probably be Android 14 by then. Will the changes be backported to Net7?

jonathanpeppers commented 1 year ago

$: The term '$' is not recognized as a name of a cmdlet. etc.

The $ is an example to represent bash, the command-prompt for Mac & Unix. You don't type the $ on Windows.

Could you please advise how to get around the problem of starting dotnet-dsrouter?

The dsrouter output above looks fine, leave it running and open another terminal window to run dotnet-trace inside.

If I make any changes to the code, I find that if I just Deploy the resulting build will either crash on start-up or just hang on the splash screen

The adb shell setprop debug.mono.profile '127.0.0.1:9000,suspend' command tells the app to pause and wait until it can connect to dotnet-dsrouter and dotnet-trace. So, if those aren't setup, the app will pause indefinitely. Android system properties will remain until you reboot the device, but you can run adb shell setprop debug.mono.profile "''" to clear it. adb shell 'getprop | grep mono' is a good way to see all the Mono system properties set.

gmck commented 1 year ago

@jonathanpeppers

The dsrouter output above looks fine, leave it running and open another terminal window to run dotnet-trace inside.

I open another terminal and execute dotnet-trace collect --diagnostic-port /tmp/android-app --format speedscope

However, the first terminal just keeps going the same as before No runtime instance connected before timeout.

I've also tried the alternate version of adb reverse tcp:0 tcp:9001 but it didn't make any difference.

Is the problem something else in the setup of my computer?

If I eventually get this working, which terminal 1 or 2, would I then run dotnet build etc.? I presuming back in terminal 1, but I thought I should check.

gmck commented 1 year ago

@jonathanpeppers Tried to do the same with PowerShell and got exactly the same result as above. Do you have any ideas why it is failing? Is it likely that it is some different about the setup of my computer?