GitVersion newer than v3.4.1 has severe performance problems

[roryprimrose]

We use GitVersionTask (3.6.3) on all the projects in a solution to ensure that all deployed assemblies reflect the correct version from a build (local or build agent). Something has happened in our git branching whereby GitVersionTask for a project has now gone from ~10 seconds to run WriteVersionInfoToBuildLog, UpdateAssemblyInfo and GetVersion to ~60 seconds.

This is a big issue for us because there a 16 projects in the solution that use GitVersionTask. Our overall build time has just jumped from 8 minutes to 18-24 minutes.

Is it possible for GitVersionTask to cache the calculation of version metadata and share this between the projects being built? Re-calculating the same information on each project build is very expensive.

[discomurray]

If you roll back to GitVersion 3.4.1 does the performance improve?

[roryprimrose]

3.6.3 ran for 24.2 minutes
3.4.1 ran for 8.6 minutes

[roryprimrose]

Should we be rolling back to 3.4.1?

[asbjornu]

@roryprimrose: If you don't need any of the features or bug fixes implemented by 3.4.1+, then by all means downgrade until we figure this one out. 😃

Caching has been a repeated issue, but usually the other way around since we implemented it in #737; people have complained about the cache being too eager and not being able to invalidate it. So a lot of stuff has happened around cache invalidation lately that I guess affects you in unexpected ways.

If you have a look at this search for "cache", you can see that there has been done a lot of stuff related to caching, so any one of those pull requests can be the source of your troubles.

The diff between 3.4.1 and 3.6.3 is too big to list on GitHub, so I guess wading through the swathes of commits is going to be too much work, but the source of your problems is hidden in there somewhere. 😄

[roryprimrose]

I've been able to narrow it down a little. I've incrementally updated each version and pushed builds. The build against 3.5.4 took 10 minutes. Updating to 3.6.0 took 24 minutes.

The following is a view of the GitVersionTask executing for just one of the projects in the solution. The execution time goes from 14 seconds to 57 seconds.

3.5.4

2016-10-13T23:44:49.5597356Z WriteVersionInfoToBuildLog:
2016-10-13T23:44:49.5753613Z   INFO [10/14/16 10:44:49:55] Applicable build agent found: 'VsoAgent'.
2016-10-13T23:44:49.6066300Z   INFO [10/14/16 10:44:49:60] Project root is: C:\B\PRODUCT_NAME\_work\8\s
2016-10-13T23:44:49.6847461Z   INFO [10/14/16 10:44:49:68] Begin: Loading version variables from disk cache
2016-10-13T23:44:49.7161194Z     INFO [10/14/16 10:44:49:71] Cache file C:\B\PRODUCT_NAME\_work\8\s\.git\gitversion_cache\FD22870349EE0ACCD405C828C070B6825088FBF4.yml not found.
2016-10-13T23:44:49.7161194Z   INFO [10/14/16 10:44:49:71] End: Loading version variables from disk cache (Took: 31.37ms)
2016-10-13T23:44:49.7161194Z   INFO [10/14/16 10:44:49:71] Branch from build environment: refs/heads/feature-performancetesting
2016-10-13T23:45:05.5298362Z   INFO [10/14/16 10:45:05:52] Using latest commit on specified branch
2016-10-13T23:45:05.5453828Z   INFO [10/14/16 10:45:05:54] Begin: Attempting to inherit branch configuration from parent branch
2016-10-13T23:45:05.6703804Z     INFO [10/14/16 10:45:05:67] Begin: Finding branch source
2016-10-13T23:45:05.7485203Z       INFO [10/14/16 10:45:05:74] Begin: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against develop
2016-10-13T23:45:05.7641515Z         INFO [10/14/16 10:45:05:76] Merge base was due to a forward merge, moving to next merge base
2016-10-13T23:45:05.7641515Z       INFO [10/14/16 10:45:05:76] End: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against develop (Took: 15.63ms)
2016-10-13T23:45:05.7641515Z       INFO [10/14/16 10:45:05:76] Begin: Found merge base of ca082ef924166f5a04ffeb19e7d54a047cc36ecf against hotfix-database2.2.8migration
2016-10-13T23:45:05.7641515Z         INFO [10/14/16 10:45:05:76] Merge base was due to a forward merge, moving to next merge base
2016-10-13T23:45:05.7641515Z       INFO [10/14/16 10:45:05:76] End: Found merge base of ca082ef924166f5a04ffeb19e7d54a047cc36ecf against hotfix-database2.2.8migration (Took: 0.00ms)
2016-10-13T23:45:05.7797741Z       INFO [10/14/16 10:45:05:77] Begin: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against master
2016-10-13T23:45:05.7797741Z       INFO [10/14/16 10:45:05:77] End: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against master (Took: 0.00ms)
2016-10-13T23:45:05.7797741Z       INFO [10/14/16 10:45:05:77] Begin: Found merge base of 7b67ca46208976a94417bee52f9dfa54aa45f315 against release-2.2
2016-10-13T23:45:05.7797741Z       INFO [10/14/16 10:45:05:77] End: Found merge base of 7b67ca46208976a94417bee52f9dfa54aa45f315 against release-2.2 (Took: 0.00ms)
2016-10-13T23:45:05.7797741Z       INFO [10/14/16 10:45:05:77] Begin: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against release-2.3
2016-10-13T23:45:05.7797741Z       INFO [10/14/16 10:45:05:77] End: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against release-2.3 (Took: 0.00ms)
2016-10-13T23:45:05.7797741Z       INFO [10/14/16 10:45:05:77] Begin: Found merge base of 7a0e0b158886edd3b22eefdb1fb9f77026521cb7 against hotfix-2.2-summary-page
2016-10-13T23:45:05.7954000Z         INFO [10/14/16 10:45:05:79] Merge base was due to a forward merge, moving to next merge base
2016-10-13T23:45:05.7954000Z       INFO [10/14/16 10:45:05:79] End: Found merge base of 7a0e0b158886edd3b22eefdb1fb9f77026521cb7 against hotfix-2.2-summary-page (Took: 15.63ms)
2016-10-13T23:45:05.7954000Z       INFO [10/14/16 10:45:05:79] Begin: Found merge base of b06ab05566ec3e46305d06b95aeabf9a53fa6086 against hotfix-bug2654-web.config
2016-10-13T23:45:05.7954000Z       INFO [10/14/16 10:45:05:79] End: Found merge base of b06ab05566ec3e46305d06b95aeabf9a53fa6086 against hotfix-bug2654-web.config (Took: 0.00ms)
2016-10-13T23:45:05.7954000Z       INFO [10/14/16 10:45:05:79] Begin: Found merge base of 1e2487b3181bc82e7e55fd0311971146c21d21c6 against hotfix-SupportWeb-fix
2016-10-13T23:45:05.7954000Z         INFO [10/14/16 10:45:05:79] Merge base was due to a forward merge, moving to next merge base
2016-10-13T23:45:05.8110289Z       INFO [10/14/16 10:45:05:81] End: Found merge base of 1e2487b3181bc82e7e55fd0311971146c21d21c6 against hotfix-SupportWeb-fix (Took: 15.63ms)
2016-10-13T23:45:05.8110289Z     INFO [10/14/16 10:45:05:81] End: Finding branch source (Took: 140.65ms)
2016-10-13T23:45:05.8266558Z     INFO [10/14/16 10:45:05:82] Found possible parent branches: master
2016-10-13T23:45:05.8266558Z   INFO [10/14/16 10:45:05:82] End: Attempting to inherit branch configuration from parent branch (Took: 281.27ms)
2016-10-13T23:45:05.8580002Z   INFO [10/14/16 10:45:05:85] Running against branch: feature-performancetesting (56b89f48126009e01f03b7498202d95a4a141b97)
2016-10-13T23:45:05.8580002Z   INFO [10/14/16 10:45:05:85] Begin: Calculating base versions
2016-10-13T23:45:05.9360365Z     INFO [10/14/16 10:45:05:93] Fallback base version: 0.1.0 with commit count source 93e085d56ea404f2d661fc6b97f9efc0f62b2fac
2016-10-13T23:45:06.0766635Z     INFO [10/14/16 10:45:06:07] Git tag 'v2.2.9': 2.2.9 with commit count source ca082ef924166f5a04ffeb19e7d54a047cc36ecf
2016-10-13T23:45:06.0922968Z     INFO [10/14/16 10:45:06:09] Git tag 'v2.2.8': 2.2.8 with commit count source 7a0e0b158886edd3b22eefdb1fb9f77026521cb7
2016-10-13T23:45:06.1079203Z     INFO [10/14/16 10:45:06:10] Git tag 'v2.2.7': 2.2.7 with commit count source 1e2487b3181bc82e7e55fd0311971146c21d21c6
2016-10-13T23:45:06.1704206Z     INFO [10/14/16 10:45:06:17] Merge message 'Merge database projects from release-2.2': 2.2.0 with commit count source b19f109c10450c3de48e19b33f14c0990a2c51cc
2016-10-13T23:45:06.1860598Z     INFO [10/14/16 10:45:06:18] Merge message 'Merge branch 'release-2.2'': 2.2.0 with commit count source a7f838407b69a8887e08fa7dc185290cb2781277
2016-10-13T23:45:06.2016791Z     INFO [10/14/16 10:45:06:20] Merge message 'Merge from release-2.2 v2.2.8 SupportWeb fix': 2.2.0 with commit count source 4fea2d180fe94864945c349f43c72b6264429e2f
2016-10-13T23:45:06.2173041Z     INFO [10/14/16 10:45:06:21] Found multiple base versions which will produce the same SemVer (2.3.0), taking oldest source for commit counting (Git tag 'v2.2.7')
2016-10-13T23:45:06.2173041Z     INFO [10/14/16 10:45:06:21] Base version used: Merge message 'Merge from release-2.2 v2.2.8 SupportWeb fix': 2.2.0 with commit count source 1e2487b3181bc82e7e55fd0311971146c21d21c6
2016-10-13T23:45:06.2329271Z   INFO [10/14/16 10:45:06:21] End: Calculating base versions (Took: 359.30ms)
2016-10-13T23:45:06.2329271Z   INFO [10/14/16 10:45:06:23] Using branch name to calculate version tag
2016-10-13T23:45:06.2798968Z   INFO [10/14/16 10:45:06:27] 37 commits found between 1e2487b3181bc82e7e55fd0311971146c21d21c6 and 56b89f48126009e01f03b7498202d95a4a141b97
2016-10-13T23:45:06.3111413Z   INFO [10/14/16 10:45:06:31] Begin: Creating dictionary
2016-10-13T23:45:06.3111413Z   INFO [10/14/16 10:45:06:31] End: Creating dictionary (Took: 0.00ms)
2016-10-13T23:45:06.3111413Z   INFO [10/14/16 10:45:06:31] Begin: Storing version variables to cache file C:\B\PRODUCT_NAME\_work\8\s\.git\gitversion_cache\EDAE63ED385E74D4D5C3E116927DAA9B12CEC761.yml
2016-10-13T23:45:06.3580255Z   INFO [10/14/16 10:45:06:35] End: Storing version variables to cache file C:\B\PRODUCT_NAME\_work\8\s\.git\gitversion_cache\EDAE63ED385E74D4D5C3E116927DAA9B12CEC761.yml (Took: 46.88ms)
2016-10-13T23:45:06.3580255Z   INFO [10/14/16 10:45:06:35] Applicable build agent found: 'VsoAgent'.
2016-10-13T23:45:06.3580255Z   Executing GenerateSetVersionMessage for 'VsoAgent'.
2016-10-13T23:45:09.7019490Z   Executing GenerateBuildLogOutput for 'VsoAgent'.
2016-10-13T23:45:09.7019490Z UpdateAssemblyInfo:
2016-10-13T23:45:09.7019490Z   INFO [10/14/16 10:45:06:37] Applicable build agent found: 'VsoAgent'.
2016-10-13T23:45:09.7019490Z   INFO [10/14/16 10:45:06:37] Project root is: C:\B\PRODUCT_NAME\_work\8\s
2016-10-13T23:45:09.7019490Z   INFO [10/14/16 10:45:06:38] Begin: Loading version variables from disk cache
2016-10-13T23:45:09.7019490Z     INFO [10/14/16 10:45:06:40] Begin: Deserializing version variables from cache file C:\B\PRODUCT_NAME\_work\8\s\.git\gitversion_cache\EDAE63ED385E74D4D5C3E116927DAA9B12CEC761.yml
2016-10-13T23:45:09.7019490Z     INFO [10/14/16 10:45:06:40] End: Deserializing version variables from cache file C:\B\PRODUCT_NAME\_work\8\s\.git\gitversion_cache\EDAE63ED385E74D4D5C3E116927DAA9B12CEC761.yml (Took: 0.00ms)
2016-10-13T23:45:09.7019490Z   INFO [10/14/16 10:45:06:40] End: Loading version variables from disk cache (Took: 15.63ms)
2016-10-13T23:45:09.7019490Z GetVersion:
2016-10-13T23:45:09.7019490Z   INFO [10/14/16 10:45:06:42] Applicable build agent found: 'VsoAgent'.
2016-10-13T23:45:09.7019490Z   INFO [10/14/16 10:45:06:42] Project root is: C:\B\PRODUCT_NAME\_work\8\s
2016-10-13T23:45:09.7019490Z   INFO [10/14/16 10:45:06:43] Begin: Loading version variables from disk cache
2016-10-13T23:45:09.7019490Z     INFO [10/14/16 10:45:06:45] Begin: Deserializing version variables from cache file C:\B\PRODUCT_NAME\_work\8\s\.git\gitversion_cache\EDAE63ED385E74D4D5C3E116927DAA9B12CEC761.yml
2016-10-13T23:45:09.7019490Z     INFO [10/14/16 10:45:06:45] End: Deserializing version variables from cache file C:\B\PRODUCT_NAME\_work\8\s\.git\gitversion_cache\EDAE63ED385E74D4D5C3E116927DAA9B12CEC761.yml (Took: 0.00ms)
2016-10-13T23:45:09.7019490Z   INFO [10/14/16 10:45:06:45] End: Loading version variables from disk cache (Took: 15.62ms)
2016-10-13T23:45:09.7019490Z CoreCompile:

3.6.0

2016-10-13T23:55:05.6395217Z WriteVersionInfoToBuildLog:
2016-10-13T23:55:05.6395217Z   INFO [10/14/16 10:55:05:63] Applicable build agent found: 'VsoAgent'.
2016-10-13T23:55:05.6395217Z   INFO [10/14/16 10:55:05:63] Branch from build environment: refs/heads/feature-performancetesting
2016-10-13T23:55:20.5781979Z   INFO [10/14/16 10:55:20:57] IsDynamicGitRepository: False
2016-10-13T23:55:20.5781979Z   INFO [10/14/16 10:55:20:57] Returning Project Root from DotGitDirectory: C:\B\PRODUCT_NAME\_work\8\s\.git - C:\B\PRODUCT_NAME\_work\8\s
2016-10-13T23:55:20.5781979Z   INFO [10/14/16 10:55:20:57] Project root is: C:\B\PRODUCT_NAME\_work\8\s
2016-10-13T23:55:20.5781979Z   INFO [10/14/16 10:55:20:57] DotGit directory is: C:\B\PRODUCT_NAME\_work\8\s\.git
2016-10-13T23:55:20.5938386Z   INFO [10/14/16 10:55:20:59] Begin: Loading version variables from disk cache
2016-10-13T23:55:20.6407025Z     INFO [10/14/16 10:55:20:64] Cache file C:\B\PRODUCT_NAME\_work\8\s\.git\gitversion_cache\1AD0D41E308A613D603A317EF4AF968DC58DF853.yml not found.
2016-10-13T23:55:20.6407025Z   INFO [10/14/16 10:55:20:64] End: Loading version variables from disk cache (Took: 46.86ms)
2016-10-13T23:55:20.7657127Z   INFO [10/14/16 10:55:20:76] Using latest commit on specified branch
2016-10-13T23:55:20.7813664Z   INFO [10/14/16 10:55:20:78] Begin: Attempting to inherit branch configuration from parent branch
2016-10-13T23:55:20.8907232Z     INFO [10/14/16 10:55:20:89] Begin: Finding branch source
2016-10-13T23:55:21.0001056Z       INFO [10/14/16 10:55:21:00] Begin: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against develop
2016-10-13T23:55:21.0157433Z         INFO [10/14/16 10:55:21:01] Merge base was due to a forward merge, moving to next merge base
2016-10-13T23:55:21.0157433Z       INFO [10/14/16 10:55:21:01] End: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against develop (Took: 15.64ms)
2016-10-13T23:55:21.0626103Z       INFO [10/14/16 10:55:21:06] Begin: Found merge base of ca082ef924166f5a04ffeb19e7d54a047cc36ecf against hotfix-database2.2.8migration
2016-10-13T23:55:21.0626103Z         INFO [10/14/16 10:55:21:06] Merge base was due to a forward merge, moving to next merge base
2016-10-13T23:55:21.0626103Z       INFO [10/14/16 10:55:21:06] End: Found merge base of ca082ef924166f5a04ffeb19e7d54a047cc36ecf against hotfix-database2.2.8migration (Took: 0.00ms)
2016-10-13T23:55:21.0626103Z       INFO [10/14/16 10:55:21:06] Begin: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against master
2016-10-13T23:55:21.0626103Z       INFO [10/14/16 10:55:21:06] End: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against master (Took: 0.00ms)
2016-10-13T23:55:21.0782503Z       INFO [10/14/16 10:55:21:06] Begin: Found merge base of 7b67ca46208976a94417bee52f9dfa54aa45f315 against release-2.2
2016-10-13T23:55:21.0782503Z       INFO [10/14/16 10:55:21:07] End: Found merge base of 7b67ca46208976a94417bee52f9dfa54aa45f315 against release-2.2 (Took: 15.64ms)
2016-10-13T23:55:21.0782503Z       INFO [10/14/16 10:55:21:07] Begin: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against release-2.3
2016-10-13T23:55:21.0782503Z       INFO [10/14/16 10:55:21:07] End: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against release-2.3 (Took: 0.00ms)
2016-10-13T23:55:21.0782503Z       INFO [10/14/16 10:55:21:07] Begin: Found merge base of 7a0e0b158886edd3b22eefdb1fb9f77026521cb7 against hotfix-2.2-summary-page
2016-10-13T23:55:21.0782503Z         INFO [10/14/16 10:55:21:07] Merge base was due to a forward merge, moving to next merge base
2016-10-13T23:55:21.0782503Z       INFO [10/14/16 10:55:21:07] End: Found merge base of 7a0e0b158886edd3b22eefdb1fb9f77026521cb7 against hotfix-2.2-summary-page (Took: 0.00ms)
2016-10-13T23:55:21.0938629Z       INFO [10/14/16 10:55:21:07] Begin: Found merge base of b06ab05566ec3e46305d06b95aeabf9a53fa6086 against hotfix-bug2654-web.config
2016-10-13T23:55:21.0938629Z       INFO [10/14/16 10:55:21:09] End: Found merge base of b06ab05566ec3e46305d06b95aeabf9a53fa6086 against hotfix-bug2654-web.config (Took: 15.61ms)
2016-10-13T23:55:21.0938629Z       INFO [10/14/16 10:55:21:09] Begin: Found merge base of 1e2487b3181bc82e7e55fd0311971146c21d21c6 against hotfix-supportweb-fix
2016-10-13T23:55:21.0938629Z         INFO [10/14/16 10:55:21:09] Merge base was due to a forward merge, moving to next merge base
2016-10-13T23:55:21.0938629Z       INFO [10/14/16 10:55:21:09] End: Found merge base of 1e2487b3181bc82e7e55fd0311971146c21d21c6 against hotfix-supportweb-fix (Took: 0.00ms)
2016-10-13T23:55:21.1095029Z     INFO [10/14/16 10:55:21:10] End: Finding branch source (Took: 218.78ms)
2016-10-13T23:55:21.1095029Z     INFO [10/14/16 10:55:21:10] Begin: Getting branches containing the commit 'c376c2695400eb1a258bf09292bc23f7dd000748'.
2016-10-13T23:55:21.1095029Z       INFO [10/14/16 10:55:21:10] Trying to find direct branches.
2016-10-13T23:55:21.1251264Z       INFO [10/14/16 10:55:21:12] Direct branch found: 'master'.
2016-10-13T23:55:21.1251264Z     INFO [10/14/16 10:55:21:12] End: Getting branches containing the commit 'c376c2695400eb1a258bf09292bc23f7dd000748'. (Took: 15.62ms)
2016-10-13T23:55:21.1251264Z     INFO [10/14/16 10:55:21:12] Found possible parent branches: master
2016-10-13T23:55:21.1251264Z   INFO [10/14/16 10:55:21:12] End: Attempting to inherit branch configuration from parent branch (Took: 343.76ms)
2016-10-13T23:55:21.1407538Z   INFO [10/14/16 10:55:21:14] Running against branch: feature-performancetesting (4d2cd258d5237c55a30b92e67f5d40e1ff5553fa)
2016-10-13T23:55:21.1563851Z   INFO [10/14/16 10:55:21:15] Begin: Calculating base versions
2016-10-13T23:55:21.2344995Z     INFO [10/14/16 10:55:21:23] Fallback base version: 0.1.0 with commit count source 93e085d56ea404f2d661fc6b97f9efc0f62b2fac
2016-10-13T23:55:21.4063881Z     INFO [10/14/16 10:55:21:40] Git tag 'v2.2.9': 2.2.9 with commit count source ca082ef924166f5a04ffeb19e7d54a047cc36ecf
2016-10-13T23:55:21.4220207Z     INFO [10/14/16 10:55:21:42] Git tag 'v2.2.8': 2.2.8 with commit count source 7a0e0b158886edd3b22eefdb1fb9f77026521cb7
2016-10-13T23:55:21.4376467Z     INFO [10/14/16 10:55:21:43] Git tag 'v2.2.7': 2.2.7 with commit count source 1e2487b3181bc82e7e55fd0311971146c21d21c6
2016-10-13T23:55:21.5001656Z     INFO [10/14/16 10:55:21:50] Merge message 'Merge database projects from release-2.2': 2.2.0 with commit count source b19f109c10450c3de48e19b33f14c0990a2c51cc
2016-10-13T23:55:21.5157771Z     INFO [10/14/16 10:55:21:51] Merge message 'Merge branch 'release-2.2'': 2.2.0 with commit count source a7f838407b69a8887e08fa7dc185290cb2781277
2016-10-13T23:55:21.5314060Z     INFO [10/14/16 10:55:21:53] Merge message 'Merge from release-2.2 v2.2.8 SupportWeb fix': 2.2.0 with commit count source 4fea2d180fe94864945c349f43c72b6264429e2f
2016-10-13T23:55:21.5470304Z     INFO [10/14/16 10:55:21:54] Found multiple base versions which will produce the same SemVer (2.3.0), taking oldest source for commit counting (Git tag 'v2.2.7')
2016-10-13T23:55:21.5470304Z     INFO [10/14/16 10:55:21:54] Base version used: Merge message 'Merge from release-2.2 v2.2.8 SupportWeb fix': 2.2.0 with commit count source 1e2487b3181bc82e7e55fd0311971146c21d21c6
2016-10-13T23:55:21.5470304Z   INFO [10/14/16 10:55:21:54] End: Calculating base versions (Took: 390.65ms)
2016-10-13T23:55:21.5626591Z   INFO [10/14/16 10:55:21:56] Using branch name to calculate version tag
2016-10-13T23:55:21.6096363Z   INFO [10/14/16 10:55:21:60] 38 commits found between 1e2487b3181bc82e7e55fd0311971146c21d21c6 and 4d2cd258d5237c55a30b92e67f5d40e1ff5553fa
2016-10-13T23:55:21.6251646Z   INFO [10/14/16 10:55:21:62] Begin: Creating dictionary
2016-10-13T23:55:21.6408723Z   INFO [10/14/16 10:55:21:64] End: Creating dictionary (Took: 15.71ms)
2016-10-13T23:55:21.6408723Z   INFO [10/14/16 10:55:21:64] Begin: Storing version variables to cache file C:\B\PRODUCT_NAME\_work\8\s\.git\gitversion_cache\1AD0D41E308A613D603A317EF4AF968DC58DF853.yml
2016-10-13T23:55:21.6877153Z   INFO [10/14/16 10:55:21:68] End: Storing version variables to cache file C:\B\PRODUCT_NAME\_work\8\s\.git\gitversion_cache\1AD0D41E308A613D603A317EF4AF968DC58DF853.yml (Took: 46.84ms)
2016-10-13T23:55:21.7032956Z   INFO [10/14/16 10:55:21:70] Applicable build agent found: 'VsoAgent'.
2016-10-13T23:55:21.7032956Z   Executing GenerateSetVersionMessage for 'VsoAgent'.
2016-10-13T23:55:23.7659490Z   Executing GenerateBuildLogOutput for 'VsoAgent'.
2016-10-13T23:55:23.7659490Z UpdateAssemblyInfo:
2016-10-13T23:55:23.7659490Z   INFO [10/14/16 10:55:21:71] Applicable build agent found: 'VsoAgent'.
2016-10-13T23:55:23.7659490Z   INFO [10/14/16 10:55:21:71] Branch from build environment: refs/heads/feature-performancetesting
2016-10-13T23:55:41.1735712Z   INFO [10/14/16 10:55:41:17] IsDynamicGitRepository: False
2016-10-13T23:55:41.1735712Z   INFO [10/14/16 10:55:41:17] Returning Project Root from DotGitDirectory: C:\B\PRODUCT_NAME\_work\8\s\.git - C:\B\PRODUCT_NAME\_work\8\s
2016-10-13T23:55:41.1735712Z   INFO [10/14/16 10:55:41:17] Project root is: C:\B\PRODUCT_NAME\_work\8\s
2016-10-13T23:55:41.1735712Z   INFO [10/14/16 10:55:41:17] DotGit directory is: C:\B\PRODUCT_NAME\_work\8\s\.git
2016-10-13T23:55:41.1892137Z   INFO [10/14/16 10:55:41:18] Begin: Loading version variables from disk cache
2016-10-13T23:55:41.2048305Z     INFO [10/14/16 10:55:41:20] Cache file C:\B\PRODUCT_NAME\_work\8\s\.git\gitversion_cache\A16C59AF972CF9FDB836687A1ABB281B4442B77E.yml not found.
2016-10-13T23:55:41.2048305Z   INFO [10/14/16 10:55:41:20] End: Loading version variables from disk cache (Took: 15.62ms)
2016-10-13T23:55:41.2048305Z   INFO [10/14/16 10:55:41:20] Using latest commit on specified branch
2016-10-13T23:55:41.2048305Z   INFO [10/14/16 10:55:41:20] Begin: Attempting to inherit branch configuration from parent branch
2016-10-13T23:55:41.3142077Z     INFO [10/14/16 10:55:41:31] Begin: Finding branch source
2016-10-13T23:55:41.4235993Z       INFO [10/14/16 10:55:41:42] Begin: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against develop
2016-10-13T23:55:41.4235993Z         INFO [10/14/16 10:55:41:42] Merge base was due to a forward merge, moving to next merge base
2016-10-13T23:55:41.4235993Z       INFO [10/14/16 10:55:41:42] End: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against develop (Took: 0.00ms)
2016-10-13T23:55:41.4704691Z       INFO [10/14/16 10:55:41:47] Begin: Found merge base of ca082ef924166f5a04ffeb19e7d54a047cc36ecf against hotfix-database2.2.8migration
2016-10-13T23:55:41.4704691Z         INFO [10/14/16 10:55:41:47] Merge base was due to a forward merge, moving to next merge base
2016-10-13T23:55:41.4704691Z       INFO [10/14/16 10:55:41:47] End: Found merge base of ca082ef924166f5a04ffeb19e7d54a047cc36ecf against hotfix-database2.2.8migration (Took: 0.00ms)
2016-10-13T23:55:41.4704691Z       INFO [10/14/16 10:55:41:47] Begin: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against master
2016-10-13T23:55:41.4704691Z       INFO [10/14/16 10:55:41:47] End: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against master (Took: 0.00ms)
2016-10-13T23:55:41.4704691Z       INFO [10/14/16 10:55:41:47] Begin: Found merge base of 7b67ca46208976a94417bee52f9dfa54aa45f315 against release-2.2
2016-10-13T23:55:41.4704691Z       INFO [10/14/16 10:55:41:47] End: Found merge base of 7b67ca46208976a94417bee52f9dfa54aa45f315 against release-2.2 (Took: 0.00ms)
2016-10-13T23:55:41.4861061Z       INFO [10/14/16 10:55:41:48] Begin: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against release-2.3
2016-10-13T23:55:41.4861061Z       INFO [10/14/16 10:55:41:48] End: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against release-2.3 (Took: 0.00ms)
2016-10-13T23:55:41.4861061Z       INFO [10/14/16 10:55:41:48] Begin: Found merge base of 7a0e0b158886edd3b22eefdb1fb9f77026521cb7 against hotfix-2.2-summary-page
2016-10-13T23:55:41.4861061Z         INFO [10/14/16 10:55:41:48] Merge base was due to a forward merge, moving to next merge base
2016-10-13T23:55:41.4861061Z       INFO [10/14/16 10:55:41:48] End: Found merge base of 7a0e0b158886edd3b22eefdb1fb9f77026521cb7 against hotfix-2.2-summary-page (Took: 0.00ms)
2016-10-13T23:55:41.4861061Z       INFO [10/14/16 10:55:41:48] Begin: Found merge base of b06ab05566ec3e46305d06b95aeabf9a53fa6086 against hotfix-bug2654-web.config
2016-10-13T23:55:41.5017251Z       INFO [10/14/16 10:55:41:48] End: Found merge base of b06ab05566ec3e46305d06b95aeabf9a53fa6086 against hotfix-bug2654-web.config (Took: 0.00ms)
2016-10-13T23:55:41.5017251Z       INFO [10/14/16 10:55:41:50] Begin: Found merge base of 1e2487b3181bc82e7e55fd0311971146c21d21c6 against hotfix-supportweb-fix
2016-10-13T23:55:41.5017251Z         INFO [10/14/16 10:55:41:50] Merge base was due to a forward merge, moving to next merge base
2016-10-13T23:55:41.5017251Z       INFO [10/14/16 10:55:41:50] End: Found merge base of 1e2487b3181bc82e7e55fd0311971146c21d21c6 against hotfix-supportweb-fix (Took: 0.00ms)
2016-10-13T23:55:41.5017251Z     INFO [10/14/16 10:55:41:50] End: Finding branch source (Took: 187.52ms)
2016-10-13T23:55:41.5017251Z     INFO [10/14/16 10:55:41:50] Begin: Getting branches containing the commit 'c376c2695400eb1a258bf09292bc23f7dd000748'.
2016-10-13T23:55:41.5017251Z       INFO [10/14/16 10:55:41:50] Trying to find direct branches.
2016-10-13T23:55:41.5173473Z       INFO [10/14/16 10:55:41:50] Direct branch found: 'master'.
2016-10-13T23:55:41.5173473Z     INFO [10/14/16 10:55:41:51] End: Getting branches containing the commit 'c376c2695400eb1a258bf09292bc23f7dd000748'. (Took: 15.62ms)
2016-10-13T23:55:41.5173473Z     INFO [10/14/16 10:55:41:51] Found possible parent branches: master
2016-10-13T23:55:41.5173473Z   INFO [10/14/16 10:55:41:51] End: Attempting to inherit branch configuration from parent branch (Took: 312.52ms)
2016-10-13T23:55:41.5330799Z   INFO [10/14/16 10:55:41:53] Running against branch: feature-performancetesting (4d2cd258d5237c55a30b92e67f5d40e1ff5553fa)
2016-10-13T23:55:41.5330799Z   INFO [10/14/16 10:55:41:53] Begin: Calculating base versions
2016-10-13T23:55:41.5954929Z     INFO [10/14/16 10:55:41:59] Fallback base version: 0.1.0 with commit count source 93e085d56ea404f2d661fc6b97f9efc0f62b2fac
2016-10-13T23:55:41.6423969Z     INFO [10/14/16 10:55:41:64] Git tag 'v2.2.9': 2.2.9 with commit count source ca082ef924166f5a04ffeb19e7d54a047cc36ecf
2016-10-13T23:55:41.6579915Z     INFO [10/14/16 10:55:41:65] Git tag 'v2.2.8': 2.2.8 with commit count source 7a0e0b158886edd3b22eefdb1fb9f77026521cb7
2016-10-13T23:55:41.6737473Z     INFO [10/14/16 10:55:41:67] Git tag 'v2.2.7': 2.2.7 with commit count source 1e2487b3181bc82e7e55fd0311971146c21d21c6
2016-10-13T23:55:41.7362193Z     INFO [10/14/16 10:55:41:73] Merge message 'Merge database projects from release-2.2': 2.2.0 with commit count source b19f109c10450c3de48e19b33f14c0990a2c51cc
2016-10-13T23:55:41.7362193Z     INFO [10/14/16 10:55:41:73] Merge message 'Merge branch 'release-2.2'': 2.2.0 with commit count source a7f838407b69a8887e08fa7dc185290cb2781277
2016-10-13T23:55:41.7673823Z     INFO [10/14/16 10:55:41:76] Merge message 'Merge from release-2.2 v2.2.8 SupportWeb fix': 2.2.0 with commit count source 4fea2d180fe94864945c349f43c72b6264429e2f
2016-10-13T23:55:41.7829997Z     INFO [10/14/16 10:55:41:78] Found multiple base versions which will produce the same SemVer (2.3.0), taking oldest source for commit counting (Git tag 'v2.2.7')
2016-10-13T23:55:41.7829997Z     INFO [10/14/16 10:55:41:78] Base version used: Merge message 'Merge from release-2.2 v2.2.8 SupportWeb fix': 2.2.0 with commit count source 1e2487b3181bc82e7e55fd0311971146c21d21c6
2016-10-13T23:55:41.7829997Z   INFO [10/14/16 10:55:41:78] End: Calculating base versions (Took: 249.92ms)
2016-10-13T23:55:41.7986180Z   INFO [10/14/16 10:55:41:78] Using branch name to calculate version tag
2016-10-13T23:55:41.8299681Z   INFO [10/14/16 10:55:41:82] 38 commits found between 1e2487b3181bc82e7e55fd0311971146c21d21c6 and 4d2cd258d5237c55a30b92e67f5d40e1ff5553fa
2016-10-13T23:55:41.8299681Z   INFO [10/14/16 10:55:41:82] Begin: Creating dictionary
2016-10-13T23:55:41.8454977Z   INFO [10/14/16 10:55:41:82] End: Creating dictionary (Took: 0.00ms)
2016-10-13T23:55:41.8454977Z   INFO [10/14/16 10:55:41:82] Begin: Storing version variables to cache file C:\B\PRODUCT_NAME\_work\8\s\.git\gitversion_cache\A16C59AF972CF9FDB836687A1ABB281B4442B77E.yml
2016-10-13T23:55:41.8454977Z   INFO [10/14/16 10:55:41:84] End: Storing version variables to cache file C:\B\PRODUCT_NAME\_work\8\s\.git\gitversion_cache\A16C59AF972CF9FDB836687A1ABB281B4442B77E.yml (Took: 15.53ms)
2016-10-13T23:55:41.8454977Z GetVersion:
2016-10-13T23:55:41.8611255Z   INFO [10/14/16 10:55:41:84] Applicable build agent found: 'VsoAgent'.
2016-10-13T23:55:41.8611255Z   INFO [10/14/16 10:55:41:84] Branch from build environment: refs/heads/feature-performancetesting
2016-10-13T23:56:01.3157913Z   INFO [10/14/16 10:56:01:31] IsDynamicGitRepository: False
2016-10-13T23:56:01.3157913Z   INFO [10/14/16 10:56:01:31] Returning Project Root from DotGitDirectory: C:\B\PRODUCT_NAME\_work\8\s\.git - C:\B\PRODUCT_NAME\_work\8\s
2016-10-13T23:56:01.3314095Z   INFO [10/14/16 10:56:01:31] Project root is: C:\B\PRODUCT_NAME\_work\8\s
2016-10-13T23:56:01.3314095Z   INFO [10/14/16 10:56:01:31] DotGit directory is: C:\B\PRODUCT_NAME\_work\8\s\.git
2016-10-13T23:56:01.3470352Z   INFO [10/14/16 10:56:01:33] Begin: Loading version variables from disk cache
2016-10-13T23:56:01.3470352Z     INFO [10/14/16 10:56:01:34] Cache file C:\B\PRODUCT_NAME\_work\8\s\.git\gitversion_cache\3E9C61DCBB9FCF5BEBBDC5933796A9A5E3ED7398.yml not found.
2016-10-13T23:56:01.3470352Z   INFO [10/14/16 10:56:01:34] End: Loading version variables from disk cache (Took: 15.63ms)
2016-10-13T23:56:01.3626624Z   INFO [10/14/16 10:56:01:36] Using latest commit on specified branch
2016-10-13T23:56:01.3626624Z   INFO [10/14/16 10:56:01:36] Begin: Attempting to inherit branch configuration from parent branch
2016-10-13T23:56:01.4564184Z     INFO [10/14/16 10:56:01:45] Begin: Finding branch source
2016-10-13T23:56:01.5502446Z       INFO [10/14/16 10:56:01:55] Begin: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against develop
2016-10-13T23:56:01.5659035Z         INFO [10/14/16 10:56:01:56] Merge base was due to a forward merge, moving to next merge base
2016-10-13T23:56:01.5659035Z       INFO [10/14/16 10:56:01:56] End: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against develop (Took: 15.66ms)
2016-10-13T23:56:01.5970544Z       INFO [10/14/16 10:56:01:59] Begin: Found merge base of ca082ef924166f5a04ffeb19e7d54a047cc36ecf against hotfix-database2.2.8migration
2016-10-13T23:56:01.5970544Z         INFO [10/14/16 10:56:01:59] Merge base was due to a forward merge, moving to next merge base
2016-10-13T23:56:01.5970544Z       INFO [10/14/16 10:56:01:59] End: Found merge base of ca082ef924166f5a04ffeb19e7d54a047cc36ecf against hotfix-database2.2.8migration (Took: 0.00ms)
2016-10-13T23:56:01.6126808Z       INFO [10/14/16 10:56:01:59] Begin: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against master
2016-10-13T23:56:01.6126808Z       INFO [10/14/16 10:56:01:61] End: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against master (Took: 15.63ms)
2016-10-13T23:56:01.6126808Z       INFO [10/14/16 10:56:01:61] Begin: Found merge base of 7b67ca46208976a94417bee52f9dfa54aa45f315 against release-2.2
2016-10-13T23:56:01.6126808Z       INFO [10/14/16 10:56:01:61] End: Found merge base of 7b67ca46208976a94417bee52f9dfa54aa45f315 against release-2.2 (Took: 0.00ms)
2016-10-13T23:56:01.6126808Z       INFO [10/14/16 10:56:01:61] Begin: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against release-2.3
2016-10-13T23:56:01.6126808Z       INFO [10/14/16 10:56:01:61] End: Found merge base of c376c2695400eb1a258bf09292bc23f7dd000748 against release-2.3 (Took: 0.00ms)
2016-10-13T23:56:01.6126808Z       INFO [10/14/16 10:56:01:61] Begin: Found merge base of 7a0e0b158886edd3b22eefdb1fb9f77026521cb7 against hotfix-2.2-summary-page
2016-10-13T23:56:01.6283184Z         INFO [10/14/16 10:56:01:62] Merge base was due to a forward merge, moving to next merge base
2016-10-13T23:56:01.6283184Z       INFO [10/14/16 10:56:01:62] End: Found merge base of 7a0e0b158886edd3b22eefdb1fb9f77026521cb7 against hotfix-2.2-summary-page (Took: 15.64ms)
2016-10-13T23:56:01.6283184Z       INFO [10/14/16 10:56:01:62] Begin: Found merge base of b06ab05566ec3e46305d06b95aeabf9a53fa6086 against hotfix-bug2654-web.config
2016-10-13T23:56:01.6283184Z       INFO [10/14/16 10:56:01:62] End: Found merge base of b06ab05566ec3e46305d06b95aeabf9a53fa6086 against hotfix-bug2654-web.config (Took: 0.00ms)
2016-10-13T23:56:01.6283184Z       INFO [10/14/16 10:56:01:62] Begin: Found merge base of 1e2487b3181bc82e7e55fd0311971146c21d21c6 against hotfix-supportweb-fix
2016-10-13T23:56:01.6283184Z         INFO [10/14/16 10:56:01:62] Merge base was due to a forward merge, moving to next merge base
2016-10-13T23:56:01.6283184Z       INFO [10/14/16 10:56:01:62] End: Found merge base of 1e2487b3181bc82e7e55fd0311971146c21d21c6 against hotfix-supportweb-fix (Took: 0.00ms)
2016-10-13T23:56:01.6439444Z     INFO [10/14/16 10:56:01:64] End: Finding branch source (Took: 187.53ms)
2016-10-13T23:56:01.6439444Z     INFO [10/14/16 10:56:01:64] Begin: Getting branches containing the commit 'c376c2695400eb1a258bf09292bc23f7dd000748'.
2016-10-13T23:56:01.6439444Z       INFO [10/14/16 10:56:01:64] Trying to find direct branches.
2016-10-13T23:56:01.6439444Z       INFO [10/14/16 10:56:01:64] Direct branch found: 'master'.
2016-10-13T23:56:01.6439444Z     INFO [10/14/16 10:56:01:64] End: Getting branches containing the commit 'c376c2695400eb1a258bf09292bc23f7dd000748'. (Took: 0.00ms)
2016-10-13T23:56:01.6439444Z     INFO [10/14/16 10:56:01:64] Found possible parent branches: master
2016-10-13T23:56:01.6439444Z   INFO [10/14/16 10:56:01:64] End: Attempting to inherit branch configuration from parent branch (Took: 281.28ms)
2016-10-13T23:56:01.6595856Z   INFO [10/14/16 10:56:01:65] Running against branch: feature-performancetesting (4d2cd258d5237c55a30b92e67f5d40e1ff5553fa)
2016-10-13T23:56:01.6595856Z   INFO [10/14/16 10:56:01:65] Begin: Calculating base versions
2016-10-13T23:56:01.7376914Z     INFO [10/14/16 10:56:01:73] Fallback base version: 0.1.0 with commit count source 93e085d56ea404f2d661fc6b97f9efc0f62b2fac
2016-10-13T23:56:01.7846002Z     INFO [10/14/16 10:56:01:78] Git tag 'v2.2.9': 2.2.9 with commit count source ca082ef924166f5a04ffeb19e7d54a047cc36ecf
2016-10-13T23:56:01.8002068Z     INFO [10/14/16 10:56:01:80] Git tag 'v2.2.8': 2.2.8 with commit count source 7a0e0b158886edd3b22eefdb1fb9f77026521cb7
2016-10-13T23:56:01.8158339Z     INFO [10/14/16 10:56:01:81] Git tag 'v2.2.7': 2.2.7 with commit count source 1e2487b3181bc82e7e55fd0311971146c21d21c6
2016-10-13T23:56:01.8783265Z     INFO [10/14/16 10:56:01:87] Merge message 'Merge database projects from release-2.2': 2.2.0 with commit count source b19f109c10450c3de48e19b33f14c0990a2c51cc
2016-10-13T23:56:01.8940315Z     INFO [10/14/16 10:56:01:89] Merge message 'Merge branch 'release-2.2'': 2.2.0 with commit count source a7f838407b69a8887e08fa7dc185290cb2781277
2016-10-13T23:56:01.9095893Z     INFO [10/14/16 10:56:01:90] Merge message 'Merge from release-2.2 v2.2.8 SupportWeb fix': 2.2.0 with commit count source 4fea2d180fe94864945c349f43c72b6264429e2f
2016-10-13T23:56:01.9252059Z     INFO [10/14/16 10:56:01:90] Found multiple base versions which will produce the same SemVer (2.3.0), taking oldest source for commit counting (Git tag 'v2.2.7')
2016-10-13T23:56:01.9252059Z     INFO [10/14/16 10:56:01:90] Base version used: Merge message 'Merge from release-2.2 v2.2.8 SupportWeb fix': 2.2.0 with commit count source 1e2487b3181bc82e7e55fd0311971146c21d21c6
2016-10-13T23:56:01.9252059Z   INFO [10/14/16 10:56:01:90] End: Calculating base versions (Took: 250.00ms)
2016-10-13T23:56:01.9252059Z   INFO [10/14/16 10:56:01:92] Using branch name to calculate version tag
2016-10-13T23:56:01.9721358Z   INFO [10/14/16 10:56:01:97] 38 commits found between 1e2487b3181bc82e7e55fd0311971146c21d21c6 and 4d2cd258d5237c55a30b92e67f5d40e1ff5553fa
2016-10-13T23:56:01.9721358Z   INFO [10/14/16 10:56:01:97] Begin: Creating dictionary
2016-10-13T23:56:01.9721358Z   INFO [10/14/16 10:56:01:97] End: Creating dictionary (Took: 0.00ms)
2016-10-13T23:56:01.9721358Z   INFO [10/14/16 10:56:01:97] Begin: Storing version variables to cache file C:\B\PRODUCT_NAME\_work\8\s\.git\gitversion_cache\3E9C61DCBB9FCF5BEBBDC5933796A9A5E3ED7398.yml
2016-10-13T23:56:01.9721358Z   INFO [10/14/16 10:56:01:97] End: Storing version variables to cache file C:\B\PRODUCT_NAME\_work\8\s\.git\gitversion_cache\3E9C61DCBB9FCF5BEBBDC5933796A9A5E3ED7398.yml (Took: 0.00ms)
2016-10-13T23:56:02.0345976Z CoreCompile:

