[Solved] WebApplication.CreateBuilder lockup in some Linux envs
Does anybody know why a basic
Microsoft.AspNetCore.Builder.WebApplicationBuilder.Build() call would be terrifyingly slow in certain envs (3-5 minutes for this call alone) while the same code on a different machine is near-instant?
Or if not why, then at least... how to diagnose it? It doesn't emit any debug logs while building as far as I can tell (set loglevel to Trace and nothin).
Only hint I have is that the filesystem in the slow env is pretty high-latency, but it's able to do all other file ops in, well, yknow, seconds or less rather than minutes. The issue isn't replicated on other systems I have that are running the same OS (Ubuntu-ish Linux) but different hardware config.
If it was running locally I'd know how to get a profiler open and figure it out from there, but since I can only replicate on a remote server, I'm a bit stuck on how to diagnose this.17 Replies
seems pretty obvious. Depending on how many file io operations that needs to do, it will be very slow if you have seconds of latency
the direct answer to your question is "trace logging"
add trace logging to your own code as much as possible
and investigate whether the code you're calling has trace logging, and how to enable it
if it's ASP.NET Core stuff, that'll be trivial
capture and analyze traces to figure out where the bottleneck is
yeah, uh, so... how? As mentioned above,
builder.Logging.SetMinimumLevel(LogLevel) with even Trace set outputs nothing for the Build() callLogging in .NET Core and ASP.NET Core
Learn how to use the logging framework provided by the Microsoft.Extensions.Logging NuGet package.
I'll wager "Minimum" level is not the same as "Default" level
MinimumLevel refers to the lowest level of logging that is shown, setting to Trace causes all debugging, Trace and up, to show.
a Default level would one that is used when another level is not specified
LoggingBuilderExtensions.SetMinimumLevel(ILoggingBuilder, LogLevel)...
Sets a minimum LogLevel requirement for log messages to be logged.
Sets a minimum LogLevel requirement for log messages to be logged."minimum requirement" doesn't imply that all sources will be emitting logs that low here's something
Logging in C# - .NET
Learn about app logging provided by the Microsoft.Extensions.Logging NuGet package in C#.
this claims that when resolving whether a log should be included, SetMinimumLevel() has the least priority of anything
there could very well be other configs that are taking precedence
The
SetMinimumLevel call does work, and provides detailed debug logs for most things - just not the Build() callas in,
IWebHost.Build()?Microsoft.AspNetCore.Builder.WebApplicationBuilder.Build()
that's the call that has a significant lockup time. No logs are given until after it's completed and other code is executingprobably because the logger system isn't built until then
probably time to engage some monitoring tools on the host, then
if you suspect the filesystem, you should be able to trace that from the OS-side
I had to do ungodly things involving manual fake-instrumentation and heavy reflection (why must all the relevant code be solution workaround is:
private/internal???) but i tracked it down:
I was slightly off thinking it was Build(), it was actually the line above, WebApplication.CreateBuilder(), which redirects to new WebApplicationBuilder() which internally calls new HostApplicationBuilder(), which internally calls HostingHostBuilderExtensions.ApplyDefaultAppConfiguration(), which calls Configuration.AddJsonFile("appsettings.json", optional: true, reloadOnChange: reloadOnChange) and then again with $"appsettings.{env.EnvironmentName}.json". The delay is constrained to the first of the two calls (AppSettings) and is not repeated in the second (EnvName). Adding these files next to the executable does not change the delay. This does some stuff and then calls configuration.Add(source) which calls IConfigurationProvider provider = source.Build(configuration) which calls new JsonConfigurationProvider which calls source.FileProvider.Watch(source.Path) which locks up
in short: File watchers lock up in some environments, and for some horrible reason AspNetCore registers a filewatcher to look for appsettings.json changing, even if you're in Production environment.
Also for some other horrible reason CreateBuilder, which, yknow, creates a builder... does all the building, registering of file system attachments, etc. which is aggressively not what a Builder should be doing before you call Build.
So the Environment.SetEnvironmentVariable("ASPNETCORE_hostBuilder:reloadConfigOnChange", "false") before you call CreateBuilder
The solution would be MS fixing the utter mess in the aspnetcore codebase. Argh.config file watchers are being constructed in CreateBuilder() because those configs have to exist BEFORE the application is built, because they can drive HOW the application is built
I have indeed heard that file watchers have issues, particularly outside of Windows
definitely submit an issue with regard to the file watcher locking up, if there isn't one already
aside from that, nothing else strikes me as poorly-architected here
config files are monitored for changes, by default, and there's an easy way to change that
read the config file i get, the filewatch is the part that monitors for changes, and that should not be present in a production env, only dev (you don't do on-the-fly fiddling with config files in production!)
the complaint about the mess was more related to the hours i spent digging through Builders that build before the build call through 12 layers of FactoryBuilderFactorySourceProviderBuilder oop hellscape