MAUI .NET 8.0 built with Full AOT Compilation reports a lot of Mono : AOT NOT FOUND
#101135
Comments
|
It's also not clear whether should AOT compiler for Android process generic types and methods when $(AndroidEnableProfiledAot)==false |
dotnet-policy-service
bot
added
the
untriaged
|
I think this is a known issue, some info at the bottom of: There are these tiny methods that are always JIT no matter what: But I don't think these are "actual methods", but tiny wrappers that enable generics or p/invoke. There is some JIT happening there currently on Android, which might be because we use MONO_AOT_MODE=Normal and allow JIT. I believe iOS/Catalyst would use MONO_AOT_MODE=Full, because those platforms require it. |
|
@crui3er just for my understanding, is there a crash that happens with the application or the question is just about unexpected log messages? Regarding full AOT compilation on Android, afaik you would have to set |
|
@ivanpovazan Not, there is no crash, but there are unexpected log messages. In my maui app I working on there are a lot of log messages with AOT NOT FOUND. Even with using recorded aot profile there are jitted methods are which are in recorded profile. So I am trying to figure out what is going wrong with this small sample app. |
Could you share more information on that: like the aot profile that you are using and which methods you would not expect to see in the log? |
|
I don’t think Full will work on Android, does that mode prevent JIT? |
|
Full AOT is what iOS uses, which does not JIT anything, since that's a requirement for iOS. |
|
I tested with |
I recorded custom aot profile https://github.com/crui3er/MauiAotTest/blob/master/custom.aprof and do test with it. Then I compared Here is a few examples of aot not found records in the log for methods mentioned in profile. stat: log: stat: log: stat: log: Here is Sample app is updated. Now it uses recorded aot profile. |
|
@crui3er Thanks for providing more information about this. I will take a look at this. |
ivanpovazan
removed
the
untriaged
|
Hi there, just curious, are there any updates on that? I want to add some context: the app we're working on shows ~20K methods in "AOT NOT FOUND" log entries - and that's just for the startup time. We were questioning whether AOT is even working at all - well, it does, coz there are also lots of "AOT FOUND" entries, but it's reasonable to assume that if you have even 50/50 split between these, you're probably getting just 50% of max. possible savings on JIT. And with AOT turned off, our startup time is almost 2x higher. In other words, if AOT issues would be fixed, our app's startup time would go from ~ 1.7s to probably just 0.3-0.5s or so, which is obviously a dramatic change. Please let @crui3er know if you need anything else. We can provide logs from the actual app + give you instructions on how to reproduce the issue there, if a small sample won't be enough to identify the root cause(s). And IMO it's super important to address this: compared to Native AOT, profile-based AOT (assuming it 100% works) is what most of mobile apps need. It allows to balance between the app size and the speed of the most crucial parts of the app, which is almost always the startup time for mobile apps. So nearly any MAUI and Blazor Hybrid app would benefit from this heavily. |
|
Also, should we change the title of this issue? It's not about just full AOT, it's about both full and profiled AOT. And it's understandable why full AOT may miss or intentionally omit some methods (the # of possible generic instances explodes exponentially with the codebase size), but profiled AOT is expected to produce AOT code at least for every method from the AOT profile. |
|
I was able to build and run the app provided here. When setting I also noticed that this profile was gathered using the legacy profiler. Next, I will try the new profiler to see if this issue still exists. If so, I will investigate further. |
What is a new profiler and how to use it? |
|
Actually, the new profiler is not fully supported on Android yet. The profiler I was talking about is this: https://github.com/dotnet/runtime/blob/main/docs/design/mono/profiled-aot.md |
I think @jonathanpeppers did experimental support https://github.com/jonathanpeppers/xamarin-android/blob/dotnet-pgo/src/Xamarin.Android.Build.Tasks/Microsoft.Android.Sdk/targets/Microsoft.Android.Sdk.Aot.targets but it's not included in .NET8, is it? |
@fanyang-mono Why do you think that methods in example 1 are not the same? |
|
@fanyang-mono funny enough, we were trying to use it as well - not sure what's the state of .mibc format in the long run, but it seems currently it's not supported by release version of .NET 8, but you can see here we were trying both .aprof and .mibc formats here: https://github.com/Actual-Chat/actual-chat/blob/dev/src/dotnet/App.Maui/App.Maui.csproj#L265 Collecting .mibc isn't an issue - as well as merging these profiles. But it looks like Android build targets just don't use We created this issue because there are so many "AOT_NOT_FOUND" for regular .aprof output that it works much worse than full AOT for us (which still produces tons of "AOT_NOT_FOUND", but this is at least explainable). The fact profiled AOT doesn't really work is a huge issue affecting every MAUI Android app, and an existential issue for apps like ours, where the startup time is crucial. I wrote earlier that fully working profiled AOT is expected to drop our startup time to 0.5...1s on Android - vs current 2s. In other words, it's as different as night and day. Just to illustrate how bad this is:
And unrelated, but: we spent a decent amount of time trying to enable AOT for iOS at least for some assemblies, but this inevitably leads to crashes. That's why for now the app works in interpreter mode there. |
|
Another illustration of how bad this is. Below is a screenshot from DotTrace showing where most of the time is spent in release build with full AOT - as I said, due to the issue listed here it's our best option for now. The timeline is constrained by [0..1.2s] interval. The original .nettrace was recorded via:
As you see, JIT takes almost 74% of time there. So if profiled AOT would work, it could be just 0.3s or so. |
|
There is a PR adding However, I don't think using Regarding:
Are you able to share a You could also record your own AOT profile, if the file size of "full AOT" (AOT everything) is too large. This would just be a tradeoff where it wouldn't AOT everything, but just the methods called during your recording. |
One is a non-generic method -> The second one has a type argument and needs to be compiled differently than the first one. However, I just check the method It seems that |
|
@alexyakunin @crui3er Could you compare the profile text files that you got from both methods to see if they are the same? I am curious about that. They might be the same. |
|
I investigated the situation more and found out that didn't pass the checks inside And the new profiler alos use |
|
I have no idea about any of the Mono stuff here, but let me just comment on the overall architectural picture: If you are using generics and generic specialization, you are not improving performance, you are making a performance tradeoff. This is true for all programming language implementations. There is no way to share code with a different calling convention without introducing some performance cost. .NET users have been incorrectly obsessing over microbenchmarks for years to eek out a win in a single function call and neglected the tradeoffs in this space. Generic specialization of value types offers the highest possible throughput for those code paths, at the expense of generating more code. For JIT runtimes this means more time JITing, more memory used for JITed code, and potentially more icache misses due to lower code density. For AOT runtimes this means vastly more generated code, larger binary sizes, longer compile times, and potentially more icache misses. The code size penalty is even larger for AOT because it can't use runtime conditions to predict whether or not a specialization is actually used at runtime, and therefore it must generate all potential ones. This is particularly bad for generic virtual methods or generic interface methods, where both the implementation and substitution are unknown and the size of the generated code grows quadratically. It's not impossible for an AOT app using GVMs to have the GVM specialization code be a substantial portion of the entire app. When using AOT with generics you need to strongly consider whether it's better to simply allocate a class or boxed interface rather than using specialization. You may gain a few microseconds due to specialized code, but lose on all other metrics.
Separately, this should only ever happen if you're using reflection, like If it is giving you a warning and your code is failing, you need to fix your code. AOT has some fundamental incompatibilities with reflection. Some of them are hard incompatibilities, like We may still implement USG for Native AOT in the future, but it will come with a different set of tradeoffs and be unusable by a different set of customers. |
|
@agocke ,
And I don't get why you guys find this acceptable. IMHO it's deeply wrong to break a bunch of features instead of making them work in some way, even if it's much slower. You can explain the slowness - and moreover, we can address the slowness, because typically all we need here is to profile & optimize the hot path. But when you break literally everything, we have to change each and every broken thing. E.g. I would be fine with either universal generics or interpreter - whatever, just don't JIT it. Based on what we see w/ interpreter on iOS, this would still allow us to shave off 50% of startup time. But somehow JIT + broken AOT is all we have, and you're trying to convince us it's fine. Moreover, AOT breaks specifically what helps JITted apps to run faster. And you can't know what's broken unless you run it.
Am I the author of any of these methods? Am I the one who concluded it makes sense to call And if Microsoft can't author AOT-friendly code, why it expects others can easily jump through all the hoops to author it? Doesn't this indicate that whoever makes the decisions on how AOT is supposed to work made a bunch of wrong calls in this specific case (i.e. generic handling?) Long story short, I don't see why it makes sense to look for excuses here, when the first step in solving a problem is at least recognizing it. |
I don't understand why banning devs from using what's quite convenient is viewed as an acceptable trade-off here. The way I would approach this is: if reflection is a mistake, we should try removing it from .NET. And if it's a genuinely useful thing (that's what 90+% of developers will tell you), we should stop pretending it's ok to break it in AOT builds only. |
|
P.S. The conversation is getting a bit heated... Can we try to refocus it on how to solve this specific issue / why it's complex? I'd love to know why these specific constraints exist, and what specifically prevents Microsoft from making them much less restrictive. This comment also worth reading: #106748 (comment) and a few more following it. A brief summary: if this fix is complex, and it's needed only for Android, how it's possible that the very same Mono AOT generates the code for all generic instances for iOS? |
|
Hi, are there any updates on that? |
To be brutally honest, this will only quick change if and when Google ban VM from running on it's platform. Just look at Apple, you either comply or take your game elsewhere. |
Well, if they'd be out of any choice - of course. I don't see why banning runtime codegen makes sense though (e.g. for Apple). And if I'd be working on JIT for Android / similar platforms, I'd certainly implement it as JIT w/ file system cache. Maybe I miss something, but it seems obviously faster to link previously compiled method code vs generating it each and every time. |
|
Any update Microsoft, this is a rather big issue, apps take many many seconds to load on Android. |
|
For MS folks: I'll be bumping up this topic on Reddit until we get a meaningful fix - for the sake of clarity, the bug was reported in April, so any patience has its limits. And this topic is an amazing example of how to turn one of your advocates into, well, at least someone who's mad at you. How it's possible to make every single step wrong?
|
|
A few updates - after some investigations today:
My attempt to use Beside that, I noticed that |
|
Okey, MS folks, you won.
As you might guess, such a pleasant experience worth sharing. |
|
Oh, and FYI, .NET 9 RC2 build for Android starts even slower than .NET 8 build. But negative correlation is still a correlation, so you can cross "[x] Listen to your customers" checkbox. |
|
@alexyakunin would you be interested in a CoreCLR/NativeAOT-based "launcher" for Blazor? We have a prototype of an Android backend for Avalonia that could be repurposed to host a WebView. You can see the difference of running the same Avalonia-based app using CoreCLR+NativeAOT, |
I'd say this is #1 thing Microsoft should be working on now; and if it's not them, probably, it's even better (this thread is one of proofs why). I don't care if it's MAUI or not, what we need is Blazor WebView running on iOS, Android, and non-mobile OSes. So if you need some testers of any preview tech, please reach me out. We'd be happy to contribute as well. And yeah, I saw that demo + one other (w/ Avalonia controls). Yes, we need something similar in terms of startup time. |
|
I have an experiment here that shows how to use It has comparisons of app size and startup time with MAUI+Blazor. I did have to bring in some of the If you are wanting the absolute fastest To be honest, if you are looking for speed, maybe native controls are the way to go instead of web content? |
You probably know this is one of the most frequent feature requests related to Blazor: "Give us a cross-platform Blazor, but ditch MAUI!".
I mentioned it many times here:
Now, speaking of switching to a lower-level APIs, such as native controls:
|
Just checked it out - overall, getting rid of MAUI is step in the right direction. But this specific solution won't change anything in our case - we don't use most of MAUI, and we know it doesn't add much to the startup time (okey, there is some control registration code that eats up maybe 0.1s, but it's nothing compared to the rest). As I wrote, the problem is that AOT mostly doesn't work on MAUI (ok, Xamarin for iOS and Android), and switching to "MAUI-less Blazor" (which still runs on top of Xamarin/Mono AOT) won't change this. Any async method and nearly any method parameterized with value type will still require JIT. |
This also won't change anything. @jonathanpeppers could you please read what's the root cause here? Not sure how you guys make decisions on priority, but the fact you suggest such "solutions" tells me you misunderstand the root cause. A quick summary:
Think of structs like
Overall, we see that in our case this triggers thousands of "AOT not found" in Mono debug log. I'll add a few screenshots showing how bad it is tomorrow. |
|
Okey, here are the screenshots - and you can easily reproduce all of that:
Here is what you'll see in the log right after the app renders (i.e. first 2-3 seconds): 15K "AOT NOT FOUND" entries: It's easy to notice all these methods are generics; some are likely just full AOT "misses", but e.g.
I.e. think about this:
Overall, ~30% of methods in this log contain And that's an impact of one of widely used generic structs in our case: -- Finally, it worth showing that AOT was actually used: The only problem is that it processed ~8K methods, and couldn't generate AOT code for another 15K. That's why I am repeating here that AOT on .NET for Android is a fiction, and only brave guys from Microsoft somehow call it a feature. |
|
@alexyakunin to be clear, just because you see an You can get a JIT timing report from Mono: Then we have a
I don't work on the Mono runtime, so I can't comment on their priorities. I am a C/C++ n00b at best, so I doubt I would be able to make a meaningful contribution to this issue. I was just trying my best to give you some options, thanks. |
|
@jonathanpeppers I'll try to get the timings as you suggested ASAP. |
|
Here is the output: jit-time-output.txt The head: Total (ms) | Self (ms) | Method
41.81 | 41.81 | System.Runtime.CompilerServices.AsyncMethodBuilderCore:Start<Microsoft.Maui.Dispatching.DispatcherExtensions/<>c__DisplayClass2_0`1/<<DispatchAsync>b__0>d<ActualChat.Language>> (Microsoft.Maui.Dispatching.DispatcherExtensions/<>c__DisplayClass2_0`1/<<DispatchAsync>b__0>d<ActualChat.Language>&)
24.22 | 24.22 | System.Collections.Frozen.FrozenDictionary:CreateFromDictionary<ActualChat.Users.ListeningMode, ActualChat.Users.ListeningModeInfo> (System.Collections.Generic.Dictionary`2<ActualChat.Users.ListeningMode, ActualChat.Users.ListeningModeInfo>)
19.48 | 19.48 | System.Runtime.CompilerServices.DefaultInterpolatedStringHandler:AppendFormatted<double> (double,string)
17.14 | 17.11 | ActualLab.Fusion.ComputedExt/<Changes>d__27`1<ActualLab.Api.ApiArray`1<ActualChat.UI.Blazor.App.Services.ActiveChat>>:MoveNext ()
17.59 | 16.29 | System.Number:NumberToStringFormat<char> (System.Collections.Generic.ValueListBuilder`1<char>&,System.Number/NumberBuffer&,System.ReadOnlySpan`1<char>,System.Globalization.NumberFormatInfo)
14.79 | 14.79 | System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1<System.ValueTuple`2<ActualLab.Result`1<ActualChat.Users.AccountFull>, ActualLab.Fusion.Client.Internal.RpcOutboundComputeCall`1<ActualChat.Users.AccountFull>>>:AwaitUnsafeOnCompleted<System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1/ConfiguredTaskAwaiter<ActualChat.Users.AccountFull>> (System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1/ConfiguredTaskAwaiter<ActualChat.Users.AccountFull>&,System.Runtime.CompilerServices.IAsyncStateMachineBox)
14.69 | 14.69 | ActualLab.Fusion.StateBoundComputed`1<bool>:.ctor (ActualLab.Fusion.ComputedOptions,ActualLab.Fusion.State`1<bool>)
14.22 | 14.22 | System.Collections.Concurrent.ConcurrentDictionary`2<long, ActualLab.Rpc.Infrastructure.RpcOutboundCall>:GetValues ()
13.17 | 13.17 | ActualLab.Fusion.Interception.ComputeMethodFunction`1/<Compute>d__8<System.ValueTuple`2<ActualChat.ChatId, bool>>:MoveNext ()
11.91 | 11.91 | Microsoft.AspNetCore.Components.WebView.Maui.MauiDispatcher:InvokeAsync<ActualChat.LocalUrl> (System.Func`1<System.Threading.Tasks.Task`1<ActualChat.LocalUrl>>)
11.68 | 11.68 | System.Runtime.CompilerServices.AsyncTaskMethodBuilder:AwaitUnsafeOnCompleted<System.Runtime.CompilerServices.ConfiguredTaskAwaitable/ConfiguredTaskAwaiter, ActualChat.Kvas.SyncedState`1/<ReadCycle>d__35<ActualChat.Users.UserOnboardingSettings>> (System.Runtime.CompilerServices.ConfiguredTaskAwaitable/ConfiguredTaskAwaiter&,ActualChat.Kvas.SyncedState`1/<ReadCycle>d__35<ActualChat.Users.UserOnboardingSettings>&)
10.86 | 10.74 | System.Net.Sockets.SocketAsyncEventArgs:StartOperationCommon (System.Net.Sockets.Socket,System.Net.Sockets.SocketAsyncOperation)
10.46 | 10.46 | System.Collections.Concurrent.ConcurrentDictionary`2<System.Reflection.MethodInfo, System.Func`2<ActualLab.Interception.Invocation, object>>:GetOrAdd<ActualLab.Interception.Invocation> (System.Reflection.MethodInfo,System.Func`3<System.Reflection.MethodInfo, ActualLab.Interception.Invocation, System.Func`2<ActualLab.Interception.Invocation, object>>,ActualLab.Interception.Invocation)
10.30 | 10.30 | System.Net.Sockets.SafeSocketHandle:.ctor ()
12.40 | 10.12 | System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1/AsyncStateMachineBox`1<ActualLab.Fusion.StateBoundComputed`1<ActualChat.UI.Blazor.App.Services.ReadPosition>, ActualLab.Fusion.State`1/<GetComputed>d__90<ActualChat.UI.Blazor.App.Services.ReadPosition>>:.cctor ()
9.70 | 9.62 | System.Linq.Enumerable:ToList<ActualChat.UI.Blazor.App.Services.ActiveChat> (System.Collections.Generic.IEnumerable`1<ActualChat.UI.Blazor.App.Services.ActiveChat>)
9.68 | 9.61 | ActualLab.Fusion.Interception.ComputeMethodFunction`1/<Compute>d__8<System.ValueTuple`2<System.Nullable`1<ActualChat.UI.Blazor.App.Services.RelatedChatEntry>, ActualChat.Chat.ChatEntry>>:MoveNext ()
9.04 | 9.04 | System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1/AsyncStateMachineBox`1<System.Threading.Tasks.VoidTaskResult, ActualChat.UI.Blazor.App.Services.ChatAudioUI/<PushRealtimePlaybackState>d__63>:MoveNext (System.Threading.Thread)
8.81 | 8.81 | System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1<System.Threading.Tasks.VoidTaskResult>:GetStateMachineBox<ActualLab.Fusion.ComputedState`1/<UpdateCycle>d__28<ActualChat.Users.UserLanguageSettings>> (ActualLab.Fusion.ComputedState`1/<UpdateCycle>d__28<ActualChat.Users.UserLanguageSettings>&,System.Threading.Tasks.Task`1<System.Threading.Tasks.VoidTaskResult>&)
8.58 | 8.58 | System.Number:FormatDouble<char> (System.Collections.Generic.ValueListBuilder`1<char>&,double,System.ReadOnlySpan`1<char>,System.Globalization.NumberFormatInfo)
8.84 | 8.26 | System.Collections.Immutable.ImmutableHashSet:ToImmutableHashSet<ActualChat.ChatId> (System.Collections.Generic.IEnumerable`1<ActualChat.ChatId>,System.Collections.Generic.IEqualityComparer`1<ActualChat.ChatId>)
8.01 | 8.01 | System.Buffers.SearchValues:TryGetSingleRange<char> (System.ReadOnlySpan`1<char>,char&,char&)
7.41 | 7.41 | System.Net.Sockets.SocketAsyncEngine:EventLoop ()
8.05 | 7.35 | ActualLab.Fusion.ComputeFunctionBase`1/<TryRecompute>d__17<int>:MoveNext ()
7.09 | 7.09 | ActualLab.Fusion.Interception.ComputeMethodFunction`1/<Compute>d__8<ActualChat.UI.Blazor.App.Services.ChatAudioUI/RecordingBeepState>:MoveNext ()
24.17 | 6.51 | ActualLab.Fusion.ComputeFunctionBase`1/<TryRecompute>d__17<ActualChat.UI.Blazor.App.Services.ChatAudioUI/RecordingBeepState>:MoveNext ()
6.35 | 6.35 | System.Collections.Concurrent.ConcurrentDictionary`2<System.ValueTuple`2<System.Reflection.MethodInfo, System.Type>, System.Func`2<ActualLab.Interception.MethodDef, object>>:TryAddInternal (System.Collections.Concurrent.ConcurrentDictionary`2/Tables<System.ValueTuple`2<System.Reflection.MethodInfo, System.Type>, System.Func`2<ActualLab.Interception.MethodDef, object>>,System.ValueTuple`2<System.Reflection.MethodInfo, System.Type>,System.Nullable`1<int>,System.Func`2<ActualLab.Interception.MethodDef, object>,bool,bool,System.Func`2<ActualLab.Interception.MethodDef, object>&)
5.99 | 5.99 | ActualLab.Fusion.Computed`1/<Update>d__35<ActualChat.ChatEntryId>:MoveNext ()
5.87 | 5.87 | ActualLab.Api.ApiArray`1<ActualLab.Text.Symbol>:MemoryPack.IMemoryPackable<ActualLab.Api.ApiArray<T>>.Serialize<MemoryPack.Internal.ReusableLinkedArrayBufferWriter> (MemoryPack.MemoryPackWriter`1<MemoryPack.Internal.ReusableLinkedArrayBufferWriter>&,ActualLab.Api.ApiArray`1<ActualLab.Text.Symbol>&)
5.82 | 5.82 | ActualLab.Fusion.Client.Interception.RemoteComputeMethodFunction`1/<Compute>d__15<ActualChat.Chat.ChatNews>:MoveNext ()
7.00 | 5.81 | ActualLab.Fusion.Interception.ComputeMethodFunction`1/<Compute>d__8<int>:MoveNext ()
7.82 | 5.79 | ActualLab.Fusion.Interception.ComputeMethodFunction`1/<Compute>d__8<ActualChat.ChatId>:MoveNext ()
6.89 | 5.64 | System.Text.Ascii:EqualsIgnoreCase<byte, uint16, System.Text.Ascii/WideningLoader> (byte&,uint16&,uintptr)
5.29 | 5.29 | ActualLab.Fusion.Client.Interception.RemoteComputeMethodFunction`1/<ComputeRpc>d__16<ActualChat.Users.Presence>:MoveNext ()
5.25 | 5.25 | ActualLab.Fusion.ComputeFunctionBase`1/<TryRecompute>d__17<ActualChat.UI.Blazor.App.Services.ChatAudioUI/RecordingState>:MoveNext ()
5.19 | 5.19 | ActualLab.Fusion.ComputedState`1/<UpdateCycle>d__28<ActualChat.Mathematics.Trimmed`1<int>>:MoveNext ()
5.12 | 5.12 | ActualLab.Fusion.ComputedExt/<Changes>d__27`1<ActualChat.ChatEntryId>:MoveNext ()
5.06 | 5.06 | ActualLab.Fusion.Client.Interception.RemoteComputeMethodFunction`1/<ApplyRpcUpdate>d__18<ActualLab.Mathematics.Range`1<long>>:MoveNext ()
7.58 | 5.00 | System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1<ActualChat.Users.UserAppSettings>:AwaitUnsafeOnCompleted<System.Runtime.CompilerServices.ConfiguredValueTaskAwaitable`1/ConfiguredValueTaskAwaiter<ActualLab.Option`1<ActualChat.Users.UserAppSettings>>> (System.Runtime.CompilerServices.ConfiguredValueTaskAwaitable`1/ConfiguredValueTaskAwaiter<ActualLab.Option`1<ActualChat.Users.UserAppSettings>>&,System.Runtime.CompilerServices.IAsyncStateMachineBox)
4.89 | 4.89 | ActualLab.Fusion.ComputeFunctionBase`1/<TryRecompute>d__17<System.ValueTuple`2<System.Nullable`1<ActualChat.UI.Blazor.App.Services.RelatedChatEntry>, ActualChat.Chat.ChatEntry>>:MoveNext ()
4.76 | 4.76 | ActualLab.Fusion.ComputedExt/<Changes>d__27`1<ActualChat.ChatId>:MoveNext ()
4.68 | 4.68 | ActualLab.Fusion.Client.Interception.RemoteComputeMethodFunction`1/<ApplyRpcUpdate>d__18<ActualChat.Chat.ChatNews>:MoveNext ()
4.65 | 4.65 | System.Text.Json.Serialization.Converters.ObjectWithParameterizedConstructorConverter`1<ActualLab.Mathematics.Range`1<string>>:OnTryRead (System.Text.Json.Utf8JsonReader&,System.Type,System.Text.Json.JsonSerializerOptions,System.Text.Json.ReadStack&,ActualLab.Mathematics.Range`1<string>&)
4.63 | 4.63 | System.Collections.Concurrent.ConcurrentDictionary`2<ActualLab.Rpc.Infrastructure.RpcCallTypeKey, System.Func`2<ActualLab.Rpc.Infrastructure.RpcOutboundContext, ActualLab.Rpc.Infrastructure.RpcOutboundCall>>:TryAddInternal (System.Collections.Concurrent.ConcurrentDictionary`2/Tables<ActualLab.Rpc.Infrastructure.RpcCallTypeKey, System.Func`2<ActualLab.Rpc.Infrastructure.RpcOutboundContext, ActualLab.Rpc.Infrastructure.RpcOutboundCall>>,ActualLab.Rpc.Infrastructure.RpcCallTypeKey,System.Nullable`1<int>,System.Func`2<ActualLab.Rpc.Infrastructure.RpcOutboundContext, ActualLab.Rpc.Infrastructure.RpcOutboundCall>,bool,bool,System.Func`2<ActualLab.Rpc.Infrastructure.RpcOutboundContext, ActualLab.Rpc.Infrastructure.RpcOutboundCall>&)
4.45 | 4.45 | System.Collections.Concurrent.ConcurrentDictionary`2<System.ValueTuple`2<System.Reflection.MethodInfo, System.Type>, System.Func`2<ActualLab.Interception.MethodDef, object>>:TryGetValueInternal (System.Collections.Concurrent.ConcurrentDictionary`2/Tables<System.ValueTuple`2<System.Reflection.MethodInfo, System.Type>, System.Func`2<ActualLab.Interception.MethodDef, object>>,System.ValueTuple`2<System.Reflection.MethodInfo, System.Type>,int,System.Func`2<ActualLab.Interception.MethodDef, object>&)
4.31 | 4.31 | ActualLab.Fusion.Interception.ComputeMethodFunction`1<ActualChat.UI.Blazor.App.Services.ChatAudioUI/RecordingBeepState>:Compute (ActualLab.Fusion.ComputedInput,ActualLab.Fusion.Computed`1<ActualChat.UI.Blazor.App.Services.ChatAudioUI/RecordingBeepState>,System.Threading.CancellationToken)
4.23 | 4.23 | System.SpanHelpers:NonPackedIndexOfValueType<int16, System.SpanHelpers/Negate`1<int16>> (int16&,int16,int)
4.20 | 4.20 | MemoryPack.MemoryPackFormatterProvider:IsRegistered<ActualLab.Rpc.RpcMethodRef> ()
4.04 | 4.01 | (wrapper native-to-managed) Android.Runtime.JNINativeWrapper:Wrap_JniMarshal_PPLIIIIIIII_V (intptr,intptr,intptr,int,int,int,int,int,int,int,int)
3.97 | 3.97 | ActualChat.Kvas.StoredState`1<ActualChat.ChatId>:CreateComputed ()
3.92 | 3.92 | ActualLab.Fusion.ComputedExt/<Changes>d__27`1<ActualChat.UI.Blazor.App.Services.ChatAudioUI/RecordingBeepState>:MoveNext ()
3.87 | 3.87 | ActualLab.Fusion.Client.Interception.RemoteComputeMethodFunction`1/<ApplyRpcUpdate>d__18<ActualLab.Api.ApiArray`1<ActualChat.PlaceId>>:MoveNext ()
3.83 | 3.83 | System.Text.Json.Serialization.Converters.ObjectWithParameterizedConstructorConverter`1<ActualLab.Mathematics.Range`1<int>>:OnTryRead (System.Text.Json.Utf8JsonReader&,System.Type,System.Text.Json.JsonSerializerOptions,System.Text.Json.ReadStack&,ActualLab.Mathematics.Range`1<int>&)
4.05 | 3.82 | ActualLab.Fusion.Client.Interception.RemoteComputeMethodFunction`1/<TryRecompute>d__20<ActualLab.Mathematics.Range`1<long>>:MoveNext ()
3.78 | 3.78 | System.DateTimeFormat:FormatCustomized<char> (System.DateTime,System.ReadOnlySpan`1<char>,System.Globalization.DateTimeFormatInfo,System.TimeSpan,System.Collections.Generic.ValueListBuilder`1<char>&)
3.74 | 3.74 | ActualLab.Fusion.ComputeFunctionBase`1/<TryRecompute>d__17<ActualChat.Mathematics.Trimmed`1<int>>:MoveNext ()
4.37 | 3.73 | System.Number:NumberToString<char> (System.Collections.Generic.ValueListBuilder`1<char>&,System.Number/NumberBuffer&,char,int,System.Globalization.NumberFormatInfo)
7.96 | 3.68 | ActualLab.Fusion.Client.Interception.RemoteComputeMethodFunction`1/<Compute>d__15<ActualLab.Mathematics.Range`1<long>>:MoveNext ()
5.87 | 3.67 | ActualLab.Fusion.Interception.ComputeMethodFunction`1/<Compute>d__8<ActualChat.Mathematics.Trimmed`1<int>>:MoveNext ()
3.67 | 3.67 | ActualLab.Fusion.Computed`1/<Update>d__35<ActualLab.Api.ApiArray`1<ActualChat.UI.Blazor.App.Services.ActiveChat>>:MoveNext ()
3.65 | 3.65 | ActualLab.Fusion.ComputeFunctionBase`1/<TryRecompute>d__17<bool>:MoveNext ()
3.64 | 3.64 | ActualLab.Fusion.Computed/<Capture>d__83`1<ActualChat.ChatId>:MoveNext ()
4.20 | 3.59 | System.Collections.Immutable.ImmutableHashSet`1<ActualChat.ChatId>:Union (System.Collections.Generic.IEnumerable`1<ActualChat.ChatId>,System.Collections.Immutable.ImmutableHashSet`1/MutationInput<ActualChat.ChatId>)
3.48 | 3.48 | ActualLab.Fusion.ComputeFunctionBase`1/<TryRecompute>d__17<System.ValueTuple`2<ActualChat.ChatId, bool>>:MoveNext ()
3.47 | 3.46 | ActualLab.Rpc.Infrastructure.RpcOutboundCall`1<ActualLab.Rpc.RpcNoWait>:.ctor (ActualLab.Rpc.Infrastructure.RpcOutboundContext)
3.45 | 3.45 | ActualLab.Fusion.Client.Interception.RemoteComputeMethodFunction`1/<ApplyRpcUpdate>d__18<ActualLab.Api.ApiArray`1<ActualChat.ContactId>>:MoveNext ()
3.42 | 3.42 | ActualLab.Fusion.Client.Interception.RemoteComputeMethodFunction`1/<ComputeCachedOrRpc>d__17<ActualLab.Api.ApiArray`1<ActualChat.ContactId>>:MoveNext ()
3.31 | 3.31 | System.Number:FormatPercent<char> (System.Collections.Generic.ValueListBuilder`1<char>&,System.Number/NumberBuffer&,int,System.Globalization.NumberFormatInfo)
3.56 | 3.30 | Pidgin.OneOfParser`2<char, char>:TryParse (Pidgin.ParseState`1<char>&,Pidgin.PooledList`1<Pidgin.Expected`1<char>>&,char&)
3.30 | 3.30 | ActualLab.Fusion.Computed/<Capture>d__83`1<System.ValueTuple`2<ActualChat.ChatId, bool>>:MoveNext ()
3.29 | 3.29 | ActualChat.Kvas.StoredState`1<ActualLab.Api.ApiArray`1<ActualChat.UI.Blazor.App.Services.ActiveChat>>:CreateComputed ()
3.28 | 3.28 | ActualLab.Fusion.Client.Interception.RemoteComputeMethodFunction`1/<Compute>d__15<ActualChat.Users.Presence>:MoveNext ()
3.46 | 3.26 | ActualLab.Result`1<System.ValueTuple`2<ActualChat.ChatId, bool>>:MemoryPack.IMemoryPackFormatterRegister.RegisterFormatter ()
3.82 | 3.24 | ActualLab.Fusion.Computed/<Capture>d__83`1<ActualChat.UI.Blazor.App.Services.ChatAudioUI/RecordingBeepState>:MoveNext ()
5.25 | 3.21 | ActualLab.Fusion.Client.Interception.RemoteComputeMethodFunction`1/<Compute>d__15<ActualLab.Api.ApiArray`1<ActualChat.ContactId>>:MoveNext ()
3.19 | 3.19 | ActualLab.Fusion.Computed`1/<Use>d__37<ActualLab.Api.ApiArray`1<ActualChat.UI.Blazor.App.Services.ActiveChat>>:MoveNext ()
3.16 | 3.16 | System.Collections.Generic.HashSet`1<ActualChat.UI.Blazor.App.Services.ActiveChat>:.ctor (System.Collections.Generic.IEqualityComparer`1<ActualChat.UI.Blazor.App.Services.ActiveChat>)
4.61 | 3.13 | ActualLab.Fusion.Client.Interception.RemoteComputeMethodFunction`1/<ComputeCachedOrRpc>d__17<ActualLab.Mathematics.Range`1<long>>:MoveNext ()
3.09 | 3.09 | System.Number:FormatDouble<byte> (System.Collections.Generic.ValueListBuilder`1<byte>&,double,System.ReadOnlySpan`1<char>,System.Globalization.NumberFormatInfo)
3.09 | 3.09 | System.Number:NumberToString<byte> (System.Collections.Generic.ValueListBuilder`1<byte>&,System.Number/NumberBuffer&,char,int,System.Globalization.NumberFormatInfo)
3.13 | 3.05 | System.Runtime.CompilerServices.AsyncTaskMethodBuilder`1/AsyncStateMachineBox`1<System.Threading.Tasks.VoidTaskResult, ActualLab.Time.TimerSet`1/<OnRun>d__25<object>>:MoveNext (System.Threading.Thread)
3.08 | 3.05 | System.Text.Json.Serialization.Metadata.JsonPropertyInfo`1<long>:ConfigureIgnoreCondition (System.Nullable`1<System.Text.Json.Serialization.JsonIgnoreCondition>)
...And the tail: |
|
@jonathanpeppers this aligns quite well with our own measurements shown e.g. here - the total startup time (that's our internal metric which measures it till a certain point in rendering) was 2.1s during this specific recording - it's slightly higher usual, but 1.4/2.1 ~= 66%, which is quite close to our own estimate. And here I even explicitly tagged you and wrote that 75% of our startup time is spent on JIT, no matter whether it's full or profiled AOT. All of that data was shared in April-May. And no one moved a finger. |
|
As for |
|
Two more runs - just wanted to check how consistent this is. The total is ~ the same, but top methods are mostly different. Oh, and I noticed there is negative "self-time" closer to the end in all these files. Based on ChatGPT analysis of out3.txt, |
|
Okey... I created pull request addressing some of issues I spotted, but overall, I am not sure if we can even trust I'm attaching new outputs here: And that's what you'll find in the end now: |
|
Just in case, the original |
|
Hmm, just found a whole category of methods which aren't generic ones: @jonathanpeppers do you know why such methods aren't AOT-compiled in full AOT mode? Or does it mean any method appears in methods.txt, i.e. AOT compiled methods also appear there, but processing time is tiny for them? Based on the # of lines (~60K) it feels like it's the second case, i.e. every method is listed there: previously I wrote that Mono debug log shows 16K "AOT NOT FOUND" + 8K "AOT FOUND" entries, i.e. 24K in total, and here it's 30K, i.e. even more somehow. If that's true, it makes sense to filter out all sub-0.01ms methods (looks like these are AOT compiled methods) + likely, all wrappers. |
Description
When I build maui application for Android with full aot compilation, I see a lot of
aot not foundlog messags for mono aot logger.Especially for generic class/methods. Even for the ones I expect that should be statically detected.
E.g.:
04-15 18:43:11.957 28518 28518 D Mono : AOT NOT FOUND: System.Collections.Concurrent.ConcurrentDictionary`2<Microsoft.Extensions.DependencyInjection.ServiceLookup.ServiceIdentifier, Microsoft.Extensions.DependencyInjection.ServiceProvider/ServiceAccessor>:.ctor ().
04-15 18:43:23.703 28518 28518 D Mono : AOT NOT FOUND: System.Runtime.CompilerServices.AsyncTaskMethodBuilder
1<System.Threading.Tasks.VoidTaskResult>:GetStateMachineBox<MauiAotTest.Components.Pages.Weather/<OnInitializedAsync>d__2> (MauiAotTest.Components.Pages.Weather/<OnInitializedAsync>d__2&,System.Threading.Tasks.Task1<System.Threading.Tasks.VoidTaskResult>&).See attached files: one with full log for the app and the one with
aot not foundonly messages.LogNote_47021f4c_20240415_18.43.07_tst2_aot_full_not_found.txt
LogNote_47021f4c_20240415_18.43.07_tst2_aot_full.txt
Steps to Reproduce
adb shell setprop debug.mono.log default,timing=bare,assembly,mono_log_level=debug,mono_log_mask=aotaot not found(exclude the ones for wrappers) log messages.Link to public reproduction project repository
https://github.com/crui3er/MauiAotTest
Version with bug
8.0.3 GA
Is this a regression from previous behavior?
Not sure, did not test other versions
Last version that worked well
Unknown/Other
Affected platforms
Android
Affected platform versions
No response
Did you find any workaround?
No
Relevant log output
No response
The text was updated successfully, but these errors were encountered: