New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Slow Razor Build Times #2406

Closed
mkArtakMSFT opened this Issue Jun 14, 2018 · 48 comments

Comments

Projects
None yet
9 participants
@mkArtakMSFT
Contributor

mkArtakMSFT commented Jun 14, 2018

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_
@mkArtakMSFT

This comment has been minimized.

Contributor

mkArtakMSFT commented Jun 14, 2018

From @pranavkm on June 5, 2018 17:26

cc @mkArtakMSFT. Issue belongs to Razor

@mkArtakMSFT

This comment has been minimized.

Contributor

mkArtakMSFT commented Jun 14, 2018

@ajaybhargavb, can you please investigate this? Thanks!

@henkmollema

This comment has been minimized.

Contributor

henkmollema commented Jun 14, 2018

@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

This comment has been minimized.

Contributor

henkmollema commented Jun 14, 2018

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

@ajaybhargavb

This comment has been minimized.

Member

ajaybhargavb commented Jun 14, 2018

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

@henkmollema

This comment has been minimized.

Contributor

henkmollema commented Jun 14, 2018

@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

This comment has been minimized.

Contributor

henkmollema commented Jun 14, 2018

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

This comment has been minimized.

Contributor

henkmollema commented Jun 14, 2018

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

@ajaybhargavb

This comment has been minimized.

Member

ajaybhargavb commented Jun 14, 2018

The behavior seems not to be consistent though.

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

@henkmollema

This comment has been minimized.

Contributor

henkmollema commented Jun 14, 2018

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

This comment has been minimized.

Member

ajaybhargavb commented Jun 14, 2018

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

This comment has been minimized.

Member

ajaybhargavb commented Jun 14, 2018

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

@henkmollema

This comment has been minimized.

Contributor

henkmollema commented Jun 14, 2018

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

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

This calls into:

public static Task<ServerResponse> RunOnServer(

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

private const int TimeOutMsNewProcess = 20000;

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

@pranavkm

This comment has been minimized.

Member

pranavkm commented Jun 14, 2018

@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

This comment has been minimized.

Member

rynowak commented Jun 14, 2018

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

This comment has been minimized.

Contributor

henkmollema commented Jun 14, 2018

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

@henkmollema

This comment has been minimized.

Contributor

henkmollema commented Jun 14, 2018

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

This comment has been minimized.

Member

ajaybhargavb commented Jun 14, 2018

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

This comment has been minimized.

Contributor

henkmollema commented Jun 14, 2018

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

This comment has been minimized.

Member

rynowak commented Jun 14, 2018

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

@henkmollema

This comment has been minimized.

Contributor

henkmollema commented Jun 14, 2018

@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

This comment has been minimized.

Contributor

henkmollema commented Jun 14, 2018

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

@henkmollema

This comment has been minimized.

Contributor

henkmollema commented Jun 14, 2018

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

@ajaybhargavb

This comment has been minimized.

Member

ajaybhargavb commented Jun 14, 2018

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

This comment has been minimized.

barrettg commented Jun 14, 2018

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

@mkArtakMSFT

This comment has been minimized.

Contributor

mkArtakMSFT commented Jun 15, 2018

Thanks folks for investigation here. While we can fix this on our end, the slow behavior for pipes with space in names looks like another bug, is it? @rynowak, is this corefx thing or an OS issue? Would be great to get another issue filed for the right area to get fixed.

@henkmollema

This comment has been minimized.

Contributor

henkmollema commented Jun 15, 2018

You're welcome!

@barrettg

This comment has been minimized.

barrettg commented Jun 15, 2018

Glad to help! Thanks for all of your hard work!

@ajaybhargavb ajaybhargavb added 2 - Working and removed 1 - Ready labels Jun 15, 2018

@rynowak

This comment has been minimized.

Member

rynowak commented Jun 15, 2018

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

@ajaybhargavb

This comment has been minimized.

Member

ajaybhargavb commented Jun 15, 2018

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

This comment has been minimized.

Contributor

henkmollema commented Jun 15, 2018

Wooops! Haha, we've all been there.

@ajaybhargavb

This comment has been minimized.

Member

ajaybhargavb commented Jun 19, 2018

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

@muratg

This comment has been minimized.

Member

muratg commented Jun 21, 2018

Approved for 2.1.3.

@danielcrabtree

This comment has been minimized.

danielcrabtree commented Jun 24, 2018

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

This comment has been minimized.

davidcarson commented Jun 26, 2018

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

@ajaybhargavb

This comment has been minimized.

Member

ajaybhargavb commented Jul 6, 2018

@henkmollema

This comment has been minimized.

Contributor

henkmollema commented Aug 14, 2018

@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

This comment has been minimized.

Member

muratg commented Aug 14, 2018

@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

This comment has been minimized.

Contributor

henkmollema commented Aug 14, 2018

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment