Skip to content
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

Extremely slow UpdateAssemblyInfo in GitVersionTask #437

Closed
asbjornu opened this issue May 6, 2015 · 44 comments
Closed

Extremely slow UpdateAssemblyInfo in GitVersionTask #437

asbjornu opened this issue May 6, 2015 · 44 comments

Comments

@asbjornu
Copy link
Member

asbjornu commented May 6, 2015

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
Copy link
Member

gep13 commented May 6, 2015

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

@asbjornu
Copy link
Member Author

asbjornu commented May 6, 2015

@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
Copy link
Member

gep13 commented May 7, 2015

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

@asbjornu
Copy link
Member Author

asbjornu commented May 7, 2015

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
Copy link
Contributor

Do you have the same issue locally?

@asbjornu
Copy link
Member Author

asbjornu commented May 7, 2015

@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
Copy link
Member

gep13 commented May 7, 2015

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
Copy link
Member Author

asbjornu commented May 7, 2015

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
Copy link
Member Author

asbjornu commented May 7, 2015

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
Copy link
Member Author

asbjornu commented May 7, 2015

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
Copy link
Member

gep13 commented May 7, 2015

@SimonCropp can you offer any suggestions on this one?

@SimonCropp
Copy link
Contributor

can you share the repo? perhaps privately?

Can you try an earlier version of GitVersion?

@JakeGinnivan
Copy link
Contributor

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
Copy link
Member Author

asbjornu commented May 7, 2015

@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
Copy link
Contributor

@JakeGinnivan
Copy link
Contributor

It should look at all branches, find the oldest common commit and that be the hard stop

@orjan
Copy link
Contributor

orjan commented May 7, 2015

Not much help, but we had a similar behavior with an early version of GV3 but then it was pretty obvious since it was +30000 commits in the meta data. Will test the repo again to see if it's possible to reproduce

On 7 maj 2015, at 17:12, Jake Ginnivan notifications@github.com wrote:

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..


Reply to this email directly or view it on GitHub.

@asbjornu
Copy link
Member Author

asbjornu commented May 7, 2015

@JakeGinnivan So the code that might be causing the slowness can be reduced to these few lines:

excludedBranches.ToList().ForEach(excludedInheritBranches.Add);

var branchPoint = currentBranch.FindCommitBranchWasBranchedFrom(repository, onlyEvaluateTrackedBranches, excludedInheritBranches.ToArray());

List<Branch> possibleParents;
if (branchPoint.Sha == currentCommit.Sha)
{
    possibleParents = currentCommit.GetBranchesContainingCommit(repository, true).Except(excludedInheritBranches).ToList();
}
else
{
    var branches = branchPoint.GetBranchesContainingCommit(repository, true).Except(excludedInheritBranches).ToList();
    var currentTipBranches = currentCommit.GetBranchesContainingCommit(repository, true).Except(excludedInheritBranches).ToList();
    possibleParents = branches
        .Except(currentTipBranches)
        .ToList();
}

@gep13
Copy link
Member

gep13 commented May 8, 2015

@asbjornu have you tested with these changes? Did it fix your problem?

@asbjornu
Copy link
Member Author

asbjornu commented May 8, 2015

@SimonCropp, @gep13, Downgrading to version 3.0.0-beta0001 did nothing, but version 2.0.1 definitely sped things up locally. Downgrading (to both versions) seems to have removed all logging to the build output, is this as expected (i.e. logging was added in beta 2)?

@JakeGinnivan, One thing GitVersion should do regardless of the performance of BranchConfigurationCalculator.InheritBranchConfiguration() is cache the result between different projects in the same solution. Can't it just write out an environment variable or do some other MSBuild voodoo to transfer the calculated version from the first project to the rest?

@JakeGinnivan
Copy link
Contributor

@asbjornu I know there are caching things it does locally already, so that might happen. @SimonCropp may know more

At any rate, it should be super fast to do this. I didn't even think about perf when writing it unfortunately

@asbjornu
Copy link
Member Author

asbjornu commented May 8, 2015

@JakeGinnivan The build output I pasted originally is repeated for every project in the solution with the same hop in time between HEAD is merge commit ... and Found possible parent branches: ..., so I'm not seeing any caching of the result from BranchConfigurationCalculator.InheritBranchConfiguration().

@asbjornu
Copy link
Member Author

Since adding MiniProfiler to GitVersionTask have brought me into a FileNotFoundException dead end, I thought that GitVersion.exe might be a simpler way to get profiling data.

However, when I ran it in the same solution, GitVersion.exe quite surprisingly executed in only 2,2 seconds. How is that possible? Do I need to provide any arguments for it to go through the same code path as GitVersionTask?

Here's my profiling branch if @JakeGinnivan, @gep13, @SimonCropp or anyone else wants to have a look at it. For completeness, here's the profile results from GitVersion.exe:

 GitVersionExe = 2 279,8ms
> VerifyArgumentsAndRun = 2 268,6ms
>> BranchConfigurationCalculator.GetBranchConfiguration = 1 695,8ms
>>> BranchConfigurationCalculator.InheritBranchConfiguration = 1 688,5ms
>>>> LibGitExtensions.FindCommitBranchWasBranchedFrom = 856,1ms
>>>>> LibGitExtensions.GetBranchesContainingCommit = 11,9ms
>>>>>> Finding direct branch = 11,7ms
>>>>> LibGitExtensions.GetBranchesContainingCommit = 2,2ms
>>>>>> Finding direct branch = 2,2ms
>>>>> LibGitExtensions.GetBranchesContainingCommit = 811,2ms
>>>>>> Finding direct branch = 1,7ms
>>>>>> Finding branches sharing commits = 809,5ms
>>>> Finding possible parents = 800,2ms
>>>>> LibGitExtensions.GetBranchesContainingCommit = 798,1ms
>>>>>> Finding direct branch = 2ms
>>>>>> Finding branches sharing commits = 796ms
>>>>> LibGitExtensions.GetBranchesContainingCommit = 2ms
>>>>>> Finding direct branch = 2ms
>>>> BranchConfigurationCalculator.GetBranchConfiguration = 0ms

If you could just help me get MiniProfiler working in GitVersionTask, I can get profile results for it too. The problem is that MSBuild complains that it can't find MiniProfiler when I execute the GitVersionTask that has the MiniProfiler reference:

The "WriteVersionInfoToBuildLog" task failed unexpectedly.
System.IO.FileNotFoundException: Could not load file or assembly 'MiniProfiler, Version=3.1.1.140, Culture=neutral, PublicKeyToken=b44f9351044011a3' or one of its dependencies. The system cannot find the file specified.
File name: 'MiniProfiler, Version=3.1.1.140, Culture=neutral, PublicKeyToken=b44f9351044011a3'
   at GitVersionTask.WriteVersionInfoToBuildLog.Execute()
   at Microsoft.Build.BackEnd.TaskExecutionHost.Microsoft.Build.BackEnd.ITaskExecutionHost.Execute()
   at Microsoft.Build.BackEnd.TaskBuilder.<ExecuteInstantiatedTask>d__20.MoveNext()

@JakeGinnivan
Copy link
Contributor

This should be fixed now, I was doing something very stupid when trying to find the source branches. It now should be fast.

Reopen/create a new issue if it's still an issue (test against master)

@asbjornu
Copy link
Member Author

asbjornu commented Jun 8, 2015

@JakeGinnivan I've tried to make a custom build and replace the local GitVersionTask package, and it looks better, but still slower than on version 2. To be sure, it would be great with a beta 3 build on NuGet. Would that be possible to get out the door anytime soon?

@JakeGinnivan
Copy link
Contributor

We need to add logging then so we can see what is taking the time. I can still see stuff which would be slow though

@asbjornu
Copy link
Member Author

asbjornu commented Jun 8, 2015

@JakeGinnivan I've started a branch that adds MiniProfiler, but it got kind of borked after a rebase, so I can redo that if you'd like? If profiling should be merged into master, some kind of abstraction should be added on top of MiniProfiler, so GitVersion doesn't expose it as a requirement.

@JakeGinnivan
Copy link
Contributor

If we add more logging, and the logging logs out timestamps we should have a pretty good idea what is slow without adding profiling in. Up to you though

@asbjornu
Copy link
Member Author

asbjornu commented Jun 8, 2015

@JakeGinnivan True. It's just that MiniProfiler keeps track of nesting and provides nice formatting with indentation and such, as you can see here. I'll see what I can do.

@JakeGinnivan
Copy link
Contributor

@asbjornu I have pushed v3-beta.3. Let me know how you go

@asbjornu
Copy link
Member Author

@JakeGinnivan Thanks, I've updated and tried again. While performance is much better, version 3 is still quite a bit slower than version 2. A clear problem still is that the version number isn't successfully cached between projects within the same solution. This shows up in the build log for all projects in the solution on TeamCity:

[WriteVersionInfoToBuildLog] Version not in cache. Calculating version.

This of course leads to GitVersion doing fetch and various other things it shouldn't need to do more than once for the entire solution. The UpdateAssemblyInfo step therefore takes 24 seconds for the first project, then ~10 seconds for each project after that. For a large enough solution, seconds quickly accumulate to minutes, which is unfortunate.

@JakeGinnivan
Copy link
Contributor

Ok cool, still work to do but getting there it seems. 24 seconds is still no where near acceptable, it should be <1 second to run.

Any thoughts on a big oss repo which shows off the issues so I can test?

@asbjornu
Copy link
Member Author

@JakeGinnivan I expect that GitVersionTask's performance in NServiceBus is impeccable? If not, that's a pretty obvious place to start. :)

Then you have NHibernate, of course. No idea if it actually shows any of the problems I have, but let's hope it does. :)

@JakeGinnivan
Copy link
Contributor

@asbjornu I have just merged logging improvements into the release/3.0.0 branch

It adds basic timing information and scoping, I am trying to close a few of the issues over this weekend so I will try to profile on a larger repo but just letting you know if you want to look into it as well :)

@asbjornu
Copy link
Member Author

asbjornu commented Jul 6, 2015

@JakeGinnivan Awesome! How do I enabled more verbose logging output when building in Visual Studio?

@asbjornu
Copy link
Member Author

asbjornu commented Jul 8, 2015

@JakeGinnivan, I now built with MSBuild and got the following output:

UpdateAssemblyInfo:
  INFO [07/08/15 14:57:03:21] Version not in cache. Calculating version.
  INFO [07/08/15 14:57:03:21] Project root is: C:\Redacted
MSBUILD : warning : WARN [07/08/15 14:57:03:21] No specific commit specified or found, falling back to latest commit on specified branch [Redacted.csproj]
  INFO [07/08/15 14:57:03:21] Begin: Attempting to inherit branch configuration from parent branch
    INFO [07/08/15 14:57:03:21] Begin: Finding branch source
    INFO [07/08/15 14:57:03:31] End: Finding branch source (Took: 93.53ms)
    INFO [07/08/15 14:57:03:31] Found possible parent branches: develop
  INFO [07/08/15 14:57:03:31] End: Attempting to inherit branch configuration from parent branch (Took: 93.53ms)
  INFO [07/08/15 14:57:03:32] Running against branch: feature/git-version-task (388add67f18efa8d778  9cc028c4718579c73ce13)
  INFO [07/08/15 14:57:03:32] Begin: Calculating base versions
    INFO [07/08/15 14:57:03:34] Fallback base version: 0.1.0 with commit count source 24a25cc2b5b9bc3863f25221cce626840e16f58a
    INFO [07/08/15 14:57:03:43] Git tag '4.1.2': 4.1.2 with commit count source 2eb0f5a38feadfab1dcf13edff33efb52634c2c5
    INFO [07/08/15 14:57:03:43] Git tag '4.1.1': 4.1.1 with commit count source 315a7329576248bb55036238d3131bbc52dc13c6
    INFO [07/08/15 14:57:03:45] Git tag '4.0.1': 4.0.1 with commit count source e18a5cab9e34b4e48be788422a36112a7d0432b5
    INFO [07/08/15 14:57:03:45] Git tag '3.7.4': 3.7.4 with commit count source 36f7d510706cebaa80d902c761dcd27c576ddb4d
    INFO [07/08/15 14:57:03:45] Git tag '3.7.3': 3.7.3 with commit count source a973f35e0bab398bda7474317df025e85244256b
    INFO [07/08/15 14:57:03:45] Git tag '3.7.2': 3.7.2 with commit count source 096294f8a1e966d142b0f8def0782dabc18d59ee
    INFO [07/08/15 14:57:03:45] Git tag '3.7.1': 3.7.1 with commit count source 59a0764702d930b434c99e744727b2bd50032b79
    INFO [07/08/15 14:57:03:45] Git tag '3.6.13': 3.6.13 with commit count source beea70b11c680af160bd3cad0757efd118d4da05
    INFO [07/08/15 14:57:03:45] Git tag '3.6.12': 3.6.12 with commit count source 96fc75b72e3ac39daac0f432135164fc1e230158
    INFO [07/08/15 14:57:03:45] Git tag '3.6.11': 3.6.11 with commit count source beac4b4969bf4ff692f774be14a4d0269524cc95
    INFO [07/08/15 14:57:03:45] Git tag '3.6.10': 3.6.10 with commit count source d85ecd5519c77d8179a34a28c26f097d64c0aa89
    INFO [07/08/15 14:57:03:45] Git tag '3.6.9': 3.6.9 with commit count source 97eeb1fd87034b81278113fc684495f361a792eb
    INFO [07/08/15 14:57:03:45] Git tag '3.6.8': 3.6.8 with commit count source cca550938fbc6f25676559ad82427c34a22ebb4a
    INFO [07/08/15 14:57:03:45] Git tag '3.6.7': 3.6.7 with commit count source 92ae0e5f04f187bdcc91a32db07681c84f7add81
    INFO [07/08/15 14:57:03:45] Git tag '3.6.6': 3.6.6 with commit count source 7fc2374fee83a42912fbcba64857e0d64336ad12
    INFO [07/08/15 14:57:03:45] Git tag '3.6.5': 3.6.5 with commit count source 790b0f9b9587f2c6c85e6290bcb9e11fc080ffe9
    INFO [07/08/15 14:57:03:46] Git tag '3.6.4': 3.6.4 with commit count source 9bd5340cdd5465ab7fc61f26bbc01fedcc4a7666
    INFO [07/08/15 14:57:03:46] Git tag '3.6.3': 3.6.3 with commit count source b7a086d886e198a2291242c182691bb2a95fa6b1
    INFO [07/08/15 14:57:03:46] Git tag '3.6.2': 3.6.2 with commit count source 1ac21f3296f90d1f2d0e4de5b6a3b780496f92af
    INFO [07/08/15 14:57:03:46] Git tag '3.6.1': 3.6.1 with commit count source ca8b2e60f8745a33f310e65ffcccc6dc35522bf3
    INFO [07/08/15 14:57:03:46] Git tag '3.5.8': 3.5.8 with commit count source 8336038ada43fdfb5b742defcffb4f5d8311ba16
    INFO [07/08/15 14:57:03:46] Git tag '3.5.7': 3.5.7 with commit count source de87fc9eb10d8fcecc100f1a4e6758dafb21c90c
    INFO [07/08/15 14:57:03:46] Git tag '3.5.6': 3.5.6 with commit count source af1b9d6337b986f49637754889a25439aadf61d4
    INFO [07/08/15 14:57:03:46] Git tag '3.5.5': 3.5.5 with commit count source b535fc3e86c2378d222e4d46e5586196386603f1
    INFO [07/08/15 14:57:03:46] Git tag '3.5.4': 3.5.4 with commit count source 06e185fc5b5fa1a022bcdb44d057271158f72c58
    INFO [07/08/15 14:57:03:46] Git tag '3.5.3': 3.5.3 with commit count source 923aab9fde6f454c87d2990f2ed0bfcc123b9664
    INFO [07/08/15 14:57:03:46] Git tag '3.5.2': 3.5.2 with commit count source b6c3af35b1daa6fa7e442fc06a23228c960cc8da
    INFO [07/08/15 14:57:03:46] Git tag '3.5.1': 3.5.1 with commit count source b19292f3a2ff431f256e4d2b4394e89e33f4b957
    INFO [07/08/15 14:57:03:46] Git tag '3.4.14': 3.4.14 with commit count source 822c94cfa66d8193b51a7d81c27c93772305a215
    INFO [07/08/15 14:57:03:46] Git tag '3.4.13': 3.4.13 with commit count source d9586d194c87ee3979f1f9eb0ecc9a353c698fbb
    INFO [07/08/15 14:57:03:48] Git tag '3.4.12': 3.4.12 with commit count source 650119ba7a8334f520c2bbee6e0091148ccf7c1f
    INFO [07/08/15 14:57:03:48] Git tag '3.4.11': 3.4.11 with commit count source bf3321d0a1256110f575a160dcf1bf0a1f843098
    INFO [07/08/15 14:57:03:48] Git tag '3.4.10': 3.4.10 with commit count source a7f279a080874e3c67c964e80e7e6ff1af518674
    INFO [07/08/15 14:57:03:48] Git tag '3.4.9': 3.4.9 with commit count source 8d36ade2b70b70a4ffc2db523381291522515fa5
    INFO [07/08/15 14:57:03:48] Git tag '3.4.8': 3.4.8 with commit count source 6d1efe4553e2d51f32b7a27b314dc7eecca3209a
    INFO [07/08/15 14:57:03:48] Git tag '3.4.7': 3.4.7 with commit count source b1ae5db57f8afbd2642c8e4bfd42c0519fe74a3e
    INFO [07/08/15 14:57:03:48] Git tag '3.4.6': 3.4.6 with commit count source a7811247e205e2cf602f3c3a0417fa20fe3f90c6
    INFO [07/08/15 14:57:03:48] Git tag '3.4.5': 3.4.5 with commit count source 22165ccbb1e9d92c566ccd2df5ceeb3a7bd23ef7
    INFO [07/08/15 14:57:03:48] Git tag '3.4.4': 3.4.4 with commit count source 7454cced26b6dacbb0a52086e956330264ab8f66
    INFO [07/08/15 14:57:03:48] Git tag '3.4.3': 3.4.3 with commit count source 3b032b3c1a35bb2c683df2826095243d1cfd66d4
    INFO [07/08/15 14:57:03:48] Git tag '3.4.2': 3.4.2 with commit count source 1f7623e95c1704ebc4d78e6dc10f6f7048d195bc
    INFO [07/08/15 14:57:03:48] Git tag '3.4.1': 3.4.1 with commit count source 60369ad2a41d48ded7889d8b6a42a160dbf87fd4
    INFO [07/08/15 14:57:03:48] Git tag '3.3.1': 3.3.1 with commit count source 1012929cd4c76623651c7db36e0be95f6d44d857
    INFO [07/08/15 14:57:03:48] Git tag '3.2.2': 3.2.2 with commit count source 537d4906efc552000c75928ba0f1cc9d96661be5
    INFO [07/08/15 14:57:03:62] Found multiple base versions which will produce the same SemVer (4.2.0), taking oldest source for commit counting (Git tag '4.1.1')
    INFO [07/08/15 14:57:03:62] Base version used: Git tag '4.1.2': 4.1.2 with commit count source 315a7329576248bb55036238d3131bbc52dc13c6
  INFO [07/08/15 14:57:03:62] End: Calculating base versions (Took: 296.22ms)
  INFO [07/08/15 14:57:03:62] Using branch name to calculate version tag
  INFO [07/08/15 14:57:03:63] 26 commits found between 315a7329576248bb55036238d3131bbc52dc13c6 and 388add67f18efa8d7789cc028c4718579c73ce13

While things look much better, Version not in cache. Calculating version. looks troubling. Why is the version number not cached properly between each project being built?

@JakeGinnivan
Copy link
Contributor

Will have to look into it some time, not that familiar with the MSBuild task. Need to change that

@asbjornu
Copy link
Member Author

asbjornu commented Jul 8, 2015

@JakeGinnivan I think it would speed things up considerably if the version number was actually cached between projects in a solution. Should I open a separate bug for that?

@JakeGinnivan
Copy link
Contributor

Yeah, it will allow someone to pick it up and sort that issue in isolation

@EbenZhang
Copy link
Contributor

The GetBranchesContainingCommit is reaaaaally slow on my repo which has 150 branches (including both remote and local) and 5500 commits. It recently takes 6 to 30 minutes but sometimes more than an hour for some old pull requests(I'm using teamcity build GitHub pull request, the local ref/branch name is pull/<1234>/merge), sometimes just few seconds especially when building a branch not a pull request.

By contrast, the git command line just takes less than 1 second to get the branches that contains a commit. git branch -r --contains <sha> for remote branches, git branch -r <sha> for local branches.

I'm new to gitversion and libgit2sharp's code. Wondering if it's possible to use git command line rather than libgit2sharp, or maybe there's some equivalent APIs in libgit2sharp we can call?

@asbjornu
Copy link
Member Author

@EbenZhang If libgit2 has support for it, then libgit2sharp should as well. So please explore its API and find a way to do it fulfilling the same requirement but in a quicker way. I'm sure @JakeGinnivan would highly appreciate it. I know at least I would.

Without such a venture, #711 should at least ensure that GetBranchesContainingCommit isn't called more than once per solution, which might improve things.

@EbenZhang
Copy link
Contributor

libgit2sharp has the below code to get the LOCAL branches for a commit:

private IEnumerable<Branch> ListBranchesContainingCommit(Repository repo, string commitSha)
{
    var localHeads = repo.Refs.Where(r => r.IsLocalBranch());

    var commit = repo.Lookup<Commit>(commitSha);
    var localHeadsContainingTheCommit = repo.Refs.ReachableFrom(localHeads, new[] { commit });

    return localHeadsContainingTheCommit
        .Select(branchRef => repo.Branches[branchRef.CanonicalName]);
}

I'm not sure how is the performance, and not sure how to get the REMOTE branches.

I've implemented using git command to get the branches for a commit and tag, it helps to reduce the time from 20min(2hours worst case) to 1 minute. I'll clean up my code, do more tests, probably need to fix the unit tests as well, and then create a pull request (hopefully this week)

@asbjornu
Copy link
Member Author

@EbenZhang Excellent! Looking forward to seeing the PR! 😄 👍

@EbenZhang
Copy link
Contributor

See #734

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

6 participants