[roryprimrose]

I've tested some additional versions. 3.6.0, 3.6.1, 3.6.2 and 3.6.4 all have this performance issue. I didn't test 3.6.3 as there seemed to be little point.

[discomurray]

The reasoned I specifically mention 3.4.1 is that I thought the following versions have a dependency on a version of libgit2sharp has has some slow debugging code, and wasn't sure if the issues you were having was related to that or an actual caching issue.

Since 3.5.4 is performing similar, maybe the dependency was introduced then.

The current support branch has an update to use the latest libgit2sharp package without the debug code.

[asbjornu]

@discomurray: What slow debugging code are you referring to? If that's indeed the case, you might be on to something.

[discomurray]

see this issue in libgit2sharp libgit2/libgit2sharp#1368

[asbjornu]

@discomurray: Ah, thanks for the pointer. Is it worth hoping that @mkoertgen's work in #1024 might help on the performance issue (as well), then?

[mkoertgen]

At least the version of libgit2 matches, so probably yes.

[roryprimrose]

We downgraded for a few weeks to avoid the perf issues, but had to go back to 3.6.4 to get pull request id values in the version. Builds are back to > 20 minute builds. :(

[DanielRose]

@roryprimrose In 3.6.0 and 3.6.1, the caching of information was broken (#942). Could this be part of the problem you are seeing? Do you have separate repositories for each project or are they shared?

[roryprimrose]

If the caching was fixed after 3.6.1 then no as we are back up to 3.6.4. We have a repository per solution under the one VSTS account.