MS Team Foundation VCS root, Collecting changes takes long time

Hi,

We have a TeamCity server set up running against a TFS off site.

Our problem is that it takes a very long time for TeamCity to collect changes before starting to build. Usually that takes about 7-20 minutes regardless if there are any changes or not. After the collection the actual build begins, and then the progress bar starts over from 0. Sometimes it says "Changes already collected" but still takes forever ( Ok not forever, its still very good build times compared Team Build that we used before, but you get spoiled...).

Some notes about our setup, don't know what is of interest:

* We have many build definitions (about 100) set up against one single VCS root.
* Team Foundation Server is on remote site, so the connection speed varies, but never to this extent when communicating with it using Team explorer, it's about seconds.
* We are using MS SQL Server as storage.

I know that it's little to go on to begin with, but the problem seems to be adding up. When we first started the TeamCity server this was not an issue.

If you have any ideas what I can do to improve the performance and maybe get rid of these long waiting times that'd be appriciated.

Roger

11 comments
Comment actions Permalink

Additional info : Using Team City Enterprise V4.5.4 (build 9071)

0
Comment actions Permalink

Clould you please attach checkout rules and the TFS root screenshot?

How many files are there under TFS?

Does TeamCity and TFS server works under the same time zone?

How many commits were done between two succeeding builds?

Please try running the following commands:
tc-tfs-native.exe /log http://tfs-server:port /user:USERNAME /password:PASSWORD result.txt v
tc-tfs-native.exe /log http://tfs-server:port /user:USERNAME /password:PASSWORD result2.txt c $/PROJECT_PATH LAST_BUILD_TFS_REVISION c
tc-tfs-native.exe /log http://tfs-server:port /user:USERNAME /password:PASSWORD result3.txt c $/PROJECT_PATH 1 c

Please capture console output of those runs and produced result*.txt files.

tc-tfs-native*.exe file is located under TeamCity server temp folder: <teamcity server>/temp

Please attach TeamCity server debug logs as described at http://www.jetbrains.net/confluence/display/TCD4/Reporting+Issues

Thanks!

0
Comment actions Permalink

Hi, and thanks for your answer.

For company policy reasons I cannot post specifics like log files and screen dumps unless masked. I could probably send them to you directly if thats ok. However:

Our TFS project is quite big, I dont know any way of counting the files but I suspect that it's nearly 200.000 files. Our dev team is sharing this several other teams. I don't know their file count overall.

We are using one VCS root and that is used by 108 build definitions with checkout rules that looks something like: Each component has unique checkout rule that gets it's specific sources.
+:DotNet/Main/ComponentA=>ComponentA
+:DotNet/Main/Support=>Support
+:DotNet/Main/Libraries=>Libraries

The TFS Server is located in US GMT-8 while our Teamcity server is in Sweden GMT+1, so no they are not in the same time zone.

There does not have to be any changes for it to take a long time.I can just press "Run" on a build definition (No pending changes) and it will take several minutes before the build starts.

I ran the commands that you suggested. First result is
<?xml version="1.0" encoding="utf-8"?>
<GetCurrentVersion formatVersion="3" currentVersion="16072" />

Second result

<?xml version="1.0" encoding="utf-8"?>
<CollectBuildChanges formatVersion="3" currentVersion="c">
  <Modification version="16072" user="###USER###" changeDate="1257349389460" description="">
    <FileChange changeName="edit" relative="####FilePATH#####.cs" beforeVersion="16071" afterVersion="16072" />
  </Modification>
</CollectBuildChanges>

Third reslut is 2MB big and contains 10000 rows, and contains a bit too much info to be masked manually, and I don submit it.

I attach the CMD output, with some masked parameters, and without the final changeset dump of all changes since beginning of times.

I'll try to get the other log files with the instructions you posted, but maybe this gives some hints in the meantime.



Attachment(s):
cmdoutput.txt.zip
0
Comment actions Permalink

Hello,

Please send the logs to teamcity-feedback@jetbrains.com

I've checked log you've attached. Please check the third run. It seems to have some mistakes because of commandline error. You may start the tool without parameters to see the usage.

Do you have fast connection to from TeamCity server to TFS server?

How much time did it take to run those commands?

How long does it taked to checkout all sources from TFS server?

Thanks!

0
Comment actions Permalink

Roger posted the original post here and I'm his colleague.

Although we've been busy with other things during the last month this is still a major issue for us.

It takes approximately 30 minutes to "check for changes" and I believe it's the the last command of your three commands that takes all that time. It then takes like two minutes to build each project.

This creates very long delays for our builds even though we have three build agents. It often results in the team members noticing broken builds before TeamCity gets to it

Somehow we have to find a solution, as this is a major problem for us.

Thanks,
Linus

0
Comment actions Permalink

Please attach TeamCity server debug logs as described at http://www.jetbrains.net/confluence/display/TCD4/Reporting+Issues

You may use either ftp://ftp.intellij.net/.uploads or teamcity-feedback@jetbrains.com

How fast is the connection between TFS server and TeamCity server?
How long will it take to checkout all sources of the project unsing TeamExplorer from the TeamCity server machine?

Do you use clean checkout? Agent side checkout? What is the version of Team Explorer? What is the version of TFS Server?
Thanks!

0
Comment actions Permalink

I can't get the logfiles quite yet as I can't get to the server today and we have a deadline on monday.

I have greatly decreased the time it takes to collect changes though. I did this by changing the VCS root to a lower level in TFS tree. But one would think this should have no effect because we still have the same checkout rules, but apparently it isn't so?

The build time has gone from about an hour to around 15-17 minutes by making this change. This is great. But 10 minutes of those are still used to update sources. See this part of the build log :

[11:44:17]: bt134
[11:44:17]: Changes are already collected
[11:44:20]: Clean build enabled: removing old files from E:\BuildAgent\work\6b470fd2dd905124
[11:44:20]: Clearing temporary directory: E:\BuildAgent\temp\buildTmp
[11:44:22]: Checkout directory: E:\BuildAgent\work\6b470fd2dd905124
[11:44:22]: Updating sources
[11:44:22]:  [Updating sources] Updating project sources
[11:44:22]:   [Updating project sources]  *** Removed checkout rules ***
[11:53:54]: Starting build process in E:\BuildAgent\work\6b470fd2dd905124

Is TeamCity fetching everything from scratch each time or is it just getting the latest changes? If it's the first case I would guess it might take the same amount of time locally on a dev PC but if it's just getting the latest changes that should take no more than a minute or so.

We are using clean checkout. In one test I did I reduced the time by 4 minutes by not doing clean checkouts but we must do this.

We use agent side checkout.

TFS is 2008 but not sure if SP1 is applied or not (and it's hard to check because it's somewhere across the atlantic ocean)

The speed should be fairly good but I'm not sure how good. I would guess 10Mbit but have really no idea.

What do you think? Is it worth spending more time investigating this or do you think we'll have to live with the 10 minutes of updating sources?

Thanks for your help,
Linus

0
Comment actions Permalink

We are also experiencing some severe delays with getting the latest from TFS.  See the extract below from the log for one of our builds:

[12:01:43]: Skip checking for changes - changes are already collected
[12:01:42]: Clearing temporary directory: C:\BuildAgent\temp\buildTmp
[12:01:42]: Checkout directory: C:\TC\OK52\pOnKey\Main
[12:01:42]: Updating sources: Agent side checkout... (4m:44s)
[12:01:42]: [Updating sources: Agent side checkout...] VCS Root: OK52_pOnKey_Main (4m:44s)
[12:01:42]: [VCS Root: OK52_pOnKey_Main] revision: 27371
[12:06:26]: NUnit report watcher
[12:06:26]: [NUnit report watcher] Watching paths:
[12:06:26]: [NUnit report watcher] C:\TC\OK52\pOnKey\Main\Source\Pragma.OnKey5.Client.Tests\bin\Debug\Pragma.OnKey5.Client.Tests.dll.TestResult.xml
[12:06:26]: [NUnit report watcher] C:\TC\OK52\pOnKey\Main\Source\Pragma.OnKey5.Tests\bin\Debug\Pragma.OnKey5.Tests.dll.TestResult.xml
[12:06:26]: NUnit report watcher
[12:06:26]: [NUnit report watcher] Found existing files:
[12:06:26]: [NUnit report watcher] C:\TC\OK52\pOnKey\Main\Source\Pragma.OnKey5.Client.Tests\bin\Debug\Pragma.OnKey5.Client.Tests.dll.TestResult.xml
[12:06:26]: [NUnit report watcher] C:\TC\OK52\pOnKey\Main\Source\Pragma.OnKey5.Tests\bin\Debug\Pragma.OnKey5.Tests.dll.TestResult.xml
[12:06:26]: Starting build process in C:\TC\OK52\pOnKey\Main
[12:06:27]: Project "Pragma.OnKey5.proj.teamcity.patch.tcprojx" (IISResetWebSite;SQLResetInstance;CleanCode;BuildAll;Test;IISResetWebSite;SQLResetInstance target(s)): (5m:23s)
[12:06:27]: [Project "Pragma.OnKey5.proj.teamcity.patch.tcprojx" (IISResetWebSite;SQLResetInstance;CleanCode;BuildAll;Test;IISResetWebSite;SQLResetInstance target(s)):] SdkPath: C:\Program Files\Microsoft SDKs\Windows\v6.1\ FrameworkPath: C:\Windows\Microsoft.NET\Framework\v3.5


Some observations:
  1. We are using Agent side checkout, i.e. TC creates a workspace on every agent to get the information from TFS.
  2. This specific build has no changes to collect, but it still tacks 4m:44s before TC actually starts running the actual MSBuild build script!!
  3. We originally used Server side checkout but this resulted in file locking issues when secondary builds fired off after each other
  4. We have no checkout rules specified for the configuration
  5. We are running TC 5.0 (Build 10669)
  6. We use SQL Server 2005 as DB
  7. The TFS database is not that big.  As mentioned, for Server side checkouts we didn't have this performance problem (but unfortunately have the file locking issue).


Please advise what to do and what additional info you'll need.  I'll try and get some logs through using the steps highlighted above.  Our current build times have just about doubled since switching from Server side to Agent side checkouts and it is causing immense frustration for the team.

Thanks

0
Comment actions Permalink

I'll try to reproduce the case with generated TFS history of ~27000 changelists.

Could you please try profiling the client with dotTrace. You may download it from www.jetbrains.com for free.

Please try profiling the following commandline:
tc-tfs-native.exe /log http://tfs-server:port /user:USERNAME /password:PASSWORD result2.txt c $/PROJECT_PATH 0 c

and

tc-tfs-native.exe /log http://tfs-server:port /user:USERNAME /password:PASSWORD result2.txt c $/PROJECT_PATH <latest change list number - 10> c

If agent side checkout and clean sources on build are used, it will perform checkout from TFS on every build. TeamCity server will cache a full patch in that case.

How may checking were there between previous and next build on the same agent?

I think, 10 minutes is too muck to update source for server side checkout and for agent size checkout with disabled chean sources feature.

BTW: Have you tried to setup TFS Proxy server on the Sweden side?

0
Comment actions Permalink

Hello,

What was the issue of server side checkout? Could you please elaborate.


I'll try to reproduce the case with generated TFS history of ~27000 changelists.
Could you please try profiling the client with dotTrace. You may download it from www.jetbrains.com for free.

Please try profiling the following commandline:
tc-tfs-native.exe /log http://tfs-server:port /user:USERNAME /password:PASSWORD result2.txt c $/PROJECT_PATH 0 c

and

tc-tfs-native.exe /log http://tfs-server:port /user:USERNAME /password:PASSWORD result2.txt c $/PROJECT_PATH <latest change list number - 10> c



Do you use clean build checkout directory option?

What is the latest change list number? How many change lists are checked in between two builds?

Please attach teamcity-vcs*log files from <server>/logs folder.
0
Comment actions Permalink

Eugene

I assume I need to profile the build agent and not the server?  I can only find a tfs-native.exe on the build agent and not a tc-tfs-native.exe.

To answer your other questions:

  1. We do not use the clean checkout option
  2. The current latest changeset number is 27470.
  3. Because we run on every checkin, the changeset typically includes between 1-5 changes.  Doing a get latest version using Team Explorer is quick on the build agent.
  4. Find attached the log file as requested.


I'll start with the profiling and send through these logs as well.



Attachment(s):
teamcity-vcs.log.zip
0

Please sign in to leave a comment.