Sdk: CLR performance Linux versus Windows

[janvorli]

@polarapfel commented on Tue Apr 04 2017

Hi there,

Running version 1.0.1, creating a new console application using the default template, I noticed that the CLR takes up to two seconds on Linux to initialize before executing the "Hello World" binary from the default template. On Windows (same machine spec), the execution is instant.

Is this a known issue?

thanks,

Tobias W.

---

@benaadams commented on Tue Apr 04 2017

What if you build first?

dotnet restore
dotnet build -c Release
dotnet run -c Release

---

@polarapfel commented on Tue Apr 04 2017

Yes. Still takes two seconds to initialize the CLR before the binary executes. Both the release and the debug binaries compiled with dotnet run instantly on the latest Mono runtime on the same Ubuntu system.

---

@polarapfel commented on Tue Apr 04 2017

@shahid-pk I ran against both for comparison.

On the same Ubuntu system, a binary compiled with dotnet (both release and debug) have different execution times on the dotnet CLR Windows versus Linux. The binary on Windows starts executing instantly after invoking the CLR. The binary on Linux has to wait around 2 seconds for the CLR to initialize (I know because I put a Console.Write with the system timestamp into main()).

Doing the same comparison on Linux with the dotnet CLR versus the Mono runtime, the binary executes instantly on Mono, the dotnet CLR takes around 2 seconds to initialize before it executes the binary.

This is bad and cannot be intentional. I didn't find any tickets pointing to this issue but I'm sure someone else must have noticed?!

thanks,

Tobias W.

---

@janvorli commented on Tue Apr 04 2017

@polarapfel It seems it is specific to the dotnet run. If I run hello world using just dotnet with path to the target dll, it takes about 100 ms to complete:

time ../dotnet ~/dotnet/test/bin/Release/netcoreapp1.1/test.dll
Hello World!

real    0m0.090s
user    0m0.079s
sys     0m0.011s

However, running it via the dotnet tool using dotnet run command, I can reproduce the time you were getting:

time ../dotnet run -c Release
Hello World!

real    0m2.329s
user    0m2.228s
sys     0m0.260s

---

@polarapfel commented on Tue Apr 04 2017

Yeah, that's right. Curious. Why is that? What happens when the "run" command is invoked within the CLR?

And also, why does the "run" command behave so differently on Windows (fast/instant) versus Linux (slow init)?

---

@janvorli commented on Tue Apr 04 2017

@polarapfel let me move this issue to cli repo since it is clearly a problem of the cli.

[janvorli]

CC: @piotrpMSFT - it looks like the dotnet run command does something that takes a long time to complete before it actually runs the target app.

[livarcocc]

Explaining why dotnet run is slower than dotnet is easy. Here is what dotnet run does for you:

• It builds your application, if it needs to. But keep in mind that even checking if the build is needed takes time. Though this is handled in MSBuild.
• It evaluates your csproj to determine how to run your application.
• It actually invokes your application (this is the piece that would be similar do dotnet .

As for the performance differences between Windows and Linux, that's not clear to me. The code is the same for both platforms.

@rainersigwald @agocke have you guys noticed or heard about any msbuild perf differences between Windows and Linux that could explain this?

[polarapfel]

@livarcocc @rainersigwald @agocke The 2 second delay after invoking dotnet on Linux happens also when the binaries already exist from a prior build.

I don't have a Mac. Can someone try this in Bash on a Mac please (see how @janvorli) demonstrated this earlier in the thread.

[livarcocc]

@polarapfel I understand that, but even when a build already exists, from my steps above, we still need to do the incremental check to see if a new build is needed and then we still need to evaluate the project to determine how to invoke the application.

[dasMulli]

There are some performance measurements for incremental builds in https://github.com/dotnet/cli/issues/5918

[polarapfel]

@livarcocc

All things being equal, the runtime performance of dotnet run should not be that dramatically different in between platforms. There's probably something within these steps that relies on a library that's optimized for Windows and performs badly on Linux.

Trying the same in the WSL (Bash on Windows) renders times in the 4 to 8 seconds btw.

I'm not familiar how the CLR and CoreFX are built themselves and how to debug them, but this particular scenario needs to be looked at and stepped through on a Linux machine to profile where execution time is being spent.

[janvorli]

Here are results from Raspberry PI provided by @jyoungyun - the difference is much more profound here:

pi3@raspberry:~/Downloads/c$ time dotnet run
Hello World!

real    0m44.373s
user    0m56.000s
sys 0m1.800s

pi3@raspberry:~/Downloads/c$ time dotnet /home/pi3/Downloads/c/bin/Debug/netcoreapp2.0/c.dll
Hello World!

real    0m1.389s
user    0m1.340s
sys 0m0.040s

[tmds]

Is MSBuild ngen-ed on Windows?

[janvorli]

@tmds I believe it is crossgen-ed on both Windows and Linux x64

[tmds]

@janvorli how can I/we check if msbuild&csc are crossgen-ed?

[janvorli]

@tmds on Linux, you can use the "file" command. For crossgen-ed dlls, it will print (on x64 Linux):
PE32+ executable (DLL) (console) x86-64 Mono/.Net assembly, for MS Windows
For IL one, it will print
PE32 executable (DLL) (console) Intel 80386 Mono/.Net assembly, for MS Windows

On Windows, you can use the dumpbin command from the visual studio command prompt. dumpbin /HEADERS file.dll will print out info on all the sections and in the optional header, you will either see 20B magic # (PE32+) for crossgen-ed or 10B magic # (PE32) for IL.

[tmds]

@janvorli Thanks, on my system, things are crossgen-ed.

/opt/dotnet/sdk/2.0.0-preview1-005807$ file Microsoft.CodeAnalysis.CSharp.dll
Microsoft.CodeAnalysis.CSharp.dll: PE32+ executable (DLL) (console) Mono/.Net assembly, for MS Windows
/opt/dotnet/sdk/2.0.0-preview1-005807$ file MSBuild.dll
MSBuild.dll: PE32+ executable (DLL) (console) Mono/.Net assembly, for MS Windows

When I (on hello world console app)

export COMPlus_PerfMapEnabled=1
perf record -F 97 -ag dotnet exec /opt/dotnet/sdk/2.0.0-preview1-005807/MSBuild.dll /m /v:m /t:Build /clp:Summary /Logger:Microsoft.DotNet.Tools.MSBuild.MSBuildLogger,/opt/dotnet/sdk/2.0.0-preview1-005807/dotnet.dll
perf report

I see things show up like:

System.Runtime.CompilerServices.AsyncTaskMethodBuilder
CILJit::compileMethod

which is unexpected since the project has already been built and things are crossgen-ed.

[tmds]

Is this a dup of https://github.com/dotnet/cli/issues/5918?

[dmbarbour]

Just a note:
dotnet run eventually calls dotnet exec bin/Debug/netcoreapp.1.1/app.dll

A fresh build is very slow, as you might expect.

> dotnet clean
> time dotnet run 
Hello World from F#!

real    0m4.716s
user    0m4.216s
sys 0m0.380s

It's a fair bit faster on subsequent runs, but still awfully slow.

> time dotnet run
Hello World from F#!

real    0m1.424s
user    0m1.300s
sys 0m0.084s

But if we call the executable directly...

> time dotnet exec bin/Debug/netcoreapp1.1/app.dll
Hello World from F#!

real    0m0.051s
user    0m0.040s
sys 0m0.008s

So it seems the problem is somewhere in the dotnet-run code. Hypothesis: Maybe something to do with the verification that the assembly is up-to-date.

[dmbarbour]

@tmds It seems dotnet/sdk#7850 is about build times, whereas this one is about the painful delay between dotnet run and dotnet exec.

[tmds]

@tmds It seems dotnet/sdk#7850 is about build times, whereas this one is about the painful delay between dotnet run and dotnet exec.

dotnet run = dotnet build + dotnet exec

[dmbarbour]

@tmds Okay, now I know some more underlying details. We could probably greatly improve dotnet build to check dependencies first, as per dotnet/sdk#7850. That said, there's still a ~20% performance advantage to dotnet build && dotnet exec ... over dotnet run across a few simple tests (both single and multi-project):

time (dotnet build && dotnet exec bin/Debug/netcoreapp1.1/tst.dll)
time (dotnet run)

I wonder where else dotnet run is wasting time?

[dasMulli]

@dmbarbour @tmds which version are you using? in 2.0 preview 2 dotnet run is restore + build + exec. (with NuGet having implemented incremental restore)

[dmbarbour]

@dasMulli 1.0.4

[dasMulli]

Another difference between run and build + exec is that run also evaluates the project to determine the command to run (by evaluating the properties RunCommand, RunArguments, and RunWorkingDirectory from the project which are defaulted by the SDK).

This causes MSBuild to at least perform an additional evaluation of the project, including expansion of all globbing patterns which is slow on large projects.

Maybe something can be done here to only evaluate once, e.g. reuse the Project instance after the build has been performed to get the final values of the properties used to run the project.

[livarcocc]

I like the suggestion of not re-evaluating the project after build to discover the run command. We also improved the build time by running restore in-proc with the build process, instead of in a separate one.

@peterhuene I think this might be an interesting one to you. Making dotnet run not re-evaluate the project after build.

[dasMulli]

@livarcocc @peterhuene Is it reasonable to ask for RunCommand/… be evaluated after calling some target (e.g. a new PrepareForRun)? That could open up adding msbuild logic to generate these settings - for example to forward to other projects by setting default projects via after.nameofthe.sln.targets.

[jobs-git]

The problem might not be on mono or dotnet run. Its because Linux's library resolution is retard.

Specially the ld.so, that is were most of the slowness comes from!

I benchmark one program, its a big big program by the way, and ld.so resolution takes up about 80% of the 30min-1hr runtime!

F** who designed the ld.so, its so retard! Now for mono, somebody got to find its "ld.so" counterpart and fix it! :)

[neooleg]

@jobs-git thanks a lot for such investigation shared here!
Can you provide more details -- how did you benchmark?

We have the same issue (.NET Core app slower on Linux than on Windows env) with 2.0 (originally this issue reported for 1.0). I would like to benchmark on our app.

Thanks!

[livarcocc]

We have a PR with an improvement to dotnet run perf by not doing globbing for the evaluation we do to determine the run command.

As for .NET Core being slower on Linux vs Windows, I suggest filling an issue on coreclr or core-setup.

Given that, I am going to close this issue.

[AndrewSav]

As for .NET Core being slower on Linux vs Windows, I suggest filling an issue on coreclr or core-setup.

I think this one is specifically about cli being slower on linux.

We have a PR with an improvement to dotnet run perf by not doing globbing for the evaluation we do to determine the run command.

It is not clear if that PR resolves this particular issue. It would be more logical to wait for the PR to come through, get this retested after it's done and _then_ close when we know that it was resolved this way.

As it stands this closure feels a bit premature.

[livarcocc]

We have two other issues tracking the dotnet run explicit problem and it feels like it got globbed together on this conversation to begin with.

[AndrewSav]

@livarcocc it would certainly help if you could list these other issues here, for people who used to track this issue and what to track those ones you mentioned. Thanks.

[livarcocc]

https://github.com/dotnet/cli/issues/8103
https://github.com/dotnet/cli/issues/7610
https://github.com/dotnet/cli/issues/7551