Single file start time regression

[sebastienros]

With SDK builds taken between 4/8 and 4/10 we noticed a regression in startup time for applications published as single files.

Environment:

• This was reproduced only on Windows (Linux is not affected) and can still be consistently. Same machine, Windows Defender disabled on the folder starting the app. Same parent folder between runs, though any AV should happen the same way on both builds.
• Not specific to a single app
• Here showing ASP.NET application without DI or middleware (Platform benchmark)

SDK versions:
10.0.100-preview.4.25207.27
10.0.100-preview.4.25209.44

black: single file
blue: trimmed
yellow: aot
pink: self-contained

I have the executables built for the two SDKs. Contact me on Teams if you want them.

Crank command lines for reference:

crank --config https://raw.githubusercontent.com/aspnet/Benchmarks/main/scenarios/platform.benchmarks.yml --scenario json --profile aspnet-citrine-win --application.buildArguments "/p:PublishReadyToRun=true /p:PublishSingleFile=true" --application.framework net10.0 --application.options.collectCounters true --load.options.reuseBuild true --application.aspNetCoreVersion 10.0.0-preview.4.25181.4 --application.runtimeVersion 10.0.0-preview.4.25174.9 --application.sdkVersion 10.0.100-preview.4.25207.27 --profile short --application.options.fetch true

crank --config https://raw.githubusercontent.com/aspnet/Benchmarks/main/scenarios/platform.benchmarks.yml --scenario json --profile aspnet-citrine-win --application.buildArguments "/p:PublishReadyToRun=true /p:PublishSingleFile=true" --application.framework net10.0 --application.options.collectCounters true --load.options.reuseBuild true --application.aspNetCoreVersion 10.0.0-preview.4.25208.1 --application.runtimeVersion 10.0.0-preview.4.25209.9 --application.sdkVersion 10.0.100-preview.4.25209.44 --profile short --application.options.fetch true

[filipnavara]

Presumably that's x64, right? (ie. not x86, not arm64)

[sebastienros]

@filipnavara In this case INTEL X64 Windows.

[dotnet-policy-service]

Tagging subscribers to this area: @agocke, @vitek-karas, @VSadov
See info in area-owners.md if you want to be subscribed.

[elinor-fung]

Slightly narrowed SDK versions:

• 10.0.100-preview.4.25208.4: 186ms
• 10.0.100-preview.4.25208.7: 512ms

singlefilehost is grabbed from the SDK known apphost packs, so that seems to be the version that matters here. Unfortunately, that is still a big range for runtime: 10.0.0-preview.4.25174.9 to 10.0.0-preview.4.25207.7 - 659321f...9559b2a

I haven't figured out how to get a repro that isn't the full build and application run through crank though - which presumably I'd need to try any sort of fix.

When I unzipped the downloaded applications (from application.options.fetch) and then kickoff jobs to just run the executables, I see the same start time for both versions: ~500ms

This is my config:

# crank --config crank-config.yml --scenario json-good --profile aspnet-citrine-win --profile short
# crank --config crank-config.yml --scenario json-bad --profile aspnet-citrine-win --profile short

# readyStateText, arguments and environmentVariables copied from platformbenchmarks
platformbenchmarks-good:
 source:
 localFolder: C:\issues\perf\good-25208.4
 executable: PlatformBenchmarks.exe

platformbenchmarks-bad:
 source:
 localFolder: C:\issues\perf\bad-25208.7
 executable: PlatformBenchmarks.exe

scenarios:
 json-good:
 application:
 job: platformbenchmarks-good

 json-bad:
 application:
 job: platformbenchmarks-bad

[elinor-fung]

I also tried to do a local version of crank's time to readyStateText measurement. I also saw the same elapsed times for both the 'good' and 'bad' versions.

using var process = new Process { StartInfo = startInfo };
var stopwatch = new Stopwatch();
bool found = false;

string readyText = "Application started.";
process.OutputDataReceived += (sender, e) =>
{
 if (e.Data != null && e.Data.StartsWith(readyText))
 {
 stopwatch.Stop();
 found = true;
 }
};

Console.WriteLine($"{startInfo.FileName}");
stopwatch.Start();
process.Start();
process.BeginOutputReadLine();
while(!found)
{
 Thread.Sleep(100);
}
process.Kill();
Console.WriteLine($" Start time (ms): {stopwatch.ElapsedMilliseconds}");

[elinor-fung]

I passed --application.collect true --application.collectStartup true to get traces (for the full build / run jobs, where this repros). Unfortunately, >70% of the stacks are reported as broken for both traces.

When I unzipped the downloaded applications (from application.options.fetch) and then kickoff jobs to just run the executables, I see the same start time for both versions: ~500ms

Another thing to note is that the 500ms from just running the output from the jobs from the base and regressed versions is on par with the reported regressed time when the job is to build/publish and run. It almost seems like a first run thing (single-file does pass assemblies to AMSI), but I'm not sure how that would happen.

Locally, if I try a similar build+run of the PlatformBenchmarks project and measure two executions of the output as in #116318 (comment), the first run is ~550ms and the second ~200ms. But I see the same thing for both 25208.4 and 25208.7

[elinor-fung]

@sebastienros Is there any way to make crank use/upload a local SDK or patch a file in the one it downloads?

I haven't been able to figure out a local repro or get traces that aren't largely broken stacks (they show a difference in blocked time, but the stacks are too broken to see from what), but I think I may have narrowed it down a bit via trying different jobs with crank.

• PlatformBenchmarks project with a commit that allows updating the KnownAppHostPack 10.0 version (corresponds to the singlefilehost that is used)
• Ran jobs for the 10.0.0-preview.4.25207.7 runtime libraries and singlefilehost with the 10.0.100-preview.4.25208.4 and 10.0.100-preview.4.25208.7 SDKs - verified that both were using the 10.0.0-preview.4.25207.7 runtime libraries and singlefilehost
• Saw the start time regression with just the SDK version difference.

That leaves the SDK itself as the only difference - dotnet/sdk@e378cb0...d4bbb19 - the dotnet/runtime update looks like the only interesting change. The only thing I could see that was changed there was Microsoft.NET.HostModel in edb0a06. That changed to writing out a temporary file for the bundle and then copying over the existing file (instead of updating it in place). I have no idea why that would change the start time on Windows, but it is the one thing I see that is shipped via the SDK and only affect single-file. That behaviour is also going to be changing with #116659 (cc @jtschuster)

If there's some way to kick off a crank job with a local/patched SDK, we could see if Microsoft.NET.HostModel is actually the difference in those runs.