Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Xamarin.Android] Performance regression between net7 and net8 #89880

Closed
grendello opened this issue Aug 2, 2023 · 84 comments
Closed

[Xamarin.Android] Performance regression between net7 and net8 #89880

grendello opened this issue Aug 2, 2023 · 84 comments

Comments

@grendello
Copy link
Contributor

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)

@ghost ghost added the untriaged New issue has not been triaged by the area owner label Aug 2, 2023
@ghost
Copy link

ghost commented Aug 2, 2023

Tagging subscribers to 'arch-android': @steveisok, @akoeplinger
See info in area-owners.md if you want to be subscribed.

Issue Details

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)

Author: grendello
Assignees: -
Labels:

os-android, untriaged, area-System.Diagnostics.Metric

Milestone: -

@steveisok
Copy link
Member

/cc @SamMonoRT

@grendello
Copy link
Contributor Author

The profile is recorded with this application https://github.com/xamarin/xamarin-android/blob/main/src/profiled-aot/CommonMethods.cs

This explains the TPL and the HTTP, luckily :) The TZ requests and the metrics handler are still worrying.

@SamMonoRT
Copy link
Member

cc @vargaz @fanyang-mono

@SamMonoRT
Copy link
Member

@mdh1418 @tarekgh - do you think #89985 should help some of the Android startup regressions related to expensive TimeZone requests?

@SamMonoRT
Copy link
Member

@antonfirsov - can #87319 cause a startup regression. @grendello is it possible to coordinate with @antonfirsov to run some profiles before/after the change.

@antonfirsov
Copy link
Member

/cc @MihaZupan @karelz and also @tarekgh in case this will be root caused to Meter performance.

@grendello since we don't have experience with Android, can you help us by running profiler/benchmarks?

@mdh1418
Copy link
Member

mdh1418 commented Aug 4, 2023

@mdh1418 @tarekgh - do you think #89985 should help some of the Android startup regressions related to expensive TimeZone requests?

If GetSystemTimeZones is the only caller to the string System.TimeZoneInfo:get_DisplayName () reported in the new methods being hit in the profile, it would help. However not sure what exactly is invoking that right now

@grendello
Copy link
Contributor Author

@antonfirsov if you point me to the commits I need to test, I can do the rest :) Note that this is not part of the startup for a hello world app, but the AOT profile recording app linked to above. However, any non-trivial app is likely to hit the same code path, so it would be great if we could address that.

@grendello
Copy link
Contributor Author

@antonfirsov it would be ideal if metrics were disabled by default, but easily enabled by setting an msbuild property of something. On mobile, it's best to do as little as possible by default.

@antonfirsov
Copy link
Member

antonfirsov commented Aug 4, 2023

f you point me to the commits I need to test

If we suspect metrics, you need to check #89985 #87319

Note that Meter and Instrument were designed in a way that there is no way to opt-out of their instantiation, since users can opt-in into measurements per-instrument at runtime.

If this has to be revisited, and we need global switch(es) to turn the entire feature on/off (per library? for the entire BCL?) you need to discuss it with @noahfalk.

@MihaZupan
Copy link
Member

When nothing is listening to metrics (the default), the overhead on an individual request should be negligible (we'll do a quick check to see if anything is listening and then skip all the extra logic).

As Anton said though, someone may start collecting this information at any time, so the HttpClient instrumentation has to do some work at startup to prepare for that possibility.
This startup cost is mainly creating the shared Meter instance, and creating a few Instruments from it.

28a4c95 was the initial commit that added this logic to HttpClient. There have been a few changes to that logic in main since, but they shouldn't meaningfully affect startup costs.

@grendello
Copy link
Contributor Author

@MihaZupan the JIT still needs to compile the methods (or load them from AOT), initialize the class etc. On mobile every bit helps, and if you have dozens or hundreds of things with negligible impact, then taken together they will have a huge impact. We've been through that process in Xamarin.Android and we managed to get our startup time from 1.6s to 120ms back then - without a single large offender, just hundreds and hundreds tiny things. This is why I'm always very insistent on not doing anything by default unless the app cannot properly run without it.

@tarekgh
Copy link
Member

tarekgh commented Aug 4, 2023

I believe the extra cost here is coming from http client enabling the metrics. Looking at the description and the list of called methods, looks to me the cost is because enabling metrics first time will start do some static initialization

+       void System.Diagnostics.Metrics.Instrument/<>c:.cctor ()
+       void System.Diagnostics.Metrics.Instrument:.cctor ()
+       void System.Diagnostics.Metrics.Meter/<>c:.cctor ()
+       void System.Diagnostics.Metrics.Meter:.cctor ()
+       void System.Diagnostics.Metrics.MeterListener:.cctor ()
+       void System.Diagnostics.Metrics.MetricsEventSource:.cctor ()
+       void System.Net.Http.Metrics.MetricsHandler/SharedMeter:.cctor ()

These initializations were not exercised before in the app startup scenario like the one mentioned here. So, enabling it will be expected to add some cost to the app startup.

@antonfirsov is it possible you can make the metrics initialization in http be lazy? to avoid the cost during the app startup. Or changing the app to not depend on the http handler in the startup scenario.

@grendello
Copy link
Contributor Author

@tarekgh static state was one of the offenders we had when optimizing Xamarin.Android startup. On mobile it's best to avoid that as much as possible. Going lazy is the way to go! :)

@MihaZupan
Copy link
Member

MihaZupan commented 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?

@antonfirsov
Copy link
Member

antonfirsov commented 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?

@MihaZupan
Copy link
Member

MihaZupan commented 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.

@tarekgh
Copy link
Member

tarekgh commented 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.

@grendello
Copy link
Contributor Author

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 :)

@steveisok
Copy link
Member

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.

@antonfirsov
Copy link
Member

antonfirsov commented Aug 4, 2023

edit: we already do this

Yeah the handler chain initialization is lazy.

I think there should be a global switch to turn built-in metrics on/off for the entire BCL, which should be off by default for mobile. You should reach out to @noahfalk, come up with a design, then @MihaZupan can raise a PR to implement it for System.Net.Http and System.Net.NameResolution.

@grendello
Copy link
Contributor Author

I think there should be a global switch to turn built-in metrics on/off for the entire BCL, which should be off by default for mobile. You should reach out to @noahfalk, come up with a design, then @MihaZupan can raise a PR to implement it for System.Net.Http and System.Net.NameResolution.

That would be ideal

@antonfirsov
Copy link
Member

(Still would be nice to see some numbers to confirm the root-causing.)

@tarekgh
Copy link
Member

tarekgh commented Aug 4, 2023

I think there should be a global switch to turn built-in metrics on/off for the entire BCL, which should be off by default for mobile. You should reach out to @noahfalk, come up with a design, then @MihaZupan can raise a PR to implement it for System.Net.Http and System.Net.NameResolution.

That would be ideal

I think there is some misunderstanding here. Creating metrics is cheap in general cases. The cost only be when someone start listening to the metrics. The issue reported here is scoped to the app startup which causes initializing the metrics first time in the process. Having http do lazy initialization should help with that.

@grendello
Copy link
Contributor Author

@tarekgh if you look at the test app, it doesn't start listening to the metrics explicitly, so something is acting behind the scenes.

@antonfirsov
Copy link
Member

The cost only be when someone start listening to the metrics.

As @grendello mentioned, this is not happening in the test app: https://github.com/xamarin/xamarin-android/blob/main/src/profiled-aot/CommonMethods.cs

Having http do lazy initialization

We already do that. The test app makes an HTTP request, which involves instrument creation. Without creating the instruments, there is no way to enable listening.

@grendello I think it would be valuable to do some benchmarking/profiling and elaborate what exactly is causing the slowdown.

@SamMonoRT
Copy link
Member

@steveisok for the sdk question ^^

@steveisok
Copy link
Member

@jonathanpeppers did you already bring this up to the sdk?

@jonathanpeppers
Copy link
Member

@grendello is out, but I will check back with him next week, what the state of the HttpClient metrics changes are. Did we create any feature flags for that?

The feature switch added in #91352 for Microsoft.Extensions, we are going to implement in the Android workload as soon as we have a runtime build to try it.

@tarekgh
Copy link
Member

tarekgh commented Aug 31, 2023

what the state of the HttpClient metrics changes are. Did we create any feature flags for that?

Not yet. #89880 (comment). I am planning to start working on that this week. Is it possible when I have a private build or changes to get some help measuring the Android perf to ensure the changes are going to address the raised issue?

To be clearer, we are going to introduce a feature switch to the metrics APIs and not for http client.

@jonathanpeppers
Copy link
Member

I basically just did this in a .NET MAUI app to test my Microsoft.Extensions changes:

image

I had a local build in D:\src\dotnet\runtime\.

But if your changes are in the BCL, this simple option might not work.

You can also try:

@tarekgh
Copy link
Member

tarekgh commented Aug 31, 2023

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

@lewing
Copy link
Member

lewing commented Aug 31, 2023

cc @kg @pavelsavara re startup regressions

@grendello
Copy link
Contributor Author

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)

@tarekgh
Copy link
Member

tarekgh commented Sep 4, 2023

Thanks @grendello, could you please answer @eerhardt question in the comment #89880 (comment) too?

@grendello
Copy link
Contributor Author

grendello commented Sep 5, 2023

@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?

Yes, the results in the OP were obtained with a fresh AOT profile which included the metrics code.

@grendello
Copy link
Contributor Author

grendello commented Sep 5, 2023

@tarekgh when you have the changes you'd like to measure impact of I can test them for you, if you point me to a dotnet/runtime branch or give me a diff of the changes. I can build these locally and run the tests.

Alternatively, if you want to be able to iterate quickly, you could build XA yourself and use my performance test utility to run the tests. However, getting your new BCL to be used in an XA app build requires some
manual file copying into the locally built XA tree. If you want to follow that route we can provide guidance :)

@tarekgh
Copy link
Member

tarekgh commented Sep 5, 2023

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

@tarekgh
Copy link
Member

tarekgh commented Sep 12, 2023

@grendello as we chatted offline, did you have a chance to try #91767 and measure it with your scenario? I appreciate your help with that. We have a few days to get this in .NET 8.0, otherwise this will not make it if delayed.

@grendello
Copy link
Contributor Author

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

@grendello
Copy link
Contributor Author

@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 :)

@tarekgh
Copy link
Member

tarekgh commented Sep 12, 2023

Thanks a lot @grendello . I'll go ahead and proceed with merging the changes.

@grendello
Copy link
Contributor Author

Excellent, thank you for addressing the issue so quickly :)

@ghost ghost added the in-pr There is an active PR which will close this issue when it is merged label Sep 13, 2023
@ghost ghost removed the in-pr There is an active PR which will close this issue when it is merged label Sep 14, 2023
@tarekgh
Copy link
Member

tarekgh commented Sep 15, 2023

This is now completed.

@tarekgh tarekgh closed this as completed Sep 15, 2023
jonathanpeppers added a commit to jonathanpeppers/xamarin-android that referenced this issue Sep 18, 2023
Context: dotnet/runtime@fecf3ee
Context: dotnet/runtime@3aeefbd
Context: dotnet/runtime#89880

In dotnet/runtime two new feature switches were added in order to
improve startup performance on Android:

* `System.Diagnostics.Metrics.Meter.IsSupported`: disables
  `System.Diagnostics.Metrics` support for `HttpClient`, etc.

* `Microsoft.Extensions.DependencyInjection.DisableDynamicEngine`: after
  the second call to retrieve a service from a dependency injection
  container, `System.Reflection.Emit is used to improve performance of
  repeated calls.

We also have the existing switch:

* `Switch.System.Reflection.ForceInterpretedInvoke`: after the second
  call to `MethodInfo.Invoke()` or `ConstructorInfo.Invoke()`,
  `System.Reflection.Emit is used to improve performance of repeated
  calls.

