Loading Android Apps on the debugger is way too slow

chabiss commented 1 month ago

Description

Development on Android is very slow. The time it takes to launch my app is almost a 1 min on Debug while the release version is way much faster. This used to launch much faster in .NET 7

https://github.com/user-attachments/assets/b74323e9-f916-4317-aeff-1458530693ad

Steps to Reproduce

Clone https://github.com/chabiss/periodictable
Set an Android device (pixel 7 pro).
Setup your startup project to 'PeriodictableMaui'
launch the app on the emulator

https://github.com/user-attachments/assets/e8ee00e5-ddfd-482c-9bd1-35b2f7493b3f

Link to public reproduction project repository

https://github.com/chabiss/periodictable

Version with bug

8.0.71 SR7.1

Is this a regression from previous behavior?

Yes, this used to work in .NET MAUI

Last version that worked well

7.0.49

Affected platforms

Android

Affected platform versions

No response

Did you find any workaround?

You have better performance on 'release' build, but then you loose XAML Hot Reload

Relevant log output

Loaded assembly: /data/data/com.companyname.periodictablemaui/files/.__override__/System.Runtime.Intrinsics.dll [External]
[riodictablemaui] Explicit concurrent copying GC freed 933(127KB) AllocSpace objects, 31(4092KB) LOS objects, 49% free, 4423KB/8846KB, paused 1.328ms,169us total 33.513ms
[riodictablemaui] Explicit concurrent copying GC freed 722(46KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 4581KB/9162KB, paused 1.856ms,170us total 14.835ms
[riodictablemaui] Explicit concurrent copying GC freed 641(43KB) AllocSpace objects, 1(108KB) LOS objects, 49% free, 4525KB/9050KB, paused 1.420ms,176us total 14.112ms
[riodictablemaui] Explicit concurrent copying GC freed 619(41KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 4579KB/9158KB, paused 1.263ms,173us total 13.825ms
[riodictablemaui] Explicit concurrent copying GC freed 483(29KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 4630KB/9260KB, paused 1.379ms,171us total 14.170ms
[riodictablemaui] Explicit concurrent copying GC freed 474(29KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 4681KB/9362KB, paused 1.628ms,167us total 19.871ms
[riodictablemaui] Explicit concurrent copying GC freed 629(43KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 4749KB/9499KB, paused 1.682ms,170us total 21.461ms
[riodictablemaui] Explicit concurrent copying GC freed 475(33KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 4812KB/9624KB, paused 1.269ms,171us total 21.170ms
[riodictablemaui] Explicit concurrent copying GC freed 474(32KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 4875KB/9751KB, paused 1.300ms,194us total 20.876ms
[riodictablemaui] Explicit concurrent copying GC freed 474(30KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 4941KB/9882KB, paused 1.293ms,174us total 21.206ms
[riodictablemaui] Explicit concurrent copying GC freed 474(30KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 5006KB/10012KB, paused 1.278ms,170us total 21.814ms
[riodictablemaui] Explicit concurrent copying GC freed 475(29KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 5072KB/10145KB, paused 1.289ms,198us total 22.289ms
[riodictablemaui] Explicit concurrent copying GC freed 321(34KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 5134KB/10MB, paused 1.352ms,167us total 19.788ms
[riodictablemaui] Explicit concurrent copying GC freed 474(36KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 5209KB/10MB, paused 1.273ms,169us total 21.329ms
[riodictablemaui] Explicit concurrent copying GC freed 474(37KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 5284KB/10MB, paused 1.327ms,170us total 23.871ms
[riodictablemaui] Explicit concurrent copying GC freed 321(32KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 5347KB/10MB, paused 1.832ms,167us total 19.635ms
[riodictablemaui] Explicit concurrent copying GC freed 475(42KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 5432KB/10MB, paused 1.858ms,760us total 21.920ms
[riodictablemaui] Explicit concurrent copying GC freed 321(32KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 5496KB/10MB, paused 1.454ms,175us total 21.326ms
[riodictablemaui] Explicit concurrent copying GC freed 476(40KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 5584KB/10MB, paused 1.294ms,173us total 24.449ms
[riodictablemaui] Explicit concurrent copying GC freed 321(28KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 5651KB/11MB, paused 1.883ms,179us total 21.251ms
[riodictablemaui] Explicit concurrent copying GC freed 474(29KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 5734KB/11MB, paused 1.275ms,168us total 22.013ms
[riodictablemaui] Explicit concurrent copying GC freed 322(29KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 5816KB/11MB, paused 1.284ms,383us total 23.138ms
[riodictablemaui] Explicit concurrent copying GC freed 321(27KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 5885KB/11MB, paused 1.296ms,170us total 20.730ms
[riodictablemaui] Explicit concurrent copying GC freed 321(33KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 5963KB/11MB, paused 2.364ms,248us total 31.878ms
[riodictablemaui] Explicit concurrent copying GC freed 474(42KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 6049KB/11MB, paused 1.753ms,176us total 18.018ms
[riodictablemaui] Explicit concurrent copying GC freed 321(28KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 6133KB/11MB, paused 1.309ms,169us total 17.798ms
[riodictablemaui] Explicit concurrent copying GC freed 322(31KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 6213KB/12MB, paused 1.278ms,171us total 16.862ms
[riodictablemaui] Explicit concurrent copying GC freed 321(35KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 6290KB/12MB, paused 1.838ms,168us total 17.552ms
[riodictablemaui] Explicit concurrent copying GC freed 321(33KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 6368KB/12MB, paused 1.296ms,169us total 17.325ms
[riodictablemaui] Explicit concurrent copying GC freed 321(31KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 6448KB/12MB, paused 1.852ms,173us total 18.263ms
[riodictablemaui] Explicit concurrent copying GC freed 321(28KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 6532KB/12MB, paused 1.932ms,173us total 17.990ms
[riodictablemaui] Explicit concurrent copying GC freed 168(30KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 6550KB/12MB, paused 1.465ms,173us total 20.518ms
[riodictablemaui] Explicit concurrent copying GC freed 14(32KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 6550KB/12MB, paused 1.762ms,168us total 16.929ms
[riodictablemaui] Explicit concurrent copying GC freed 319(28KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 6633KB/12MB, paused 1.310ms,173us total 17.733ms
[riodictablemaui] Explicit concurrent copying GC freed 322(27KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 6718KB/13MB, paused 1.279ms,171us total 17.699ms
[riodictablemaui] Explicit concurrent copying GC freed 321(25KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 6804KB/13MB, paused 1.711ms,177us total 18.758ms
[riodictablemaui] Explicit concurrent copying GC freed 170(34KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 6882KB/13MB, paused 1.303ms,175us total 19.332ms
[riodictablemaui] Explicit concurrent copying GC freed 319(28KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 6965KB/13MB, paused 1.270ms,177us total 17.923ms
[riodictablemaui] Explicit concurrent copying GC freed 321(28KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 7049KB/13MB, paused 1.263ms,173us total 18.197ms
[riodictablemaui] Explicit concurrent copying GC freed 321(36KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 7141KB/13MB, paused 1.311ms,170us total 19.532ms
[riodictablemaui] Explicit concurrent copying GC freed 322(34KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 7235KB/14MB, paused 1.330ms,172us total 19.411ms
[riodictablemaui] Explicit concurrent copying GC freed 321(25KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 7321KB/14MB, paused 1.315ms,170us total 19.345ms
[riodictablemaui] Explicit concurrent copying GC freed 321(28KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 7405KB/14MB, paused 1.365ms,174us total 20.579ms
[riodictablemaui] Explicit concurrent copying GC freed 168(29KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 7488KB/14MB, paused 1.293ms,196us total 20.132ms
[riodictablemaui] Explicit concurrent copying GC freed 321(26KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 7574KB/14MB, paused 1.300ms,203us total 20.445ms
[riodictablemaui] Explicit concurrent copying GC freed 321(27KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 7674KB/14MB, paused 1.296ms,258us total 20.827ms
[riodictablemaui] Explicit concurrent copying GC freed 321(26KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 7760KB/15MB, paused 1.663ms,181us total 20.823ms
[riodictablemaui] Explicit concurrent copying GC freed 318(36KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 7851KB/15MB, paused 1.353ms,174us total 20.903ms
[riodictablemaui] Explicit concurrent copying GC freed 172(32KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 7931KB/15MB, paused 1.289ms,174us total 20.590ms
[riodictablemaui] Explicit concurrent copying GC freed 321(27KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 8031KB/15MB, paused 1.277ms,172us total 20.028ms
[riodictablemaui] Explicit concurrent copying GC freed 321(28KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 8115KB/15MB, paused 1.271ms,199us total 21.029ms
[riodictablemaui] Explicit concurrent copying GC freed 168(29KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 8198KB/16MB, paused 1.383ms,175us total 23.660ms
[riodictablemaui] Checksum mismatch for dex base.apk
[riodictablemaui] Could not add methods to the existing profiler. Clearing the profile data.
[riodictablemaui] Explicit concurrent copying GC freed 323(34KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 8307KB/16MB, paused 1.255ms,174us total 21.011ms
[Choreographer] Skipped 2011 frames!  The application may be doing too much work on its main thread.

github-actions[bot] commented 1 month ago

Hi I'm an AI powered bot that finds similar issues based off the issue title.

Please view the issues below to see if they solve your problem, and if the issue describes your problem please consider closing this one and thumbs upping the other issue to help us prioritize it. Thank you!

Open similar issues:

[BUG] .NET MAUI 9.0 Preview 2 Android debugger hangs up often when using UseInterpreter = false (#21536), similarity score: 0.80

Closed similar issues:

App doesn't load on Android (#12373), similarity score: 0.82
[Bug]: Android release crash, debug work as normal (#14653), similarity score: 0.79
Runs in Windows Emulator, Throws System.NullReferenceException error in Android Emulator. Don't know where to start. (#10249), similarity score: 0.79
Cannot debug on iOS as Loaded Assembly xxxxx phase takes too long. (#14822), similarity score: 0.78

Note: You can give me feedback by thumbs upping or thumbs downing this comment.

kevinxufei commented 1 month ago

I can repro this issue at Android platform on the latest 17.11.0 Preview 6.0( 8.0.71). And it works well on .NE7, that's almost a quarter of the time it takes net8.

jonathanpeppers commented 1 month ago

@chabiss if you close XAML Live Preview, does it improve?

I will profile this, but since there are many lines of:

[riodictablemaui] Explicit concurrent copying GC freed 619(41KB) AllocSpace objects, 0(0B) LOS objects, 49% free, 4579KB/9158KB, paused 1.263ms,173us total 13.825ms

That's not exactly normal.

I suspect I'm going to find some heavy byte[] / string / or Image? passing around. I should be able to see the stack trace of who is doing it in dotnet-trace.

jonathanpeppers commented 1 month ago

Ok, I don't think the slowness related to XAML Live Preview, but I'm still profiling.

@chabiss one change to make it a bit better:

https://github.com/chabiss/periodictable/compare/main...jonathanpeppers:periodictable:OnPropertyChanged

Before it was firing INotifyCollectionChanged events for each element in the period table. We can populate the list and refresh once instead.

jonathanpeppers commented 1 month ago

@chabiss there is unfortunately, not an allocation tracker for dotnet-trace, so I've resorted to just taking dotnet-gcdump snapshots and looking at a point in time.

I think there are two large contributors to allocations in Debug mode: