dotnet / sdk

Core functionality needed to create .NET Core projects, that is shared between Visual Studio and CLI
https://dot.net/core
MIT License
2.65k stars 1.05k forks source link

dotnet run of hello world takes way too long #8697

Closed ericstj closed 3 years ago

ericstj commented 7 years ago

Reported by @migueldeicaza

Steps to reproduce

  1. dotnet new console
  2. dotnet build
  3. dotnet run

Expected behavior

dotnet run executes fast, nearly the same as calling dotnet <pathToDll>

Actual behavior

dotnet run is slow, about 3 seconds on my machine. It's consistently this slow, even when it doesn't need to rebuild.

It appears that run is calling msbuild twice before actually running the app: image

Can't we have a fast-path here that bypasses MSBuild? It seems like we've optimized for incremental build via the run command which I'm not sure is really the primary workflow for run (but I may be wrong).

omajid commented 7 years ago

I believe dotnet run --no-build will help here. Maybe it should be the default.

wli3 commented 7 years ago

@livarcocc do we know the cause? if no i'd like to do some performance profile for this case

warrenrumak commented 7 years ago

If you want to run your application after it's already been compiled, do this: dotnet bin\debug\netcoreapp2.0\ncc.dll

This is much quicker than using dotnet run, with or without --no-build, because dotnet doesn't need to spending time figuring out which file contains the startup object.

ericstj commented 7 years ago

I understand that, I'm suggesting that perhaps dotnet run should do something closer to that, since it seems to be the expectation. Anyone know what other frameworks CLI's do here?

eerhardt commented 7 years ago

Hmm, there may be something wrong with your machine. Here's what I am seeing on mine with

PS F:\DotNetTest\HelloWorld> dotnet --info
.NET Command Line Tools (2.0.0)

Product Information:
 Version:            2.0.0
 Commit SHA-1 hash:  cdcd1928c9

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.15063
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Program Files\dotnet\sdk\2.0.0\

Microsoft .NET Core Shared Framework Host

  Version  : 2.0.0
  Build    : e8b8861ac7faf042c87a5c2f9f2d04c98b69f28d

NOTE: I've already done a build.

PS F:\DotNetTest\HelloWorld> Measure-Command { dotnet run }

TotalSeconds      : 1.8731543

PS F:\DotNetTest\HelloWorld> Measure-Command { dotnet run --no-build }

TotalSeconds      : 0.3443567

PS F:\DotNetTest\HelloWorld> Measure-Command { dotnet .\bin\Debug\netcoreapp2.0\HelloWorld.dll }

TotalSeconds      : 0.0428232

I think the expectation of dotnet run is that it works like F5 in VS. You don't need to build in VS before hitting F5. If the project is out of date, it gets built. Also, just like dotnet build changed to ensure your project is restored correctly by default, dotnet run ensures your project is built by default. Both of these allow you to turn it off when you know you don't need it: --no-restore, --no-build.

Either way, 3 seconds is too long. Can you post a dump of the MSBuild Performance Summary of an incremental build? For example:

Project Evaluation Performance Summary:
      184 ms  F:\DotNetTest\HelloWorld\HelloWorld.csproj   1 calls

Project Performance Summary:
      856 ms  F:\DotNetTest\HelloWorld\HelloWorld.csproj   1 calls
                856 ms  Build                                      1 calls

Target Performance Summary:
        0 ms  ResolveReferences                          1 calls
        0 ms  BeforeResGen                               1 calls
...
ericstj commented 7 years ago

That's on the same order of magnitude that I'm seeing, things slow down a bit when I procmon it, but measuring build and run gives me similar numbers. I would call that too much time for a command called run on a hello world that's already built. I would expect something closer to the --no-build time for an already built project.

eerhardt commented 7 years ago

Which one is too much? 1.8s or 0.344s?

ericstj commented 7 years ago

1.8s: I'd expect that to be closer to 0.344s

omajid commented 6 years ago

Can the undocumented dotnet exec (https://github.com/dotnet/cli/issues/2243) work as a solution?

ericstj commented 6 years ago

Not if user expects run to do only a run without a build... The workaround is already to run with --no-build or point the host directly at the application: we don't need more workarounds. This is issue is about validating the assumption that the majority of users expect run to also do a build. I've seen enough cases where people don't expect this to question that assumption.

Furthermore, the console spew is so minimal that the user doesn't even realize they are getting an incremental build + run. Even fixing that could make it feel a bit more natural. As it is now it just looks like we're incredibly slow to run helloworld.

eerhardt commented 6 years ago

One thing that came in for 2.0 was the implicit restore feature. This appears to have added at least half a second to the scenario. On the same machine as above on an already built project:

PS F:\DotNetTest\HelloWorld> Measure-Command { dotnet build --no-restore }

TotalSeconds      : 0.9844525

PS F:\DotNetTest\HelloWorld> Measure-Command { dotnet build }

TotalSeconds      : 1.5361392

So 33% of the 1.8s vs 0.3s difference is just the call to implicitly restore.

Of the remaining time to just build, the biggest culprit is ResolveAssemblyReferences (tracked by https://github.com/Microsoft/msbuild/issues/2015):

PS F:\DotNetTest\HelloWorld> dotnet build --no-restore /clp:PerformanceSummary
Microsoft (R) Build Engine version 15.3.409.57025 for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

  HelloWorld -> F:\DotNetTest\HelloWorld\bin\Debug\netcoreapp2.0\HelloWorld.dll

Project Evaluation Performance Summary:
      160 ms  F:\DotNetTest\HelloWorld\HelloWorld.csproj   1 calls

Project Performance Summary:
      575 ms  F:\DotNetTest\HelloWorld\HelloWorld.csproj   1 calls
                575 ms  Build                                      1 calls

Target Performance Summary:
        1 ms  ResolveProjectReferences                   1 calls
        1 ms  _ComputeTFMOnlyFileDependencies            1 calls
        1 ms  _ComputeNETCoreBuildOutputFiles            1 calls
        1 ms  GetAssemblyVersion                         1 calls
        1 ms  IncrementalClean                           1 calls
        1 ms  AssignTargetPaths                          1 calls
        1 ms  SplitResourcesByCulture                    1 calls
        1 ms  _SetEmbeddedWin32ManifestProperties        1 calls
        1 ms  _CheckForInvalidConfigurationAndPlatform   1 calls
        2 ms  CopyFilesToOutputDirectory                 1 calls
        2 ms  PrepareForBuild                            1 calls
        2 ms  _GetProjectReferenceTargetFrameworkProperties   1 calls
        3 ms  _GenerateCompileDependencyCache            1 calls
        3 ms  CheckForDuplicateItems                     1 calls
        3 ms  _CleanGetCurrentAndPriorFileWrites         1 calls
        4 ms  CoreCompile                                1 calls
        4 ms  _ComputeLockFileCopyLocal                  1 calls
        4 ms  _ComputeLockFileReferences                 1 calls
        9 ms  CheckForImplicitPackageReferenceOverrides   1 calls
       12 ms  _CollectTargetFrameworkForTelemetry        1 calls
       13 ms  FindReferenceAssembliesForReferences       1 calls
       13 ms  RunProduceContentAssets                    1 calls
       17 ms  ResolveLockFileReferences                  1 calls
       22 ms  RunResolvePackageDependencies              1 calls
       27 ms  _HandlePackageFileConflicts                1 calls
       51 ms  ReportAssetsLogMessages                    1 calls
      362 ms  ResolveAssemblyReferences                  1 calls

Task Performance Summary:
        1 ms  GetFrameworkPath                           1 calls
        1 ms  GetAssemblyVersion                         1 calls
        1 ms  AssignTargetPath                           5 calls
        1 ms  WriteLinesToFile                           2 calls
        1 ms  Hash                                       2 calls
        1 ms  ReadLinesFromFile                          1 calls
        1 ms  MakeDir                                    1 calls
        1 ms  FindUnderPath                              5 calls
        1 ms  Message                                    3 calls
        1 ms  Copy                                       2 calls
        1 ms  MSBuild                                    1 calls
        1 ms  CheckForTargetInAssetsFile                 1 calls
        2 ms  Telemetry                                  1 calls
        3 ms  CheckForDuplicateItems                     3 calls
        5 ms  CheckForImplicitPackageReferenceOverrides   1 calls
       11 ms  ProduceContentAssets                       1 calls
       20 ms  ResolvePackageDependencies                 1 calls
       25 ms  ResolvePackageFileConflicts                1 calls
       51 ms  ReportAssetsLogMessages                    1 calls
      361 ms  ResolveAssemblyReference                   1 calls

Build succeeded.
    0 Warning(s)
    0 Error(s)

Time Elapsed 00:00:00.77

I assume the rest of the time is just overhead of spinning up processes and loading assemblies.

eerhardt commented 6 years ago

On a separate note, I am pushing for https://github.com/dotnet/cli/issues/2960 to get implemented in 2.1. In general - allow the CLI to be configurable. Once that happens, a configuration that could be set would be "what default dotnet run experience do you want?". Users who know they will always build before they call dotnet run can configure it to be --no-build. Users who don't want to bother with ensuring their project is already built before calling run can configure it to be --ensure-built.

Then it is just a matter of picking the default/unconfigured option and letting users change it if the default isn't what they want.

svick commented 6 years ago

@ericstj

the console spew is so minimal that the user doesn't even realize they are getting an incremental build + run. Even fixing that could make it feel a bit more natural.

If I'm writing a console application, I like that something like dotnet run > app.log 2> app.err produces the same output as dotnet app.dll > app.log 2> app.err. It means I can debug the console output using dotnet run and don't have to use dotnet publish.

tmds commented 6 years ago

This was reported some months ago with the switch to the msbuild project system: https://github.com/dotnet/cli/issues/5918. Last comment links to https://github.com/dotnet/project-system/issues/2789.

eiva commented 6 years ago

Strange, but --no-build doesn't help...

time dotnet run --no-build
Hello World!

real    0m2.326s
user    0m0.406s
sys     0m0.875s
dotnet --version
2.1.3
olsonpm commented 6 years ago

To give a new user's perspective: I just downloaded .net core today on my arch machine. Got here for the same reason as OP - dotnet run is unexpectedly slow. --no-build has an acceptable time though it's still not instant which is what I expect on subsequent runs. I think it's worth noting the first time I ran the command I wasn't surprised because I suspected it was due to building the executable. Subsequent runs however did surprise me.

Edit: I don't mean to infer my use-case should be supported or that my expectation speaks for everyone.

karlmayer commented 6 years ago

I'm here for the same reason as olsonpm.

Measure-Command { dotnet run }
TotalMilliseconds : 2334.6173

Measure-Command { dotnet run --no-restore --no-build }
TotalMilliseconds : 512.5228

Measure-Command { dotnet .\bin\Debug\netcoreapp2.0\HelloWorld.dll }
TotalMilliseconds : 57.7411
dasMulli commented 6 years ago

@karlmayer which version of the .NET Core SDK (dotnet --version) have you been using for that?

The current Preview 1 for .NET Core 2.1 (SDK Version 2.1.300-preview1-…) should give better results now, with some improvement still to come:

https://www.hanselman.com/blog/MajorBuildSpeedImprovementsTryNETCore21Preview1Today.aspx https://blogs.msdn.microsoft.com/dotnet/2018/02/27/announcing-net-core-2-1-preview-1/

karlmayer commented 6 years ago

@dasMulli, I'm on .NET Core 2.1.100. Preview 1 looks promising -- thanks for the heads up! If I didn't have to upgrade Visual Studio to Preview as well, I'd switch over.

davkean commented 6 years ago

As a heads up, more improvements have been made in Preview 2 - https://blogs.msdn.microsoft.com/dotnet/2018/04/11/announcing-net-core-2-1-preview-2/.

I'll let the graph speak for itself:

image

perlun commented 6 years ago

@davkean That's nice stuff indeed! The graph speaks about "incremental build" though; does it really have to build anything if "last modified of */.cs" < "last modified of output.dll"? (Note: I know absolutely nothing about how the underlying implementation looks in this case, merely scratching the surface as an innocent bystander.)

(What I mean to say: checking the file dates of all affected files and comparing with the target file should be much less than 10s on any reasonably-sized project on a normal SSD disk.)

davkean commented 6 years ago

In effect that's what it's doing, there's just overhead in:

Lots of above improvements is just being smart around trying to get to the "are they are up-to-date" as quick as possible.

dasMulli commented 6 years ago

@perlun That's pretty much how the underlying build framework (MSBuild) works.

"Incremental Build" refers to additional builds started after an initial build. During this "incremental build", steps like compiling C# code can be skipped if the output is "up to date" (when outputs of a step are not older than the inputs to the step).

The recent efforts of the team included both "classic perf work" on existing code (e.g. a community PR made MSbuild's directory scanning much faster) as well as reducing duplicated work in incremental builds - loading cached outputs if the inputs didn't change. This also makes incremental builds much faster even if C# code needs to be recompiled, but maybe your referenced NuGet packages and other projects didn't change and MSBuild doesn't need to resolve potential conflicts of same assemblies in different versions again, or search for additional dependencies it found in the first build.

davkean commented 6 years ago

I think the interesting thing here, is that if MSBuild was a closed system, I'm pretty damn confident we could make this blazingly fast. It's not. By design, it's an open extensible system and any package, SDK, project can and do supplement the build process. We have to be able to identify performance issues and fix each individual step in the process and do it in a way that makes sure you projects still build in the same ways. It's challenging but its really rewarding to see the 10s of devs involved in this pipeline to all rally around a single goal to make builds as fast as possible.

Looooooka commented 6 years ago

With the latest 2.1 update and VS update the debugging got super slow. I believe it was promised it would actually get faster not slower. The interesting part is NET Core 2.1 can actually handle more concurrent connections so at least that itself is indeed faster...but man after running debug on an upgraded project I feel like I'm running Crysis in the background.

davkean commented 6 years ago

@Looooooka Can you please Help -> Send Feedback -> Report a Problem from and record the "slow" debugging? This will give us traces/data underneath that will help us identify the cause.

wesley-firewalla commented 6 years ago

It is quite slow when I just run the Console.WriteLine("Hello World!"); on Macos.

argentini commented 5 years ago

Yes, my dotnet core console app renders console output in Ubuntu Linux SUPER slowly. It's threaded, so my app finishes and beeps as the writes are still slowly being rendered for 30 seconds or more.

ericstj commented 5 years ago

@wenbinke and @argentini can you clarify if you are seeing slowness just in dotnet run and not dotnet ? That's what this issue is about. That slowness is related the cost of an incremental build before running the app.

If you are seeing slow execution when directly starting the app.dll then please file an issue on http://github.com/dotnet/corefx with full repro steps and we can investigate.

argentini commented 5 years ago

Sorry, yes, my comment was with regard to dotnet core app output to the console, not performance of "run" versus a build. Sorry about that.

ericstj commented 5 years ago

No need to apologize, it actually sounds like a potential issue in System.Console. I know folks have been working on the unix console implementation a lot lately so you should make sure they are aware of that. @wtgodbe @stephentoub

wesley-firewalla commented 5 years ago

@wenbinke and @argentini can you clarify if you are seeing slowness just in dotnet run and not dotnet ? That's what this issue is about. That slowness is related the cost of an incremental build before running the app.

If you are seeing slow execution when directly starting the app.dll then please file an issue on http://github.com/dotnet/corefx with full repro steps and we can investigate.

Hi @ericstj ,

I created the console project with code.cs. then run dotnet run code.cs. It takes a few seconds to finish. I expect it could be done in 50ms.

code.cs

using System;

namespace Hello
{
    class Program
    {
        static void Main(string[] args)
        {
            Console.WriteLine("Hello World!");
        }
    }
}

code.csproj

<Project Sdk="Microsoft.NET.Sdk">
<PropertyGroup>
  <OutputType>Exe</OutputType>
  <TargetFramework>netcoreapp2.1</TargetFramework>
</PropertyGroup>
</Project>
ericstj commented 5 years ago

@wenbinke is that just the first time or every time? What do you see when directly running the built dll? I’d expect the first time to take longer because the compiler has to run. Subsequent times I’d expect to be comparable to directly running the built dll. That’s what this issue is about.

wesley-firewalla commented 5 years ago

@wenbinke is that just the first time or every time? What do you see when directly running the built dll? I’d expect the first time to take longer because the compiler has to run. Subsequent times I’d expect to be comparable to directly running the built dll. That’s what this issue is about.

@ericstj I meant "every time". Now I run dotnet run code.dll it also takes long time every time.

ericstj commented 5 years ago

Can you confirm you are doing DotNet code.dll and not DotNet run code.dll and still seeing slow startup? If so that’s a different issue as I mentioned, and you should open an issue in the corefx repo.

wesley-firewalla commented 5 years ago

Can you confirm you are doing DotNet code.dll and not DotNet run code.dll and still seeing slow startup? If so that’s a different issue as I mentioned, and you should open an issue in the corefx repo.

@ericstj , dotnet code.dll is fast. but dotnet run code.dll is slow. I think it is easy to reproduce by yourself.

# macOS High Sierra Version 10.13.6

dotnet --version
2.1.402
dirq commented 5 years ago

I have the same problem. Using the "play" button for debugging a dotnet core console app runs very very slow. CDing to the projects bin debug folder and running dotnet code.dll runs fast. Running the published version outside of debugging also runs fast.

dotnet --version 2.1.402

Visual Studio Microsoft Visual Studio Enterprise 2017 Version 15.8.6 VisualStudio.15.Release/15.8.6+28010.2041

ORESoftware commented 5 years ago

I am new to F#, I played with OCaml for a few days before trying out F#, OCaml programs start pretty much instantly using dune

https://medium.com/@bobbypriambodo/starting-an-ocaml-app-project-using-dune-d4f74e291de8

is there a reason why dotnet takes about 200 ms to startup?

kurtnelle commented 5 years ago

Experiencing the same problem on Debian ARM on my Pocket Beagle (TI Sitara AM335x). dotnet code.dll takes 3 seconds to print the "Hello World", but when run on Windows, it prints almost instantly.

ghost commented 5 years ago

Using dotnet 3.0.100-preview6-012264 , dotnet run takes 8 seconds before my app runs. That is a subsequent run, not the first run. The app is a WPF app.

This delay slows down productivity when developing dotnet app. There is hugh benefit in making dotnet run fast.

bolner commented 5 years ago

It could have an execute option, like dotnet execute in which case it would read the location of the already compiled file from a cached text file. It would update that file after each build or run. Then it would not need to parse through the folders searching for files and file changes.

vvolodin commented 5 years ago

Every refresh of the hello world 3.0-preview7 with angular through UseProxyToSpaDevelopmentServer takes at least 4.5 seconds for me: image

asad-c commented 4 years ago

Every refresh of the hello world 3.0-preview7 with angular through UseProxyToSpaDevelopmentServer takes at least 4.5 seconds for me: image

Having the same issue with preview 8, using the proxy is super slow. Should be able to run the SPA independently but without the proxy the IdentityServer redirects don't work correctly.

MarkusReynolds1989 commented 4 years ago

I was using core 3.0.100-preview9-014004 today on a Windows 10 machine and it's still slow to compile it in powershell. 1.7 seconds to run the simple hello-world project and 0.5 seconds with no-build. If I just run the dll it runs like I'd expect at 0.1 seconds.

hoshyK2 commented 4 years ago

I'd just like to add some timings here... i think it speaks for itself.

time dotnet bin/Debug/netcoreapp3.0/consoleTest.dll

real 0m0.184s user 0m0.109s sys 0m0.078s

time dotnet run bin/Debug/netcoreapp3.0/consoleTest.dll

real 0m6.336s user 0m2.797s sys 0m5.641s

dotnet --version 3.0.100

Ubuntu on Win10... I also see near identical timings with dotnet run on windows command line.

livarcocc commented 4 years ago

The two times above are non-comparable. They are not meant to be equivalent.

dotnet <path_to_dll> is the expected way to run FDD apps and does not require the SDK. It does very little.

Meanwhile, dotnet run is a developer tool equivalent to F5 in VS or some other IDE. It does a bunch of things, like restore and build your project and then, it evaluates it to find the necessary commands to run your app and then finally, using this information, kicks off that process.

While it could, potentially be faster, it will never have the same perf as dotnet <path_to_dll> and that is very much expected.

blaz0r commented 4 years ago

Meanwhile, dotnet run is a developer tool equivalent to F5 in VS or some other IDE. It does a bunch of things, like restore and build your project and then, it evaluates it to find the necessary commands to run your app and then finally, using this information, kicks off that process.

Yeap, totally understood that there's more going on, but you hit the nail on the head with regards to "similar to F5"... hitting F5 I'm sub 1 second and that's including an attached debugger, so 4-5 seconds without the debugger makes for a frustrating dev experience (incidentally, no build and no restore options didn't help).

Anyway, just adding weight as it's putting me off that particular dev experience.

SrMordred commented 4 years ago

Just started learning C#, i'm on a low end machine atm, and i´m already here. I´m very surprised that dotnet run is that slow. Since most of other programming languagues that i work with, that are compile to binary have way faster 'hello world' compilation times.

One thing that i noticed is that build and run the exe is faster than just the run command, which is odd: ( Not the very first build, runned multiple times make sure its cached )

timecmd dotnet run 00:00:03.38

timecmd dotnet build && bin\Debug\netcoreapp3.1\cs.exe 00:00:02.32 ( and off course, first time builds are way slower )

I´m very confused.

mattgreen commented 4 years ago

Find myself in the same boat here. Used C# with VS back in the 2006 era or so and loved the rapid development experience coupled with the IDE. I suspect VS was background compiling files as I changed them.

Now I find myself enjoying C# + dotnet while using MonoGame, but the dev experience is definitely hindered by the slow compile + launch even on very recent hardware.

bailscodesstuff commented 4 years ago

Just started learning C#, i'm on a low end machine atm, and i´m already here. I´m very surprised that dotnet run is that slow. Since most of other programming languagues that i work with, that are compile to binary have way faster 'hello world' compilation times.

I'm in the exact same position as you and had the same thought! Can this issue be resolved, or is it just something we must get used to?