Extremely slow UpdateAssemblyInfo in GitVersionTask

[asbjornu]

I'm using GitVersionTask 3.0.0-beta0002 in a project that suddenly experience extreme slowness in the UpdateAssemblyInfo task. For each project having a GitVersionTask reference, this task takes well over 2 minutes. Here's some relevant output from the TeamCity build log:

[14:57:23]  [Redacted.csproj] UpdateAssemblyInfo (2m:53s)
[14:57:23]      [UpdateAssemblyInfo] WriteVersionInfoToBuildLog (1m:20s)
[14:57:23]          [WriteVersionInfoToBuildLog] Applicable build agent found: 'TeamCity'.
[14:57:23]          [WriteVersionInfoToBuildLog] Executing PerformPreProcessingSteps for 'TeamCity'.
[14:57:24]          [WriteVersionInfoToBuildLog] One remote found (origin -> 'https://user@bitbucket.org/redacted.git').
[14:57:24]          [WriteVersionInfoToBuildLog] Fetching from remote 'origin' using the following refspecs: +refs/heads/*:refs/remotes/origin/*.
[14:57:55]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/1.2'.
[14:57:55]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/1.3'.
[14:57:55]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/1.4'.
[14:57:55]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/1.5'.
[14:57:55]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/2.0'.
[14:57:55]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/2.1'.
[14:57:56]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/2.4.x'.
[14:57:56]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/audit-log'.
[14:57:56]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/cleanup'.
[14:57:56]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/create-drop-schema'.
[14:57:56]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/develop'.
[14:57:56]          [WriteVersionInfoToBuildLog] Skipping local branch creation since it already exists 'refs/remotes/origin/feature/git-version-task'.
[14:57:56]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/log-result'.
[14:57:56]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/master'.
[14:57:56]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/nh4'.
[14:57:56]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/nhibernate-3.1'.
[14:57:56]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/nhibernate-3.2'.
[14:57:56]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/nhibernate-4'.
[14:57:56]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/nuget'.
[14:57:56]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/nuget-history'.
[14:57:56]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/resource-manager'.
[14:57:56]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/rm-selenium'.
[14:57:56]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/serializable-configuration'.
[14:57:56]          [WriteVersionInfoToBuildLog] Creating local branch from remote tracking 'refs/remotes/origin/structuremap-3'.
[14:57:56]          [WriteVersionInfoToBuildLog] HEAD points at branch 'refs/heads/feature/git-version-task'.
[14:57:56]          [WriteVersionInfoToBuildLog] No specific commit specified or found, falling back to latest commit on specified branch
[14:57:56]          [WriteVersionInfoToBuildLog] Attempting to inherit branch configuration from parent branch
[14:57:56]          [WriteVersionInfoToBuildLog] HEAD is merge commit, this is likely a pull request using develop as base
[14:58:43]          [WriteVersionInfoToBuildLog] Found possible parent branches: master, origin/develop, origin/feature/git-version-task, origin/master
[14:58:43]          [WriteVersionInfoToBuildLog] Failed to inherit Increment branch configuration, ended up with: master, origin/develop, origin/feature/git-version-task, origin/master
                                                 Falling back to develop branch config
[14:58:43]          [WriteVersionInfoToBuildLog] Version not in cache. Calculating version.
[14:58:43]          [WriteVersionInfoToBuildLog] Running against branch: feature/git-version-task
[14:58:43]          [WriteVersionInfoToBuildLog] Base Versions:
[14:58:43]          [WriteVersionInfoToBuildLog] Fallback base version: 0.1.0 from commit 24a25cc2b5b9bc3863f25221cce626840e16f58a
[14:58:43]          [WriteVersionInfoToBuildLog] Git tag '3.7.1': 3.7.1 from commit 59a0764702d930b434c99e744727b2bd50032b79
[14:58:43]          [WriteVersionInfoToBuildLog] Git tag '3.7.1': 3.7.1 from commit 59a0764702d930b434c99e744727b2bd50032b79
[14:58:43]          [WriteVersionInfoToBuildLog] Base version used: Git tag '3.7.1': 3.7.1 from commit 59a0764702d930b434c99e744727b2bd50032b79
[14:58:43]          [WriteVersionInfoToBuildLog] Incrementing Minor Version
[14:58:43]          [WriteVersionInfoToBuildLog] Using branch name to calculate version tag
[14:58:43]          [WriteVersionInfoToBuildLog] Applicable build agent found: 'TeamCity'.
[14:58:43]          [WriteVersionInfoToBuildLog] Executing GenerateSetVersionMessage for 'TeamCity'.
[14:58:43]          [WriteVersionInfoToBuildLog] ##teamcity[buildNumber '3.8.0-git-version-task.1']
[14:58:43]          [WriteVersionInfoToBuildLog] Executing GenerateBuildLogOutput for 'TeamCity'.
[14:58:43]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='GitVersion.Major' value='3']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='system.GitVersion.Major' value='3']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='GitVersion.Minor' value='8']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='system.GitVersion.Minor' value='8']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='GitVersion.Patch' value='0']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='system.GitVersion.Patch' value='0']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='GitVersion.PreReleaseTag' value='git-version-task.1']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='system.GitVersion.PreReleaseTag' value='git-version-task.1']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='GitVersion.PreReleaseTagWithDash' value='-git-version-task.1']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='system.GitVersion.PreReleaseTagWithDash' value='-git-version-task.1']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='GitVersion.BuildMetaData' value='33']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='system.GitVersion.BuildMetaData' value='33']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='GitVersion.FullBuildMetaData' value='33.Branch.feature/git-version-task.Sha.30ce319dc4ba66766d6c6b10a9027aa03d65a8ae']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='system.GitVersion.FullBuildMetaData' value='33.Branch.feature/git-version-task.Sha.30ce319dc4ba66766d6c6b10a9027aa03d65a8ae']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='GitVersion.MajorMinorPatch' value='3.8.0']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='system.GitVersion.MajorMinorPatch' value='3.8.0']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='GitVersion.SemVer' value='3.8.0-git-version-task.1']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='system.GitVersion.SemVer' value='3.8.0-git-version-task.1']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='GitVersion.LegacySemVer' value='3.8.0-git-version-task1']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='system.GitVersion.LegacySemVer' value='3.8.0-git-version-task1']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='GitVersion.LegacySemVerPadded' value='3.8.0-git-version-task0001']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='system.GitVersion.LegacySemVerPadded' value='3.8.0-git-version-task0001']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='GitVersion.AssemblySemVer' value='3.8.0.0']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='system.GitVersion.AssemblySemVer' value='3.8.0.0']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='GitVersion.FullSemVer' value='3.8.0-git-version-task.1+33']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='system.GitVersion.FullSemVer' value='3.8.0-git-version-task.1+33']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='GitVersion.InformationalVersion' value='3.8.0-git-version-task.1+33.Branch.feature/git-version-task.Sha.30ce319dc4ba66766d6c6b10a9027aa03d65a8ae']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='system.GitVersion.InformationalVersion' value='3.8.0-git-version-task.1+33.Branch.feature/git-version-task.Sha.30ce319dc4ba66766d6c6b10a9027aa03d65a8ae']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='GitVersion.BranchName' value='feature/git-version-task']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='system.GitVersion.BranchName' value='feature/git-version-task']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='GitVersion.Sha' value='30ce319dc4ba66766d6c6b10a9027aa03d65a8ae']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='system.GitVersion.Sha' value='30ce319dc4ba66766d6c6b10a9027aa03d65a8ae']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='GitVersion.NuGetVersionV2' value='3.8.0-git-version-task0001']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='system.GitVersion.NuGetVersionV2' value='3.8.0-git-version-task0001']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='GitVersion.NuGetVersion' value='3.8.0-git-version-task0001']
[14:58:44]          [WriteVersionInfoToBuildLog] ##teamcity[setParameter name='system.GitVersion.NuGetVersion' value='3.8.0-git-version-task0001']
[14:58:44]      [UpdateAssemblyInfo] UpdateAssemblyInfo (46s)
[14:58:44]          [UpdateAssemblyInfo] No specific commit specified or found, falling back to latest commit on specified branch
[14:58:44]          [UpdateAssemblyInfo] Attempting to inherit branch configuration from parent branch
[14:58:44]          [UpdateAssemblyInfo] HEAD is merge commit, this is likely a pull request using develop as base
[14:59:30]          [UpdateAssemblyInfo] Found possible parent branches: master, origin/develop, origin/feature/git-version-task, origin/master
[14:59:30]          [UpdateAssemblyInfo] Failed to inherit Increment branch configuration, ended up with: master, origin/develop, origin/feature/git-version-task, origin/master
                                         Falling back to develop branch config
[14:59:30]      [UpdateAssemblyInfo] GetVersion (46s)
[14:59:30]          [GetVersion] No specific commit specified or found, falling back to latest commit on specified branch
[14:59:30]          [GetVersion] Attempting to inherit branch configuration from parent branch
[14:59:30]          [GetVersion] HEAD is merge commit, this is likely a pull request using develop as base
[15:00:17]          [GetVersion] Found possible parent branches: master, origin/develop, origin/feature/git-version-task, origin/master
[15:00:17]          [GetVersion] Failed to inherit Increment branch configuration, ended up with: master, origin/develop, origin/feature/git-version-task, origin/master
                                 Falling back to develop branch config

As far as I can tell, there's no external dependencies (like network resources) that should take any time here as most of the time is spent to complete the following step:

Found possible parent branches: master, origin/develop, origin/feature/git-version-task, origin/master

If this step is dependent on network resources and my network for some reason is unbearably slow at the moment for this exact operation but not anything else, I understand that this might be impossible to debug or fix, but I would love any insight into why my build suddenly went from taking ~5 minutes to now completing in 1 hour and 20 minutes.

[gep13]

How big is your repository? i.e. what is the file size on disk? Are you getting a fresh clone each build?

[asbjornu]

@gep13 The repository is 145 MB on disk and TeamCity is doing a clean checkout for each build to avoid random cache related bugs in MSBuild.

[gep13]

Hmmm, so that isn't huge. Are the TeamCity server and Source Control Server on the same network?

[asbjornu]

No, TeamCity is locally hosted while git is up on Bitbucket. However, GitVersionTask has run without problems in this and other repositories before, so I'm wondering if the branch layout combined with the last commit and something other internal crazy state causes GitVersion to get into a weird almost-eternal loop or something.

The time consumption is happening between these two steps:

[14:57:56] [WriteVersionInfoToBuildLog] HEAD is merge commit, this is likely a pull request using develop as base
[14:58:43] [WriteVersionInfoToBuildLog] Found possible parent branches: master, origin/develop, origin/feature/git-version-task, origin/master

[JakeGinnivan]

Do you have the same issue locally?

[asbjornu]

@JakeGinnivan Good question! I first tested the wrong branch, which of course didn't yield any slowness, but now that I've switched to the problematic branch, just loading the solution in Visual Studio takes ages. I don't see any output either, so I can't see exactly what is taking time. Could GitVersionTask affect the time it takes to load the project files it is included in?

[gep13]

That sounds very strange.

As a test, I would suggest removing GitVersionTask, i.e comment it out, and make sure there is not some other problem going on here.

[asbjornu]

Went to get a ☕ and when I came back, VS was done loading the solution. The build is noticeably slower on the git-version-task branch than on develop, but nowhere near as slow as on TeamCity. As MSBuild isn't outputting any timestamps in its build output, I can't say what is taking time, but I do get the same messages as in TeamCity's build log:

25>MSBUILD : warning : No specific commit specified or found, falling back to latest commit on specified branch
25>MSBUILD : warning : Failed to inherit Increment branch configuration, ended up with: develop, master, origin/develop, origin/feature/git-version-task, origin/HEAD, origin/master
25>MSBUILD : warning : 
25>MSBUILD : warning : Falling back to develop branch config
25>MSBUILD : warning : No specific commit specified or found, falling back to latest commit on specified branch
25>MSBUILD : warning : Failed to inherit Increment branch configuration, ended up with: develop, master, origin/develop, origin/feature/git-version-task, origin/HEAD, origin/master
25>MSBUILD : warning : 
25>MSBUILD : warning : Falling back to develop branch config

@gep13 Yea, I'll try that and report back the results.

[asbjornu]

Just a sidenote, I discovered these strange things in the warning list in Visual Studio:

Warning 189: The type 'ReleaseDateAttribute' in 'Redacted\tests\Redacted.UnitTests\obj\Debug\GitVersionTaskAssemblyInfo.g.cs' conflicts with the imported type 'ReleaseDateAttribute' in 'Redacted\app\Core\Domain\bin\Debug\Redacted.dll'. Using the type defined in 'Redacted\tests\Redacted.UnitTests\obj\Debug\GitVersionTaskAssemblyInfo.g.cs'.

[asbjornu]

Yes, removing GitVersionTask definitely sped up everything. Not just noticeably, but orders of magnitude. Reverting the changes with git so GitVersionTask was installed again, then doing "Reload All" in Visual Studio brought back the slowness in both project loading and the build.

I've made a commit in the branch and pushed it so it triggers a TeamCity build. I'll report back on how long it takes for TeamCity to complete the build.

[gep13]

@SimonCropp can you offer any suggestions on this one?

[SimonCropp]

can you share the repo? perhaps privately?

Can you try an earlier version of GitVersion?

[JakeGinnivan]

I think I know what the issue is. For repos for large history I think the branch inheritance code is walking the git tree waaayy too much and is just thrashing the git repo..

On a repo/branch which causes this we need to debug and see what is happening in that function which is causing it to be so slow..

[asbjornu]

@JakeGinnivan That makes a lot of sense. This is an old project with probably several thousand commits. Couldn't the branch inheritance code break when it's (close to certain) about what to deduce from it to produce an accurate version number? Can you point to the piece of code, loop or otherwise in GitVersion where this is done?

[JakeGinnivan]

This will be the problematic method:

https://github.com/ParticularLabs/GitVersion/blob/master/GitVersionCore/BranchConfigurationCalculator.cs#L36