Nerdbank.gitversioning: Sporadic MSBuild hangs with managed git + .NET 5.0

[qmfrederik]

I'm seeing sporadic hangs in MSBuild when using Nerdbank.GitVersioning 3.4.142-alpha with .NET SDK 5.0.100:

Microsoft (R) Build Engine version 16.8.0+126527ff1 for .NET
Copyright (C) Microsoft Corporation. All rights reserved.

Attempting to cancel the build...
/Users/vagrant/.nuget/packages/nerdbank.gitversioning/3.4.142-alpha/build/Nerdbank.GitVersioning.Inner.targets(17,5): warning MSB4220: Waiting for the currently executing task "Nerdbank.GitVersioning.Tasks.GetBuildVersion" to cancel.
/Users/vagrant/.nuget/packages/nerdbank.gitversioning/3.4.142-alpha/build/Nerdbank.GitVersioning.Inner.targets(17,5): warning MSB4220: Waiting for the currently executing task "Nerdbank.GitVersioning.Tasks.GetBuildVersion" to cancel.
/Users/vagrant/.nuget/packages/nerdbank.gitversioning/3.4.142-alpha/build/Nerdbank.GitVersioning.Inner.targets(17,5): warning MSB4220: Waiting for the currently executing task "Nerdbank.GitVersioning.Tasks.GetBuildVersion" to cancel.
/Users/vagrant/.nuget/packages/nerdbank.gitversioning/3.4.142-alpha/build/Nerdbank.GitVersioning.Inner.targets(17,5): warning MSB4220: Waiting for the currently executing task "Nerdbank.GitVersioning.Tasks.GetBuildVersion" to cancel.

I've observed the hang on macOS and Windows, I have not (yet) observed it on Linux.

The issue appears to be specific to .NET 5.0; I have not seen it when using .NET SDK 3.1.404.

I didn't find the time to dig deeper yet, but thought I'd be worth sharing the info nonetheless.

[AArnott]

Thanks. Next time you see this, can you please capture a heap dump and share (privately)?

[BenjaminAbt]

Same problem (also .NET SDK 5.0.100) happens to me on GitHub Action (Ubuntu Latest Pool) and Azure DevOps (Windows 2019 Pool) Pipeline but not locally.

```yaml
- name: Versioning
uses: dotnet/nbgv@master
id: nbgv

  - name: 'Install .NET SDK'
    uses: actions/setup-dotnet@v1
    with:
      dotnet-version: ${{ env.DOTNET_VERSION }}

  - name: Restore
    run: dotnet restore --configfile 'NuGet.config'

  - name: Build
    run: dotnet build $(SOLUTION_FILE) -c Release --no-restore

````

[AArnott]

Thanks, @BenjaminAbt. Is it consistent for you? We can rig procdump.exe to watch the process and collect a heap dump after a timeout for when it happens next.

[BenjaminAbt]

I guess it is consistent on every GitHub action but let me know what I have to do with the procmon in the action and I will add it.

[AArnott]

@BenjaminAbt It's procdump, rather than procmon. I'm not sure how to invoke a build (which typically spawns multiple processes) and get procdump to dump all processes if it exceeds more than the time you would expect a build to require, but that's basically the direction I would go.

I see the dotnet/nbgv github action in your YAML above, but that wouldn't explain a hang in dotnet build. You are consuming the Nerdbank.GitVersioning package too, correct? How long does a non-hung build typically take? Is this an OSS repo that I can look at, fork, and experiment with?

[AArnott]

It looks like changing your dotnet build to procdump -s 4 -cl 20 -n 15 -x <dump-path> dotnet build will do the trick.
Set dump-path to something that your github workflow will later collect as an artifact even on failure. You might want to set a timeout on the github action step as well so that the workflow will actually progress from the hung process on to the artifact collection step.

You can script a download of procdump with this script.

[BenjaminAbt]

_Sorry, procmon was auto-correction._

It's a private repo on GitHub I cannot share.

• It uses GHA dotnet/nbgv@master for GH versioning
• It uses Nerdbank.GitVersioning in (and only in) the aspnetcore app for in-app versioing (only because we want to have the version in the html-code head)

nbgv

dotnet/nbgv@master works fine all the time and finishes in ~10s on GH and (manually as dotnet tool) ~15s on AzD
So no problem with nbgv.

Nerdbank.GitVersioning (3.3.37)

Usually our build takes 130s on GHA (Ubuntu) and 600 on AzD (Windows).
_The difference is unfortunately the dotnet restore, which is slower on Windows machines due to the file system._

Everything is fine.

Nerdbank.GitVersioning (3.4.142-alpha)

With the latest 3.4.142-alpha I had to cancel both builds after 50 minutes (we had no cancel, now we have one).
This is reproducable.

C:\Users\VssAdministrator\.nuget\packages\nerdbank.gitversioning\3.4.142-alpha\build\Nerdbank.GitVersioning.Inner.targets(17,5): warning MSB4220: Waiting for the currently executing task "Nerdbank.GitVersioning.Tasks.GetBuildVersion" to cancel.
Terminate batch job (Y/N)? 
Entering debug mode. Use h or ? for help. 

At D:\a\_tasks\CmdLine_d9bafed4-0b18-4f58-968d-86655b4d2ce9\2.177.3\ps_modules\VstsTaskSdk\ToolFunctions.ps1:113 
char:13

+         if ($originalEncoding) {

+             ~~~~~~~~~~~~~~~~~
^C
[DBG]: PS D:\a\1\s>> 
##[error]The operation was canceled.

Edit: thanks for your message.
I will add your script asap.

[AArnott]

Oh, excellent. If you have a way to cancel an in-progress build in your cloud, then adding a simpler procdump command before actually cancelling may be possible in order to control the timing of the dump collection.

[BenjaminAbt]

I still have to find the right settings. Currently there is way too much data generated by the dump, so I am constantly running into some new limits.

This takes more time than I thought.

[AArnott]

I wonder if you can repro it with a build of just the one asp.net project. If it has dependencies perhaps you can build them first without a dump, then build the web project with /p:buildprojectreferences=false and procdump wired up.

[qmfrederik]

Yes, it's odd. I can fairly consistently reproduce this in Azure DevOps, but I haven't been able to reproduce this locally.
I tried cloning the Git repository using the same steps performed by Azure DevOps (to make sure we get e.g. the same packfiles), and I also tried making sure the environment variables are the same. (As far as I know, only SYSTEM_TEAMPROJECTID and BUILD_SOURCEBRANCH should be relevant.)

I'll give procdump a try.

[qmfrederik]

OK - I can reproduce this locally by uploading the entire source tree and invoking dotnet build in a local copy of that exact source tree:

- task: PublishBuildArtifacts@1
  inputs:
    pathtoPublish: $(Build.SourcesDirectory)
    artifactName: sources
  condition: true
  displayName: Publish entire source tree
- script: set
  displayName: Export environment variables

This is the stack trace:

>   System.Private.CoreLib.dll!System.Buffers.TlsOverPerCoreLockedStacksArrayPool<byte>.Return(byte[] array, bool clearArray) Line 178  C#
    NerdBank.GitVersioning.dll!Nerdbank.GitVersioning.ManagedGit.StreamExtensions.Read(System.IO.Stream stream, System.Span<byte> span) Unknown
    NerdBank.GitVersioning.dll!Nerdbank.GitVersioning.ManagedGit.GitPackDeltafiedStream.Read(System.Span<byte> span)    Unknown
    NerdBank.GitVersioning.dll!Nerdbank.GitVersioning.ManagedGit.GitPackDeltafiedStream.Read(byte[] buffer, int offset, int count)  Unknown
    NerdBank.GitVersioning.dll!Nerdbank.GitVersioning.ManagedGit.StreamExtensions.Read(System.IO.Stream stream, System.Span<byte> span) Unknown
    NerdBank.GitVersioning.dll!Nerdbank.GitVersioning.ManagedGit.GitPackMemoryCacheStream.Read(System.Span<byte> buffer)    Unknown
    NerdBank.GitVersioning.dll!Nerdbank.GitVersioning.ManagedGit.GitPackMemoryCacheStream.Read(byte[] buffer, int offset, int count)    Unknown
    NerdBank.GitVersioning.dll!Nerdbank.GitVersioning.ManagedGit.StreamExtensions.Read(System.IO.Stream stream, System.Span<byte> span) Unknown
    NerdBank.GitVersioning.dll!Nerdbank.GitVersioning.ManagedGit.StreamExtensions.ReadAll(System.IO.Stream stream, System.Span<byte> buffer)    Unknown
    NerdBank.GitVersioning.dll!Nerdbank.GitVersioning.ManagedGit.GitTreeStreamingReader.FindNode(System.IO.Stream stream, System.ReadOnlySpan<byte> name)   Unknown
    NerdBank.GitVersioning.dll!Nerdbank.GitVersioning.ManagedGit.GitRepository.GetTreeEntry(Nerdbank.GitVersioning.ManagedGit.GitObjectId treeId, System.ReadOnlySpan<byte> nodeName)   Unknown
    NerdBank.GitVersioning.dll!Nerdbank.GitVersioning.Managed.ManagedVersionFile.GetVersion(Nerdbank.GitVersioning.ManagedGit.GitCommit commit, string repoRelativeProjectDirectory, System.Collections.Generic.Dictionary<Nerdbank.GitVersioning.ManagedGit.GitObjectId, Nerdbank.GitVersioning.VersionOptions> blobVersionCache, out string actualDirectory)  Unknown
    NerdBank.GitVersioning.dll!Nerdbank.GitVersioning.Managed.GitExtensions.GitWalkTracker.GetVersion(Nerdbank.GitVersioning.ManagedGit.GitCommit commit)   Unknown
    NerdBank.GitVersioning.dll!Nerdbank.GitVersioning.Managed.GitExtensions.CommitMatchesVersion(Nerdbank.GitVersioning.ManagedGit.GitCommit commit, Nerdbank.GitVersioning.SemanticVersion expectedVersion, Nerdbank.GitVersioning.SemanticVersion.Position comparisonPrecision, Nerdbank.GitVersioning.Managed.GitExtensions.GitWalkTracker tracker)  Unknown
    NerdBank.GitVersioning.dll!Nerdbank.GitVersioning.Managed.GitExtensions.GetVersionHeight.AnonymousMethod__0(Nerdbank.GitVersioning.ManagedGit.GitCommit c)  Unknown
    NerdBank.GitVersioning.dll!Nerdbank.GitVersioning.Managed.GitExtensions.GetCommitHeight.__TryCalculateHeight|4_0(Nerdbank.GitVersioning.ManagedGit.GitCommit commit, ref Nerdbank.GitVersioning.Managed.GitExtensions.<>c__DisplayClass4_0 value)   Unknown
    NerdBank.GitVersioning.dll!Nerdbank.GitVersioning.Managed.GitExtensions.GetCommitHeight(Nerdbank.GitVersioning.ManagedGit.GitRepository repository, Nerdbank.GitVersioning.ManagedGit.GitCommit startingCommit, Nerdbank.GitVersioning.Managed.GitExtensions.GitWalkTracker tracker, System.Func<Nerdbank.GitVersioning.ManagedGit.GitCommit, bool> continueStepping)   Unknown
    NerdBank.GitVersioning.dll!Nerdbank.GitVersioning.Managed.GitExtensions.GetHeight(Nerdbank.GitVersioning.Managed.ManagedGitContext context, System.Func<Nerdbank.GitVersioning.ManagedGit.GitCommit, bool> continueStepping)    Unknown
    NerdBank.GitVersioning.dll!Nerdbank.GitVersioning.Managed.GitExtensions.GetVersionHeight(Nerdbank.GitVersioning.Managed.ManagedGitContext context, System.Version baseVersion)  Unknown
    NerdBank.GitVersioning.dll!Nerdbank.GitVersioning.Managed.ManagedGitContext.CalculateVersionHeight(Nerdbank.GitVersioning.VersionOptions committedVersion, Nerdbank.GitVersioning.VersionOptions workingVersion)    Unknown
    NerdBank.GitVersioning.dll!Nerdbank.GitVersioning.VersionOracle.VersionOracle(Nerdbank.GitVersioning.GitContext context, Nerdbank.GitVersioning.ICloudBuild cloudBuild, int? overrideVersionHeightOffset)   Unknown
    Nerdbank.GitVersioning.Tasks.dll!Nerdbank.GitVersioning.Tasks.GetBuildVersion.ExecuteInner()    Unknown
    [Native to Managed Transition]  

I'll have a look.

[qmfrederik]

@BenjaminAbt #542 fixes this for me. Could you give that version a try and let me know if it works for you? The build on the PR contains a pre-build NuGet package in the deployables artifact.

[BenjaminAbt]

LGTM on GitHub Action (ubuntu-latest) and Azure DevOps (windows-2019)!
Also there is no speed difference (everything within the daily fluctuations).

Thanks! 🎉