runtime: [Xamarin.Android] Performance regression between net7 and net8

We’ve observed that a plain “hello world” Xamarin.Android application (dotnet new android) starts up slower than it did under net7. The slowdown cannot be attribute to changes in XA itself, as there haven’t been any changes that could affect performance to this degree. Our performance test measures three startup metrics:

“Application displayed time” as reported by the Android OS. This is measured by the system and is the time between starting the application (via intent or by clicking its icon in the UI) and the point where the application frame is fully painted. This metric regressed by an average of 11% across 10 test runs.
First managed call performance (we call a static class method which does some initialization for us). This metric regressed by around 50%
The “total init time” is the time spent in the native XA runtime. This includes the “first managed call” sequence above, plus MonoVM initialization, loading of some assemblies as needed to make the first managed call, setting up handlers etc. This metric regressed by about 25%

XA uses profiled AOT to improve startup time, and recording a new profile allowed me to see what new methods are called at startup. Here’s a set of them that has the biggest potential to adversely affect performance:

+       bool System.Collections.Generic.List`1/Enumerator<System.Diagnostics.Metrics.Instrument>:MoveNext ()
+       bool System.Collections.Generic.List`1/Enumerator<System.Diagnostics.Metrics.Instrument>:MoveNextRare ()
+       bool System.Collections.Generic.List`1<System.Diagnostics.Metrics.Instrument>:Contains (System.Diagnostics.Metrics.Instrument)
+       bool System.Diagnostics.Metrics.Meter:AddInstrument (System.Diagnostics.Metrics.Instrument)
+       bool System.Globalization.CultureData:IsValidCultureName (string,int&,int&)
+       bool System.Guid:TryWriteBytes (System.Span`1<byte>)
+       bool System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1/ConfiguredTaskAwaiter<Java.Net.Proxy>:get_IsCompleted ()
+       bool System.Runtime.CompilerServices.ConfiguredTaskAwaitable`1/ConfiguredTaskAwaiter<System.Net.HttpStatusCode>:get_IsCompleted ()
+       bool System.Runtime.CompilerServices.ConfiguredTaskAwaitable/ConfiguredTaskAwaiter:get_IsCompleted ()
+       bool System.RuntimeTypeHandle:IsFunctionPointer (System.RuntimeType)
+       Interop/Globalization/ResultCode System.TimeZoneInfo/<>c:<GetDisplayName>b__192_0 (System.Span`1<char>,string,string,Interop/Globalization/TimeZoneDisplayNameType)
+       Interop/Sys/OpenFlags Microsoft.Win32.SafeHandles.SafeFileHandle:PreOpenConfigurationFromOptions (System.IO.FileMode,System.IO.FileAccess,System.IO.FileShare,System.IO.FileOptions,bool)
+       int System.Collections.Generic.List`1<System.Diagnostics.Metrics.Instrument>:IndexOf (System.Diagnostics.Metrics.Instrument)
+       object System.Diagnostics.Metrics.Instrument:get_SyncObject ()
+       object System.Reflection.MethodBaseInvoker:InterpretedInvoke_Constructor (object,intptr*)
+       object System.Reflection.MethodBaseInvoker:InterpretedInvoke_Method (object,intptr*)
+       object System.Reflection.MethodBaseInvoker:InvokeConstructorWithoutAlloc (object,bool)
+       object System.Reflection.MethodBaseInvoker:InvokeDirectByRefWithFewArgs (object,System.Span`1<object>,System.Reflection.BindingFlags)
+       object System.Reflection.MethodBaseInvoker:InvokeWithFewArgs (object,System.Reflection.BindingFlags,System.Reflection.Binder,object[],System.Globalization.CultureInfo)
+       object System.Reflection.MethodBaseInvoker:InvokeWithNoArgs (object,System.Reflection.BindingFlags)
+       string System.Globalization.CultureData:NormalizeCultureName (string,System.ReadOnlySpan`1<char>,int&)
+       string System.TimeZoneInfo:get_DaylightName ()
+       string System.TimeZoneInfo:get_DisplayName ()
+       string System.TimeZoneInfo:PopulateDaylightDisplayName ()
+       string System.TimeZoneInfo:PopulateDisplayName ()
+       string System.TimeZoneInfo:PopulateStandardDisplayName ()
+       System.Collections.Generic.List`1/Enumerator<System.Diagnostics.Metrics.Instrument> System.Collections.Generic.List`1<System.Diagnostics.Metrics.Instrument>:GetEnumerator ()
+       System.Collections.Generic.List`1<System.Diagnostics.Metrics.MeterListener> System.Diagnostics.Metrics.MeterListener:GetAllListeners ()
+       System.Diagnostics.Metrics.Counter`1<long> System.Diagnostics.Metrics.Meter:CreateCounter (string,string,string)
+       System.Diagnostics.Metrics.Counter`1<long> System.Diagnostics.Metrics.Meter:CreateCounter (string,string,string,System.Collections.Generic.IEnumerable`1<System.Collections.Generic.KeyValuePair`2<string, object>>)
+       System.Diagnostics.Metrics.Histogram`1<double> System.Diagnostics.Metrics.Meter:CreateHistogram (string,string,string)
+       System.Diagnostics.Metrics.Histogram`1<double> System.Diagnostics.Metrics.Meter:CreateHistogram (string,string,string,System.Collections.Generic.IEnumerable`1<System.Collections.Generic.KeyValuePair`2<string, object>>)
+       System.Diagnostics.Metrics.Instrument System.Diagnostics.Metrics.Meter/<>c__DisplayClass29_0`1<System.Int64>:<CreateCounter>b__0 ()
+       System.Diagnostics.Metrics.Instrument System.Diagnostics.Metrics.Meter/<>c__DisplayClass31_0`1<System.Double>:<CreateHistogram>b__0 ()
+       System.Diagnostics.Metrics.Instrument System.Diagnostics.Metrics.Meter/<>c__DisplayClass33_0`1<System.Int64>:<CreateUpDownCounter>b__0 ()
+       System.Diagnostics.Metrics.Instrument System.Diagnostics.Metrics.Meter:GetCachedInstrument (System.Collections.Generic.List`1<System.Diagnostics.Metrics.Instrument>,System.Type,string,string,System.Collections.Generic.IEnumerable`1<System.Collections.Generic.KeyValuePair`2<string, object>>)
+       System.Diagnostics.Metrics.Instrument System.Diagnostics.Metrics.Meter:GetOrCreateInstrument (System.Type,string,string,string,System.Collections.Generic.IEnumerable`1<System.Collections.Generic.KeyValuePair`2<string, object>>,System.Func`1<System.Diagnostics.Metrics.Instrument>)
+       System.Diagnostics.Metrics.Instrument System.Diagnostics.Metrics.Meter:GetOrCreateInstrument (System.Type,string,string,string,System.Collections.Generic.IEnumerable`1<System.Collections.Generic.KeyValuePair`2<string, object>>,System.Func`1<System.Diagnostics.Metrics.Instrument>)
+       System.Diagnostics.Metrics.Meter System.Net.Http.Metrics.MetricsHandler/SharedMeter:get_Instance ()
+       System.Diagnostics.Metrics.UpDownCounter`1<long> System.Diagnostics.Metrics.Meter:CreateUpDownCounter (string,string,string)
+       System.Diagnostics.Metrics.UpDownCounter`1<long> System.Diagnostics.Metrics.Meter:CreateUpDownCounter (string,string,string,System.Collections.Generic.IEnumerable`1<System.Collections.Generic.KeyValuePair`2<string, object>>)
+       System.Guid System.Reflection.RuntimeModule:get_ModuleVersionId ()
+       System.Guid System.Reflection.RuntimeModule:GetModuleVersionId ()
+       System.Net.Http.Metrics.MetricsHandler System.Net.Http.HttpClientHandler:SetupHandlerChain ()
+       System.Reflection.MethodInfo System.Type:GetMethod (string,System.Reflection.BindingFlags,System.Reflection.Binder,System.Reflection.CallingConventions,System.Type[],System.Reflection.ParameterModifier[])
+       System.Reflection.MethodInfo System.Type:GetMethod (string,System.Reflection.BindingFlags,System.Reflection.Binder,System.Type[],System.Reflection.ParameterModifier[])
+       System.Reflection.Module System.RuntimeType:get_Module ()
+       System.Threading.Tasks.Task`1<System.Net.Http.HttpResponseMessage> System.Net.Http.HttpMessageHandlerStage:SendAsync (System.Net.Http.HttpRequestMessage,System.Threading.CancellationToken)
+       System.Threading.Tasks.Task`1<System.Net.Http.HttpResponseMessage> System.Threading.Tasks.ValueTask`1<System.Net.Http.HttpResponseMessage>:AsTask ()
+       System.Threading.Tasks.ValueTask`1<System.Net.Http.HttpResponseMessage> System.Net.Http.Metrics.MetricsHandler:SendAsync (System.Net.Http.HttpRequestMessage,bool,System.Threading.CancellationToken)
+       System.TimeZoneInfo/AdjustmentRule[] System.Collections.Generic.List`1<System.TimeZoneInfo/AdjustmentRule>:ToArray ()
+       void System.Collections.Generic.List`1/Enumerator<System.Diagnostics.Metrics.Instrument>:.ctor (System.Collections.Generic.List`1<System.Diagnostics.Metrics.Instrument>)
+       void System.Diagnostics.Metrics.Counter`1<System.Int64>:.ctor (System.Diagnostics.Metrics.Meter,string,string,string,System.Collections.Generic.IEnumerable`1<System.Collections.Generic.KeyValuePair`2<string, object>>)
+       void System.Diagnostics.Metrics.Histogram`1<System.Double>:.ctor (System.Diagnostics.Metrics.Meter,string,string,string,System.Collections.Generic.IEnumerable`1<System.Collections.Generic.KeyValuePair`2<string, object>>)
+       void System.Diagnostics.Metrics.Instrument`1<System.Double>:.ctor (System.Diagnostics.Metrics.Meter,string,string,string,System.Collections.Generic.IEnumerable`1<System.Collections.Generic.KeyValuePair`2<string, object>>)
+       void System.Diagnostics.Metrics.Instrument`1<System.Int64>:.ctor (System.Diagnostics.Metrics.Meter,string,string,string,System.Collections.Generic.IEnumerable`1<System.Collections.Generic.KeyValuePair`2<string, object>>)
+       void System.Diagnostics.Metrics.Instrument/<>c:.cctor ()
+       void System.Diagnostics.Metrics.Instrument/<>c:.ctor ()
+       void System.Diagnostics.Metrics.Instrument:.cctor ()
+       void System.Diagnostics.Metrics.Instrument:.ctor (System.Diagnostics.Metrics.Meter,string,string,string,System.Collections.Generic.IEnumerable`1<System.Collections.Generic.KeyValuePair`2<string, object>>)
+       void System.Diagnostics.Metrics.Instrument:Publish ()
+       void System.Diagnostics.Metrics.Instrument:ValidateTypeParameter ()
+       void System.Diagnostics.Metrics.Instrument:ValidateTypeParameter ()
+       void System.Diagnostics.Metrics.Meter/<>c:.cctor ()
+       void System.Diagnostics.Metrics.Meter/<>c:.ctor ()
+       void System.Diagnostics.Metrics.Meter:.cctor ()
+       void System.Diagnostics.Metrics.Meter:.ctor (string)
+       void System.Diagnostics.Metrics.Meter:.ctor (string,string,System.Collections.Generic.IEnumerable`1<System.Collections.Generic.KeyValuePair`2<string, object>>,object)
+       void System.Diagnostics.Metrics.Meter:Initialize (string,string,System.Collections.Generic.IEnumerable`1<System.Collections.Generic.KeyValuePair`2<string, object>>,object)
+       void System.Diagnostics.Metrics.MeterListener:.cctor ()
+       void System.Diagnostics.Metrics.MetricsEventSource:.cctor ()
+       void System.Diagnostics.Metrics.MetricsEventSource:.ctor ()
+       void System.Diagnostics.Metrics.UpDownCounter`1<System.Int64>:.ctor (System.Diagnostics.Metrics.Meter,string,string,string,System.Collections.Generic.IEnumerable`1<System.Collections.Generic.KeyValuePair`2<string, object>>)
+       void System.Net.Http.Metrics.MetricsHandler:.ctor (System.Net.Http.HttpMessageHandler,System.Diagnostics.Metrics.IMeterFactory,System.Diagnostics.Metrics.Meter&)
+       void System.Net.Http.Metrics.MetricsHandler/SharedMeter:.cctor ()
+       void System.Net.Http.Metrics.MetricsHandler/SharedMeter:.ctor ()
+       void System.TimeZoneInfo:GetDaylightDisplayName (string,string&)
+       void System.TimeZoneInfo:GetFullValueForDisplayNameField (string,System.TimeSpan,string&)
+       void System.TimeZoneInfo:GetStandardDisplayName (string,string&)

The worrying parts are the HTTP requests, the System.Diagnostic.Metrics calls, the TPL use and the timezone data - the latter was greatly improved lately, but it appears that accessing timezone data has somehow become part of the default startup path. startup (the biggest issue here is retrieving the zone’s display name, which is an expensive operation)

About this issue

Original URL
State: closed
Created a year ago
Comments: 84 (84 by maintainers)

Commits related to this issue

[Xamarin.Android.Build.Tasks] feature switch defaults for fast startup Context: https://github.com/dotnet/runtime/commit/fecf3eeffd3650566555e15292f9df0d3abcdfc6 Context: https://github.com/dotnet/ru... — committed to jonathanpeppers/xamarin-android by jonathanpeppers 9 months ago
[Xamarin.Android.Build.Tasks] feature switch defaults for fast startup (#8347) Context: https://github.com/dotnet/runtime/commit/fecf3eeffd3650566555e15292f9df0d3abcdfc6 Context: https://github.com/... — committed to xamarin/xamarin-android by jonathanpeppers 9 months ago

Most upvoted comments

@tarekgh I think this problem should be addressed by creating a central mechanism to disable all metrics, similar to how we have a central mechanism to disable all EventSource. I do not think it makes sense to create one-off solution for disabling metrics just for System.Net.Http.

jkotas on Aug 7, 2023

@tarekgh good news! Disabling metrics with the feature flag shows a ~4% improvement in total startup time, and a similar amount for the managed code init time 😃

grendello on Sep 12, 2023

@tarekgh not yet, but I will get to it in a 2-3 hours. Will report on the results before EOD today.

grendello on Sep 12, 2023

@grendello I’ll share the changes with you when I have them.

tarekgh on Sep 5, 2023

I need to do the exact measurements that @grendello did #89880 (comment).

I’ll try to get the numbers in the next couple of days (been out for 2 weeks, need to get up to speed with all that’s happened first)

grendello on Sep 4, 2023

cc @kg @pavelsavara re startup regressions

lewing on Aug 31, 2023

@noahfalk after some misses, I think I have some realistic perf numbers. I compared builds of two runtime commits - the one which introduced metrics to the HttpClient (28a4c95) and the one just before it. My tests measure several metrics (each measure is 10 runs of a cold-started app on the same device, Pixel 6 Pro):

“Native-to-managed transition” time is where Xamarin.Android runtime calls the managed runtime for the very first time. It’s an invocation of a static method, during which we see a lot of what’s in the profile in the OP above. This measure is slower by 5.22%

“Total init” time is the entire time spent in the native Xamarin.Android code between the point where Android calls us (via Java startup code we have) and when we hand the reigns over to the managed land. This includes the “Native-to-managed” portion. This measure is worse by 20.91%

“Displayed” time is what Android sees as the time between starting the app and it being fully shown to the user. This includes the two measurements above + some Android OS overhead (mostly windowing system renderer and compositor). That measure took a hit of 4.44%

@grendello - Did you update the AOT profile after the change which introduced metrics to the HttpClient (28a4c95)? or does this 4% diff include the cost of JIT’ing these new methods which aren’t part of the current AOT profile?

cc @jonathanpeppers

eerhardt on Aug 31, 2023

@tarekgh it would be great if it was part of the net8 release.

grendello on Aug 8, 2023

@tarekgh a way to disable metrics is to put them behind a feature flag which will allow the linker to remove their use completely.

grendello on Aug 7, 2023

Thanks @grendello

tarekgh on Aug 4, 2023

@tarekgh yes, I will do that, on Monday however 😃 It’s Friday evening here and I am yearning to start the weekend 😃 I’ll get back to you on Monday with the new numbers.

grendello on Aug 4, 2023

One way to test whether the main difference is really coming from the initialization of Meter components would be to revert to before https://github.com/dotnet/runtime/commit/28a4c9534f18368f5b6b328de932ae2d6001ffc4, then test with/without adding the following to the test app itself. The Http stack isn’t doing a whole lot more than that, so seeing radically different numbers would be surprising.

static void MetricsHandlerOverhead()
{
    var meter = new Meter("Dummy.Net.Http");
    _ = meter.CreateUpDownCounter<long>("someCounterName", null, "Some counter description.");
    _ = meter.CreateUpDownCounter<long>("someCounterName2", null, "Some counter description.");
    _ = meter.CreateHistogram<double>("someHistogramName", null, "Some histogram description.");
}

MihaZupan on Aug 4, 2023

We could make it lazy up until the first request (edit: we already do this), but yeah after that we’ll need the Instruments to let us know whether we should do anything. I guess that wouldn’t really help your overall situation that includes making the request.

I think the only option to prevent startup impact is to make it opt-in or opt out.

steveisok on Aug 4, 2023

is it possible you can make the metrics initialization be lazy?

Should be possible, yes.

If I prepare a draft change for that, would you be able to test it @grendello?

Absolutely, but not earlier than on Monday 😃

grendello on Aug 4, 2023

This is weird, I wonder what is starting a listener in the test app?

The listener is not started, it is just statically initialized. no listener object is created as I am seeing.

tarekgh on Aug 4, 2023

@antonfirsov is it possible you can make the metrics initialization be lazy?

Should be possible, yes.

I don’t see how. My understanding is that one cannot opt-in into listening without creating the meters and instruments first. What am I missing?

+       void System.Diagnostics.Metrics.MeterListener:.cctor ()
+       void System.Diagnostics.Metrics.MetricsEventSource:.cctor ()

This is weird, I wonder what is starting a listener in the test app?

antonfirsov on Aug 4, 2023

is it possible you can make the metrics initialization be lazy?

~~Should be possible, yes.~~ See below - it’s already lazy up until the first request.

If I prepare a draft change for that, would you be able to test it @grendello?

MihaZupan on Aug 4, 2023