Slow Razor Build Times #2406

mkArtakMSFT · 2018-06-14T17:59:43Z

From @barrettg on June 5, 2018 16:45

I am experiencing very slow build times after installing the 2.1 SDK on my Windows machine. I'm creating a new project with dotnet new mvc -au Individual and then building with dotnet build /clp:performancesummary. It seems the Razor build engine is the source of the problem:

Copyright (C) Microsoft Corporation. All rights reserved.

  Restore completed in 47.36 ms for C:\GitHub\test\test.csproj.
  test -> C:\GitHub\test\bin\Debug\netcoreapp2.1\test.dll
  test -> C:\GitHub\test\bin\Debug\netcoreapp2.1\test.Views.dll

Project Evaluation Performance Summary:
      294 ms  C:\GitHub\test\test.csproj                 3 calls

Project Performance Summary:
    43474 ms  C:\GitHub\test\test.csproj                 7 calls
                260 ms  Restore                                    1 calls
                  0 ms  _IsProjectRestoreSupported                 2 calls
                  1 ms  _GenerateRestoreProjectPathWalk            1 calls
                 21 ms  _GenerateRestoreGraphProjectEntry          1 calls
                  4 ms  _GenerateProjectRestoreGraph               1 calls
              43187 ms  Build                                      1 calls

Target Performance Summary:
        0 ms  ResGen                                     1 calls
        0 ms  _RazorPrepareForRun                        1 calls
        0 ms  PrepareResourceNames                       1 calls
        0 ms  PrepareForRazorCompile                     1 calls
        0 ms  Compile                                    1 calls
        0 ms  PrepareResources                           1 calls
        0 ms  GetReferenceAssemblyPaths                  1 calls
        0 ms  ResolvePackageDependenciesForBuild         1 calls
        0 ms  ResolveRazorCompileInputs                  1 calls
        0 ms  PrepareProjectReferences                   1 calls
        0 ms  BeforeBuild                                1 calls
        0 ms  AfterBuild                                 1 calls
        0 ms  _GenerateRazorAssemblyInfo                 1 calls
        0 ms  _CopySourceItemsToOutputDirectory          1 calls
        0 ms  GenerateRazorTargetAssemblyInfo            1 calls
        0 ms  CreateSatelliteAssemblies                  1 calls
        0 ms  GetFrameworkPaths                          1 calls
        0 ms  BeforeResGen                               1 calls
        0 ms  InitializeSourceControlInformation         1 calls
        0 ms  SetWin32ManifestProperties                 1 calls
        0 ms  GenerateUserSecretsAttribute               1 calls
        0 ms  CreateCustomManifestResourceNames          1 calls
        0 ms  PrepareForRun                              1 calls
        0 ms  BeforeCompile                              1 calls
        0 ms  BeforeResolveReferences                    1 calls
        0 ms  GenerateAssemblyInfo                       1 calls
        0 ms  CoreBuild                                  1 calls
        0 ms  AfterCompile                               1 calls
        0 ms  AfterResGen                                1 calls
        0 ms  RazorCompile                               1 calls
        0 ms  AfterResolveReferences                     1 calls
        0 ms  AddSourceRevisionToInformationalVersion    1 calls
        0 ms  RazorGenerate                              1 calls
        0 ms  _GetRestoreSettingsCurrentProject          1 calls
        0 ms  _GenerateRestoreProjectPathItemsCurrentProject   1 calls
        0 ms  PrepareForRazorGenerate                    1 calls
        0 ms  GetTargetPath                              1 calls
        0 ms  _GenerateProjectRestoreGraph               1 calls
        0 ms  _DefaultMicrosoftNETPlatformLibrary        1 calls
        0 ms  _GenerateRestoreGraphProjectEntry          1 calls
        0 ms  _GenerateRestoreDependencies               1 calls
        0 ms  _GenerateProjectRestoreGraphCurrentProject   1 calls
        0 ms  BuildOnlySettings                          1 calls
        0 ms  EnableIntermediateOutputPathMismatchWarning   1 calls
        0 ms  EnsureTFMCompatibility                     1 calls
        0 ms  _CheckForUnsupportedSelfContained          1 calls
        0 ms  IncludeTransitiveProjectReferences         1 calls
        0 ms  Build                                      1 calls
        0 ms  _SetTargetFrameworkMonikerAttribute        1 calls
        0 ms  ExpandSDKReferences                        1 calls
        0 ms  ResolveSDKReferences                       1 calls
        0 ms  ResolveLockFileAnalyzers                   1 calls
        0 ms  _ResolveGeneratedRazorCompileInputs        1 calls
        0 ms  _BeforeVBCSCoreCompile                     1 calls
        0 ms  CollectPackageReferences                   2 calls
        0 ms  _GetRestoreSettingsOverrides               1 calls
        0 ms  ComputeDependencyFileCompilerOptions       1 calls
        0 ms  _GetRestoreSettingsPerFramework            1 calls
        0 ms  _CheckForObsoleteDotNetCliToolReferences   2 calls
        0 ms  _CopyReferenceOnlyAssembliesForBuild       1 calls
        0 ms  _SplitProjectReferencesByFileExistence     1 calls
        0 ms  RazorGetAssemblyAttributes                 1 calls
        0 ms  _CheckForUnsupportedNETCoreVersion         3 calls
        0 ms  _GetRestoreProjectStyle                    2 calls
        0 ms  _IsProjectRestoreSupported                 1 calls
        0 ms  _GetProjectJsonPath                        2 calls
        0 ms  GetAssemblyAttributes                      1 calls
        0 ms  _GenerateRestoreProjectPathItems           1 calls
        0 ms  _GenerateCompileInputs                     1 calls
        0 ms  _ResolveRazorTargetPath                    1 calls
        0 ms  GetRazorTargetAssemblyAttributes           1 calls
        0 ms  GetTargetPathWithTargetPlatformMoniker     1 calls
        0 ms  _RazorGetCopyToOutputDirectoryItems        1 calls
        0 ms  _GenerateSatelliteAssemblyInputs           1 calls
        0 ms  _ComputeNETCoreBuildOutputFiles            1 calls
        0 ms  _CheckForCompileOutputs                    1 calls
        0 ms  CoreResGen                                 1 calls
        0 ms  GetAssemblyVersion                         1 calls
        0 ms  _GenerateRestoreSpecs                      1 calls
        0 ms  _GenerateRestoreProjectPathWalk            1 calls
        0 ms  _ResolveRazorGenerateOutputs               1 calls
        0 ms  _CheckForInvalidConfigurationAndPlatform   1 calls
        0 ms  ResolveReferences                          1 calls
        0 ms  _GenerateRestoreProjectSpec                1 calls
        0 ms  _GenerateRestoreProjectPathItemsPerFramework   1 calls
        0 ms  _GetProjectReferenceTargetFrameworkProperties   1 calls
        0 ms  SplitResourcesByCulture                    1 calls
        0 ms  AssignRazorGenerateTargetPaths             1 calls
        1 ms  ResolveAssemblyReferenceRazorGenerateInputs   1 calls
        1 ms  _CollectTargetFrameworkForTelemetry        1 calls
        1 ms  CoreGenerateAssemblyInfo                   1 calls
        1 ms  GenerateTargetFrameworkMonikerAttribute    1 calls
        1 ms  ResolveRazorConfiguration                  1 calls
        1 ms  CoreGenerateRazorTargetAssemblyInfo        1 calls
        1 ms  _CreateRazorAssemblyInfoInputsCacheFile    1 calls
        1 ms  CreateGeneratedAssemblyInfoInputsCacheFile   1 calls
        1 ms  CheckForDuplicateItems                     1 calls
        1 ms  CoreGenerateUserSecretsAttribute           1 calls
        1 ms  GetCopyToOutputDirectoryItems              1 calls
        1 ms  _GetRestoreTargetFrameworksOutput          1 calls
        1 ms  _HashRazorGenerateInputs                   1 calls
        1 ms  _CreateRazorTargetAssemblyInfoInputsCacheFile   1 calls
        1 ms  ResolveRazorGenerateInputs                 1 calls
        1 ms  _SetEmbeddedWin32ManifestProperties        1 calls
        1 ms  _ComputeReferenceAssemblies                1 calls
        1 ms  AssignTargetPaths                          1 calls
        1 ms  IncrementalClean                           1 calls
        1 ms  _CoreGenerateRazorAssemblyInfo             1 calls
        1 ms  ResolveLockFileReferences                  1 calls
        2 ms  CopyFilesToOutputDirectory                 1 calls
        2 ms  _GenerateCompileDependencyCache            1 calls
        2 ms  _GetAllRestoreProjectPathItems             1 calls
        3 ms  CheckForImplicitPackageReferenceOverrides   2 calls
        3 ms  _RazorCopyFilesToOutputDirectory           1 calls
        3 ms  _CopyOutOfDateSourceItemsToOutputDirectory   1 calls
        3 ms  _GenerateProjectRestoreGraphPerFramework   1 calls
        3 ms  _CleanGetCurrentAndPriorFileWrites         1 calls
        4 ms  PrepareForBuild                            1 calls
        5 ms  _GenerateDotnetCliToolReferenceSpecs       1 calls
        5 ms  RunProduceContentAssets                    1 calls
        6 ms  _LoadRestoreGraphEntryPoints               1 calls
       13 ms  _GetRestoreSettings                        1 calls
       25 ms  _HandlePackageFileConflicts                1 calls
       27 ms  _GenerateRestoreGraph                      1 calls
       28 ms  FindReferenceAssembliesForReferences       1 calls
       28 ms  ResolveProjectReferences                   1 calls
       36 ms  GenerateBuildRuntimeConfigurationFiles     1 calls
       74 ms  GenerateBuildDependencyFile                1 calls
       75 ms  _FilterRestoreGraphProjectInputItems       1 calls
       86 ms  ResolvePackageAssets                       1 calls
      109 ms  ResolveAssemblyReferences                  1 calls
      141 ms  Restore                                    1 calls
      270 ms  RazorCoreCompile                           1 calls
      995 ms  CoreCompile                                1 calls
    20568 ms  RazorCoreGenerate                          1 calls
    20920 ms  ResolveTagHelperRazorGenerateInputs        1 calls

Task Performance Summary:
        0 ms  GetAssemblyVersion                         1 calls
        0 ms  AssignCulture                              1 calls
        0 ms  ReadLinesFromFile                          1 calls
        0 ms  Delete                                     1 calls
        0 ms  GetRestoreProjectReferencesTask            1 calls
        0 ms  FindAppConfigFile                          1 calls
        0 ms  Telemetry                                  1 calls
        0 ms  GetFrameworkPath                           1 calls
        0 ms  Message                                    7 calls
        0 ms  FindInList                                 1 calls
        1 ms  JoinItems                                  1 calls
        1 ms  CheckForDuplicateItems                     3 calls
        1 ms  GetProjectTargetFrameworksTask             1 calls
        1 ms  FindUnderPath                              5 calls
        1 ms  ConvertToAbsolutePath                      3 calls
        1 ms  AssignTargetPath                           6 calls
        1 ms  Hash                                       5 calls
        1 ms  CheckForImplicitPackageReferenceOverrides   2 calls
        2 ms  WriteCodeFragment                          4 calls
        2 ms  Touch                                      2 calls
        2 ms  GetRestorePackageReferencesTask            1 calls
        3 ms  RemoveDuplicates                           7 calls
        3 ms  WriteLinesToFile                           6 calls
        4 ms  GetRestoreDotnetCliToolsTask               1 calls
        5 ms  ProduceContentAssets                       1 calls
        5 ms  WarnForInvalidProjectsTask                 1 calls
        5 ms  Copy                                       6 calls
        5 ms  MakeDir                                    4 calls
       13 ms  GetRestoreSettingsTask                     1 calls
       20 ms  ResolvePackageFileConflicts                1 calls
       36 ms  GenerateRuntimeConfigurationFiles          1 calls
       74 ms  GenerateDepsFile                           1 calls
       86 ms  ResolvePackageAssets                       1 calls
       87 ms  MsBuild                                    7 calls
      108 ms  ResolveAssemblyReference                   1 calls
      141 ms  RestoreTask                                1 calls
     1262 ms  Csc                                        2 calls
    20566 ms  RazorGenerate                              1 calls
    20917 ms  RazorTagHelper                             1 calls

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

Time Elapsed 00:00:43.74

_Copied from original issue: aspnet/Home#3199_

The text was updated successfully, but these errors were encountered:

mkArtakMSFT · 2018-06-14T17:59:44Z

From @pranavkm on June 5, 2018 17:26

cc @mkArtakMSFT. Issue belongs to Razor

mkArtakMSFT · 2018-06-14T18:01:46Z

@ajaybhargavb, can you please investigate this? Thanks!

henkmollema · 2018-06-14T18:42:19Z

@mkArtakMSFT I'm experiencing the same behavior, even when the changes are not in any .cshtml file (just .cs ones).

      667 ms  RazorCoreCompile                           1 calls
     1527 ms  Restore                                    1 calls
     3351 ms  CoreCompile                                1 calls
    21487 ms  ResolveTagHelperRazorGenerateInputs        1 calls
    26476 ms  Build                                      2 calls

Build times vary from 20 to 50 seconds. It makes developing pretty unbearable. The behavior seems not to be consistent though.

dotnet --info output:

λ dotnet --info
.NET Core SDK (reflecting any global.json):
 Version:   2.1.300
 Commit:    adab45bf0c

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

Host (useful for support):
  Version: 2.1.0
  Commit:  caa7b7e2ba

.NET Core SDKs installed:
  2.1.104 [C:\Program Files\dotnet\sdk]
  2.1.200 [C:\Program Files\dotnet\sdk]
  2.1.201 [C:\Program Files\dotnet\sdk]
  2.1.300-preview2-008533 [C:\Program Files\dotnet\sdk]
  2.1.300-rc1-008673 [C:\Program Files\dotnet\sdk]
  2.1.300 [C:\Program Files\dotnet\sdk]

.NET Core runtimes installed:
  Microsoft.AspNetCore.All 2.1.0-preview1-final [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.1.0-preview2-final [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.1.0-rc1-final [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.All 2.1.0 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.All]
  Microsoft.AspNetCore.App 2.1.0-preview1-final [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.1.0-preview2-final [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.1.0-rc1-final [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.AspNetCore.App 2.1.0 [C:\Program Files\dotnet\shared\Microsoft.AspNetCore.App]
  Microsoft.NETCore.App 2.0.5 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.0.6 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.0.7 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.0-preview1-26216-03 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.0-preview2-26406-04 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.0-rc1 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]
  Microsoft.NETCore.App 2.1.0 [C:\Program Files\dotnet\shared\Microsoft.NETCore.App]

henkmollema · 2018-06-14T18:43:05Z

The slow build times reproduce in Visual Studio 15.7.3 as well.

ajaybhargavb · 2018-06-14T18:45:24Z

@henkmollema, are you creating your project with dotnet new mvc -au Individual as well?

henkmollema · 2018-06-14T18:49:59Z

@ajaybhargavb it repros with an existing application as well as with any clean dotnet new application with Razor files (mvc, mvc -au Individual, angular, etc). dotnet new web (empty web app) builds quickly as expected.

henkmollema · 2018-06-14T18:52:20Z

Might be useful: when you cancel the build with CTRL + C it fails with:

Build FAILED.

C:\Program Files\dotnet\sdk\NuGetFallbackFolder\microsoft.aspnetcore.razor.design\2.1.0\build\netstandard2.0\Microsoft.AspNetCore.Razor.Design.CodeGeneration.targets(69,5): error MSB4018: The "RazorTagHelper" task failed unexpectedly. [C:\tmp\tmpmvc\tmpmvc.csproj]
C:\Program Files\dotnet\sdk\NuGetFallbackFolder\microsoft.aspnetcore.razor.design\2.1.0\build\netstandard2.0\Microsoft.AspNetCore.Razor.Design.CodeGeneration.targets(69,5): error MSB4018: System.OperationCanceledException: The operation was canceled. [C:\tmp\tmpmvc\tmpmvc.csproj]
C:\Program Files\dotnet\sdk\NuGetFallbackFolder\microsoft.aspnetcore.razor.design\2.1.0\build\netstandard2.0\Microsoft.AspNetCore.Razor.Design.CodeGeneration.targets(69,5): error MSB4018:    at System.Threading.CancellationToken.ThrowOperationCanceledException() [C:\tmp\tmpmvc\tmpmvc.csproj]
C:\Program Files\dotnet\sdk\NuGetFallbackFolder\microsoft.aspnetcore.razor.design\2.1.0\build\netstandard2.0\Microsoft.AspNetCore.Razor.Design.CodeGeneration.targets(69,5): error MSB4018:    at System.Threading.ManualResetEventSlim.Wait(Int32 millisecondsTimeout, CancellationToken cancellationToken) [C:\tmp\tmpmvc\tmpmvc.csproj]
C:\Program Files\dotnet\sdk\NuGetFallbackFolder\microsoft.aspnetcore.razor.design\2.1.0\build\netstandard2.0\Microsoft.AspNetCore.Razor.Design.CodeGeneration.targets(69,5): error MSB4018:    at System.Threading.Tasks.Task.SpinThenBlockingWait(Int32 millisecondsTimeout, CancellationToken cancellationToken) [C:\tmp\tmpmvc\tmpmvc.csproj]
C:\Program Files\dotnet\sdk\NuGetFallbackFolder\microsoft.aspnetcore.razor.design\2.1.0\build\netstandard2.0\Microsoft.AspNetCore.Razor.Design.CodeGeneration.targets(69,5): error MSB4018:    at System.Threading.Tasks.Task.InternalWaitCore(Int32 millisecondsTimeout, CancellationToken cancellationToken) [C:\tmp\tmpmvc\tmpmvc.csproj]
C:\Program Files\dotnet\sdk\NuGetFallbackFolder\microsoft.aspnetcore.razor.design\2.1.0\build\netstandard2.0\Microsoft.AspNetCore.Razor.Design.CodeGeneration.targets(69,5): error MSB4018:    at System.Threading.Tasks.Task.Wait(Int32 millisecondsTimeout, CancellationToken cancellationToken) [C:\tmp\tmpmvc\tmpmvc.csproj]
C:\Program Files\dotnet\sdk\NuGetFallbackFolder\microsoft.aspnetcore.razor.design\2.1.0\build\netstandard2.0\Microsoft.AspNetCore.Razor.Design.CodeGeneration.targets(69,5): error MSB4018:    at Microsoft.AspNetCore.Razor.Tasks.DotNetToolTask.TryExecuteOnServer(String pathToTool, String responseFileCommands, String commandLineCommands, Int32& result) [C:\tmp\tmpmvc\tmpmvc.csproj]
C:\Program Files\dotnet\sdk\NuGetFallbackFolder\microsoft.aspnetcore.razor.design\2.1.0\build\netstandard2.0\Microsoft.AspNetCore.Razor.Design.CodeGeneration.targets(69,5): error MSB4018:    at Microsoft.AspNetCore.Razor.Tasks.DotNetToolTask.ExecuteTool(String pathToTool, String responseFileCommands, String commandLineCommands) [C:\tmp\tmpmvc\tmpmvc.csproj]
C:\Program Files\dotnet\sdk\NuGetFallbackFolder\microsoft.aspnetcore.razor.design\2.1.0\build\netstandard2.0\Microsoft.AspNetCore.Razor.Design.CodeGeneration.targets(69,5): error MSB4018:    at Microsoft.Build.Utilities.ToolTask.Execute() [C:\tmp\tmpmvc\tmpmvc.csproj]
C:\Program Files\dotnet\sdk\NuGetFallbackFolder\microsoft.aspnetcore.razor.design\2.1.0\build\netstandard2.0\Microsoft.AspNetCore.Razor.Design.CodeGeneration.targets(69,5): error MSB4018:    at Microsoft.Build.BackEnd.TaskExecutionHost.Microsoft.Build.BackEnd.ITaskExecutionHost.Execute() [C:\tmp\tmpmvc\tmpmvc.csproj]
C:\Program Files\dotnet\sdk\NuGetFallbackFolder\microsoft.aspnetcore.razor.design\2.1.0\build\netstandard2.0\Microsoft.AspNetCore.Razor.Design.CodeGeneration.targets(69,5): error MSB4018:    at Microsoft.Build.BackEnd.TaskBuilder.ExecuteInstantiatedTask(ITaskExecutionHost taskExecutionHost, TaskLoggingContext taskLoggingContext, TaskHost taskHost, ItemBucket bucket, TaskExecutionMode howToExecuteTask) [C:\tmp\tmpmvc\tmpmvc.csproj]

henkmollema · 2018-06-14T19:00:37Z

This issue does not reproduce with 2.0 tooling (e.g. 2.1.201)

ajaybhargavb · 2018-06-14T19:03:19Z

The behavior seems not to be consistent though.

I am having a hard time reproducing it. How frequently does this happen?

henkmollema · 2018-06-14T19:06:51Z

It seems to be consistent since I've said that, haha. 😅 It reproduces with any dotnet new mvc && dotnet build:

C:\tmp\tmpmvc1
λ dotnet new mvc && dotnet build
The template "ASP.NET Core Web App (Model-View-Controller)" was created successfully.
This template contains technologies from parties other than Microsoft, see https://aka.ms/aspnetcore-template-3pn-210 for details.

Processing post-creation actions...
Running 'dotnet restore' on C:\tmp\tmpmvc1\tmpmvc1.csproj...
  Restoring packages for C:\tmp\tmpmvc1\tmpmvc1.csproj...
  Generating MSBuild file C:\tmp\tmpmvc1\obj\tmpmvc1.csproj.nuget.g.props.
  Generating MSBuild file C:\tmp\tmpmvc1\obj\tmpmvc1.csproj.nuget.g.targets.
  Restore completed in 1,16 sec for C:\tmp\tmpmvc1\tmpmvc1.csproj.

Restore succeeded.

Microsoft (R) Build Engine version 15.7.179.6572 for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

  Restore completed in 55,6 ms for C:\tmp\tmpmvc1\tmpmvc1.csproj.
  tmpmvc1 -> C:\tmp\tmpmvc1\bin\Debug\netcoreapp2.1\tmpmvc1.dll
  tmpmvc1 -> C:\tmp\tmpmvc1\bin\Debug\netcoreapp2.1\tmpmvc1.Views.dll

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

Time Elapsed 00:00:45.32

ajaybhargavb · 2018-06-14T19:15:19Z

That's interesting. I can't get it to slow down even once. I'll try it on a clean machine.

C:\GitHub\temp\RazorBuildTimeTest> dotnet new mvc; dotnet build
The template "ASP.NET Core Web App (Model-View-Controller)" was created successfully.
This template contains technologies from parties other than Microsoft, see https://aka.ms/aspnetcore-template-3pn-210 for details.

Processing post-creation actions...
Running 'dotnet restore' on C:\GitHub\temp\RazorBuildTimeTest\RazorBuildTimeTest.csproj...
  Restoring packages for C:\GitHub\temp\RazorBuildTimeTest\RazorBuildTimeTest.csproj...
  Generating MSBuild file C:\GitHub\temp\RazorBuildTimeTest\obj\RazorBuildTimeTest.csproj.nuget.g.props.
  Generating MSBuild file C:\GitHub\temp\RazorBuildTimeTest\obj\RazorBuildTimeTest.csproj.nuget.g.targets.
  Restore completed in 2.82 sec for C:\GitHub\temp\RazorBuildTimeTest\RazorBuildTimeTest.csproj.

Restore succeeded.

Microsoft (R) Build Engine version 15.7.179.6572 for .NET Core
Copyright (C) Microsoft Corporation. All rights reserved.

  Restore completed in 84.97 ms for C:\GitHub\temp\RazorBuildTimeTest\RazorBuildTimeTest.csproj.
  RazorBuildTimeTest -> C:\GitHub\temp\RazorBuildTimeTest\bin\Debug\netcoreapp2.1\RazorBuildTimeTest.dll
  RazorBuildTimeTest -> C:\GitHub\temp\RazorBuildTimeTest\bin\Debug\netcoreapp2.1\RazorBuildTimeTest.Views.dll

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

Time Elapsed 00:00:03.00

C:\GitHub\temp\RazorBuildTimeTest> dotnet --info
.NET Core SDK (reflecting any global.json):
 Version:   2.1.300
 Commit:    adab45bf0c

Runtime Environment:
 OS Name:     Windows
 OS Version:  10.0.17134
 OS Platform: Windows
 RID:         win10-x64
 Base Path:   C:\Users\ajay\.dotnet\x64\x64\sdk\2.1.300\

Host (useful for support):
  Version: 2.1.0
  Commit:  caa7b7e2ba

ajaybhargavb · 2018-06-14T19:22:44Z

Could you run dotnet build /bl and attach the produced msbuild.binlog file here?

henkmollema · 2018-06-14T19:24:35Z

The stack trace shows that it's stuck here when I cancel in the middle of building:

Razor/src/Microsoft.AspNetCore.Razor.Tasks/DotnetToolTask.cs

Lines 155 to 156 in dc76027

    
           var responseTask = ServerConnection.RunOnServer(PipeName, arguments, serverPaths, _razorServerCts.Token, debug: DebugTool); 
        
           responseTask.Wait(_razorServerCts.Token);

This calls into:

Razor/src/Microsoft.AspNetCore.Razor.Tools/ServerProtocol/ServerConnection.cs

Line 95 in dc76027

public static Task<ServerResponse> RunOnServer(

Which is a task with a time-out of 20 seconds:

Razor/src/Microsoft.AspNetCore.Razor.Tools/ServerProtocol/ServerConnection.cs

Line 23 in dc76027

private const int TimeOutMsNewProcess = 20000;

And every slow build is at least 20 seconds long. Any idea?

pranavkm · 2018-06-14T19:27:55Z

@henkmollema could you try adding <UseRazorBuildServer>false</UseRazorBuildServer> to your project? We could try eliminating the Razor build server as a possible source for this issue.

rynowak · 2018-06-14T19:28:07Z

Thanks @henkmollema - that's great info.

Also for anyone who wants an unblocker on this - you can set <UseRazorBuildServer>false</UseRazorBuildServer> and it will skip the build server.

@ajaybhargavb - my best guess is that the build server is failing to start or failing to respond. For instance if the build server crashes before starting to listen - would we wait the whole 20 sec?

This timeout should probably be adjusted

henkmollema · 2018-06-14T19:30:33Z

@pranavkm yep that's it. Build times are back to normal after I added that.

henkmollema · 2018-06-14T19:34:37Z

My build times around 20, 40 or 60 seconds makes sense now. It seems that it re-attempts to launch the server and eventually it succeeds. I wonder why it's having trouble launching it almost every time though. Could be an issue with my local machine?

ajaybhargavb · 2018-06-14T19:39:48Z

if the build server crashes before starting to listen - would we wait the whole 20 sec?

We wait the whole 20 seconds only when it is trying to connect to the named pipe for the first time when the server starts. Every other time we only wait 1 second. If the server crashes, we immediately fallback to in-process execution. My guess is that it's stuck here for 20 seconds and then it gives up.

This timeout should probably be adjusted

Agreed

henkmollema · 2018-06-14T19:41:39Z

Running dotnet build -v diag would have told me this earlier perhaps. I can literally see it failing and hanging at

                     C:\Program Files\dotnet\sdk\NuGetFallbackFolder\microsoft.aspnetcore.mvc.razor.extensions\2.1.0\lib\netstandard2.0\Microsoft.AspNetCore.Mvc.Razor.Extensions.dll
                     ' (TaskId:60)
                     Server execution failed with response Rejected. For more info, check the server log file in the location specified by the RAZORBUILDSERVER_LOG environment variable. (TaskId:60)
                     Fallback to in-process execution. (TaskId:60)
                     Verifying assembly at C:\Program Files\dotnet\sdk\NuGetFallbackFolder\microsoft.aspnetcore.mvc.razor.extensions\2.1.0\lib\netstandard2.0\Microsoft.AspNetCore.Mvc.Razor.Extensions.dll (TaskId:60)
                     Output Item(s): FileWrites=obj\Debug\netcoreapp2.1\mvc1.TagHelpers.output.cache (TaskId:60)
                   Done executing task "RazorTagHelper". (TaskId:60)
21:39:13.506   1:7>Done building target "ResolveTagHelperRazorGenerateInputs" in project "mvc1.csproj".: (TargetId:108)
21:39:13.506   1:7>Target "PrepareForRazorGenerate: (TargetId:109)" in file "C:\Program Files\dotnet\sdk\2.1.300\Sdks\Microsoft.NET.Sdk.Razor\build\netstandard2.0\Sdk.Razor.CurrentVersion.targets" from project "C:\tmp\mvc1\mvc1.csproj" (target "RazorGenerate" depends on it):
21:39:13.506   1:7>Done building target "PrepareForRazorGenerate" in project "mvc1.csproj".: (TargetId:109)
                   Target "_CheckForMissingRazorCompiler" skipped, due to false condition; ('$(IsRazorCompilerReferenced)' != 'true') was evaluated as ('true' != 'true').
21:39:13.506   1:7>Target "_HashRazorGenerateInputs: (TargetId:110)" in file "C:\Program Files\dotnet\sdk\NuGetFallbackFolder\microsoft.aspnetcore.razor.design\2.1.0\build\netstandard2.0\Microsoft.AspNetCore.Razor.Design.CodeGeneration.targets" from project "C:\tmp\mvc1\mvc1.csproj" (target "RazorCoreGenerate" depends on it):
                   Task "Hash" (TaskId:61)
                     Task Parameter:
                         ItemsToHash=

rynowak · 2018-06-14T19:43:13Z

@henkmollema - would you mind checking the event log? Do you see crashes in there from rzc.dll or dotnet.exe

henkmollema · 2018-06-14T19:45:17Z

@ajaybhargavb

My guess is that it's stuck here for 20 seconds and then it gives up.

It seems that it tries again, as my build times vary from ~20 seconds and ~40 seconds.

henkmollema · 2018-06-14T19:46:21Z

@rynowak I can't find any rzc.dll entries in the event viewer.

henkmollema · 2018-06-14T19:53:16Z

The full build output for the failing task part: https://pastebin.com/2kSUP5Ah.

ajaybhargavb · 2018-06-14T20:10:20Z

I suspect there is something wacky going on with the pipe it tries to connect to.

@henkmollema, would you mind running dotnet build /p:_RazorBuildServerPipeName=my-custom-pipe-name and see if the issue still exists?

barrettg · 2018-06-14T20:34:33Z

I can confirm that adding the /p:_RazorBuildServerPipeName=my-custom-pipe-name switch takes my build time from 42.70 to 1.55 seconds

rynowak · 2018-06-15T18:01:04Z

We've started a separate discussion about the pipe issue with some folks from CoreFX.

ajaybhargavb · 2018-06-15T19:57:12Z

I found the actual cause of this. I was passing the pipe name directly as argument instead of within quotes 🤦‍♂️ https://github.com/aspnet/Razor/pull/2409/files#diff-685762d07aeab591272fec7135b4d5f3R293. This has nothing to do with corefx.

henkmollema · 2018-06-15T20:44:44Z

Wooops! Haha, we've all been there.

ajaybhargavb · 2018-06-19T22:24:07Z

Merged in dev 17e3aa8. Keeping the issue open to track porting the fix to the patch.

muratg · 2018-06-21T18:58:54Z

Approved for 2.1.3.

danielcrabtree · 2018-06-24T13:07:59Z

I ran into the same issue with ASP.NET Core 2.1 in Visual Studio 2017 v15.7.4 and at the command line.

Unfortunately, my initial searches didn't turn up this issue. I figured out a couple of workarounds and <UseRazorBuildServer>false</UseRazorBuildServer> is the best for now.

Thank-you for figuring out the underlying issue was with usernames containing a space. I didn't get that far.

Thanks for getting this fixed for 2.1.3 as well.

davidcarson · 2018-06-26T00:08:17Z

You can also put a _RazorBuildServerPipeName setting in your .csproj file as described in this StackOverflow answer - that sorted it out for me.

ajaybhargavb · 2018-07-06T18:08:36Z

e7db3f8

henkmollema · 2018-08-14T11:49:43Z

@ajaybhargavb @muratg

Approved for 2.1.3.

Did you mean .NET Core 2.1.3 or ASP.NET Core 2.1.3? It seems that it did not make it into .NET Core 2.1.3. In case of the latter, when is this planned?

muratg · 2018-08-14T15:05:24Z

@henkmollema 2.1.3 has not shipped yet. I believe it's slated for later this month. (BTW, it's the version of both of the runtimes.)

henkmollema · 2018-08-14T15:07:14Z

My bad, I mislooked at my version number... 😊
Thanks for the update!

mkArtakMSFT mentioned this issue Jun 14, 2018

Slow Razor Build Times dotnet/aspnetcore#3199

Closed

mkArtakMSFT added the investigate label Jun 14, 2018

mkArtakMSFT assigned pranavkm and ajaybhargavb and unassigned pranavkm Jun 14, 2018

ajaybhargavb mentioned this issue Jun 15, 2018

Handle pipe names with whitespace properly #2409

Merged

ajaybhargavb closed this as completed in #2409 Jun 19, 2018

ajaybhargavb reopened this Jun 19, 2018

muratg added SHP: Approved Shiproom has approved the issue and removed SHP: Approval pending Shiproom approval is required for the issue labels Jun 21, 2018

ajaybhargavb mentioned this issue Jul 4, 2018

[Port] Handle pipe name with whitespace properly #2460

Merged

ajaybhargavb closed this as completed Jul 6, 2018

ajaybhargavb added 3 - Done and removed 2 - Working labels Jul 6, 2018

erwindevreugd mentioned this issue Jul 15, 2018

Feature notification csharpfritz/CoreWiki#199

Merged

natemcmaster mentioned this issue Aug 3, 2018

Enable Linux tests on VSTS #2507

Closed

henkmollema mentioned this issue Feb 16, 2019

Slow build times with .NET Core SDK 3.0 preview2 dotnet/core#2323

Closed

This was referenced Sep 6, 2021

chore(deps): update dependency microsoft.aspnetcore.all to v2.2.8 googleapis/google-api-dotnet-client#1939

Closed

chore(deps): update dependency microsoft.aspnetcore.mvc.core to v2.2.5 googleapis/google-api-dotnet-client#1941

Closed

renovate-bot mentioned this issue Sep 25, 2021

chore(deps): update dependency microsoft.aspnetcore.all to v2.2.8 - autoclosed GoogleCloudPlatform/getting-started-dotnet#168

Closed

1 task

renovate-bot mentioned this issue Oct 4, 2021

chore(deps): update dependency microsoft.aspnetcore.all to 2.2.8 GoogleCloudPlatform/getting-started-dotnet#175

Open

1 task

Slow Razor Build Times #2406

Slow Razor Build Times #2406

Comments

mkArtakMSFT commented Jun 14, 2018

mkArtakMSFT commented Jun 14, 2018

mkArtakMSFT commented Jun 14, 2018

henkmollema commented Jun 14, 2018

henkmollema commented Jun 14, 2018

ajaybhargavb commented Jun 14, 2018

henkmollema commented Jun 14, 2018 • edited Loading

henkmollema commented Jun 14, 2018

henkmollema commented Jun 14, 2018

ajaybhargavb commented Jun 14, 2018

henkmollema commented Jun 14, 2018

ajaybhargavb commented Jun 14, 2018 • edited Loading

ajaybhargavb commented Jun 14, 2018

henkmollema commented Jun 14, 2018

pranavkm commented Jun 14, 2018

rynowak commented Jun 14, 2018

henkmollema commented Jun 14, 2018

henkmollema commented Jun 14, 2018

ajaybhargavb commented Jun 14, 2018

henkmollema commented Jun 14, 2018

rynowak commented Jun 14, 2018

henkmollema commented Jun 14, 2018

henkmollema commented Jun 14, 2018

henkmollema commented Jun 14, 2018

ajaybhargavb commented Jun 14, 2018

barrettg commented Jun 14, 2018 • edited Loading

rynowak commented Jun 15, 2018

ajaybhargavb commented Jun 15, 2018

henkmollema commented Jun 15, 2018

ajaybhargavb commented Jun 19, 2018

muratg commented Jun 21, 2018

danielcrabtree commented Jun 24, 2018

davidcarson commented Jun 26, 2018 • edited Loading

ajaybhargavb commented Jul 6, 2018

henkmollema commented Aug 14, 2018

muratg commented Aug 14, 2018

henkmollema commented Aug 14, 2018

henkmollema commented Jun 14, 2018 •

edited

Loading

ajaybhargavb commented Jun 14, 2018 •

edited

Loading

barrettg commented Jun 14, 2018 •

edited

Loading

davidcarson commented Jun 26, 2018 •

edited

Loading