Introduce two new MSBuild properties:

* `$(AvoidEmitForPerformance)` to toggle both
  `Microsoft.Extensions.DependencyInjection.DisableDynamicEngine` and
  `Switch.System.Reflection.ForceInterpretedInvoke`. This is a public
  property that defaults to `true`, matching a property of the same name
  used somewhere in ASP.NET.

* `$(_SystemDiagnosticsMetricsMeterIsSupported)` to toggle
  `System.Diagnostics.Metrics.Meter.IsSupported`. This is a private
  property that defaults to `false`.

I added a test to check `System.Diagnostics.Metrics.Meter.IsSupported`
at runtime. I did not do this with Microsoft.Extensions, as we'd have to
add a reference to the NuGet package and track its version for nightly
builds.

I also updated the AOT profile, and some
`System.Diagnostics.Metrics.Meter` API calls are gone now:

    bool System.Diagnostics.Metrics.Meter:AddInstrument (System.Diagnostics.Metrics.Instrument)
    object System.Diagnostics.Metrics.Instrument:get_SyncObject ()
    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.Counter`1<long> System.Diagnostics.Metrics.Meter:CreateCounter (string,string,string)
    void System.Diagnostics.Metrics.MeterListener:.cctor ()
    void System.Diagnostics.Metrics.MetricsEventSource:.cctor ()
    void System.Diagnostics.Metrics.MetricsEventSource:.ctor ()
jonpryor pushed a commit to dotnet/android that referenced this issue Sep 21, 2023
#8347)

Context: dotnet/runtime@fecf3ee
Context: dotnet/runtime@3aeefbd
Context: dotnet/runtime#89880

In dotnet/runtime two new feature switches were added in order to
improve startup performance on Android:

  * `System.Diagnostics.Metrics.Meter.IsSupported`: disables
    `System.Diagnostics.Metrics` support for `HttpClient`, etc.

  * `Microsoft.Extensions.DependencyInjection.DisableDynamicEngine`:
    after the second call to retrieve a service from a dependency
    injection container, `System.Reflection.Emit` is used to improve
    performance of repeated calls.

We also have the existing switch:

  * `Switch.System.Reflection.ForceInterpretedInvoke`: after the
    second call to `MethodInfo.Invoke()` or `ConstructorInfo.Invoke()`,
    `System.Reflection.Emit` is used to improve performance of
    repeated calls.

Introduce two new MSBuild properties:

  * `$(AndroidAvoidEmitForPerformance)` to toggle both
    `Microsoft.Extensions.DependencyInjection.DisableDynamicEngine` and
    `Switch.System.Reflection.ForceInterpretedInvoke`. This is a public
    property that defaults to `true`.

  * `$(_SystemDiagnosticsMetricsMeterIsSupported)` to toggle
    `System.Diagnostics.Metrics.Meter.IsSupported`.  This is a private
    property that defaults to `false`.

I added a test to check `System.Diagnostics.Metrics.Meter.IsSupported`
at runtime.  I did not do this with Microsoft.Extensions, as we'd have
to add a reference to the NuGet package and track its version for
nightly builds.

I also updated the AOT profile, and some
`System.Diagnostics.Metrics.Meter` API calls are now gone:

	bool System.Diagnostics.Metrics.Meter:AddInstrument (System.Diagnostics.Metrics.Instrument)
	object System.Diagnostics.Metrics.Instrument:get_SyncObject ()
	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.Counter`1<long> System.Diagnostics.Metrics.Meter:CreateCounter (string,string,string)
	void System.Diagnostics.Metrics.MeterListener:.cctor ()
	void System.Diagnostics.Metrics.MetricsEventSource:.cctor ()
	void System.Diagnostics.Metrics.MetricsEventSource:.ctor ()
@ghost ghost locked as resolved and limited conversation to collaborators Oct 16, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

No branches or pull requests