Builds take a long time to Start

Many of our builds now take longer to start than they take to complete.

When I start a build, either manually or via a build trigger, the running build reports:

TeamCity server version is 7.1.1 (build 24074)

for well over a minute. When you click on build log, there are no entries.

When it gets past the above message, the build log then contains:

Checking for Changes


for about 3 minutes.

Here is a snippet from the build log through the TeamCity UI:

[03:18:55]Checking for changes
[03:21:41]Swabra


Here is what is in teamcity-server.log. The build configuration name I manually triggered is MyProject :: MyBuild {id=bt2364}:

[2012-09-28 03:16:51,797]   INFO - ity.BuildQueuePriorityOrdering - New item QueuedBuildImpl{myBuildType=MyProject :: MyBuild {id=bt2364},ItemId=3936283} with weight 0.00 inserted at the default position 0 in the end of the queue 
[2012-09-28 03:16:51,933]   INFO - tbrains.buildServer.ACTIVITIES - Build of "MyProject :: MyBuild" was added to queue by "Tony Carl"
[2012-09-28 03:16:51,943]   INFO - tbrains.buildServer.ACTIVITIES - Configuration added to queue; name=MyProject :: MyBuild {id=bt2364}; requestor=Tony Carl; promotion id=3936283
[2012-09-28 03:16:53,055]   INFO - tbrains.buildServer.ACTIVITIES - Build started; name=MyProject :: MyBuild, personal=false, buildId=1342223
[2012-09-28 03:16:53,073]   INFO - tbrains.buildServer.ACTIVITIES - Configuration removed from queue; name=MyProject :: MyBuild, requestor=Tony Carl, comment=null, user=null, promotion id=3936283
[2012-09-28 03:16:53,073]   INFO -   jetbrains.buildServer.SERVER - Flush queue finished, number of builds started: 1
[2012-09-28 03:17:00,060]   INFO -   jetbrains.buildServer.SERVER - Agent description updated for agent: Agent i02 {id=34, host=192.168.9.27:9095, agentTypeId=20, pool=Default}
[2012-09-28 03:17:51,742]   INFO -   jetbrains.buildServer.SERVER - Agent description updated for agent: Agent m01 {id=26, host=192.168.9.27:9096, agentTypeId=12, pool=Default}
[2012-09-28 03:17:56,402]   INFO -   jetbrains.buildServer.SERVER - Agent description updated for agent: Agent d02 {id=28, host=192.168.9.27:9091, agentTypeId=14, pool=Default}
[2012-09-28 03:18:03,030]   INFO -   jetbrains.buildServer.SERVER - Agent description updated for agent: Agent d05 {id=14, host=192.168.9.70:9090, agentTypeId=11, pool=Default}
[2012-09-28 03:18:13,686]   INFO -   jetbrains.buildServer.SERVER - Agent description updated for agent: Agent p10 {id=42, host=192.168.9.70:9102, agentTypeId=28, pool=Default}
[2012-09-28 03:18:13,744]   INFO -   jetbrains.buildServer.SERVER - Agent description updated for agent: Agent p06 {id=36, host=192.168.9.70:9100, agentTypeId=22, pool=Default}
[2012-09-28 03:18:15,117]   INFO -   jetbrains.buildServer.SERVER - Agent description updated for agent: Agent p08 {id=41, host=192.168.9.70:9101, agentTypeId=27, pool=Default}
[2012-09-28 03:18:17,433]   INFO -   jetbrains.buildServer.SERVER - Agent description updated for agent: Agent p12 {id=43, host=192.168.9.70:9103, agentTypeId=29, pool=Default}
[2012-09-28 03:18:17,477]   INFO -   jetbrains.buildServer.SERVER - Agent description updated for agent: Agent p03 {id=22, host=192.168.9.70:9098, agentTypeId=3, pool=Default}
[2012-09-28 03:18:17,483]   INFO -   jetbrains.buildServer.SERVER - Agent description updated for agent: Agent p04 {id=23, host=192.168.9.70:9099, agentTypeId=1, pool=Default}
[2012-09-28 03:18:50,287]   INFO -   jetbrains.buildServer.SERVER - Agent description updated for agent: Agent m01 {id=26, host=192.168.9.27:9096, agentTypeId=12, pool=Default}
[2012-09-28 03:19:08,655]   INFO -   jetbrains.buildServer.SERVER - Agent description updated for agent: Agent d08 {id=17, host=192.168.9.70:9093, agentTypeId=6, pool=Default}
[2012-09-28 03:19:13,208]   INFO -   jetbrains.buildServer.SERVER - Agent description updated for agent: Agent i04 {id=19, host=192.168.9.70:9095, agentTypeId=10, pool=Default}
[2012-09-28 03:19:20,600]   INFO -   jetbrains.buildServer.SERVER - Agent description updated for agent: Agent i03 {id=18, host=192.168.9.70:9094, agentTypeId=7, pool=Default}
[2012-09-28 03:21:14,274]   INFO -   jetbrains.buildServer.SERVER - Agent description updated for agent: Agent m02 (Calculon x64) {id=30, host=192.168.9.27:9097, agentTypeId=16, pool=Default}
[2012-09-28 03:21:34,208]   INFO -   jetbrains.buildServer.SERVER - Agent description updated for agent: Agent m02 (Calculon x64) {id=30, host=192.168.9.27:9097, agentTypeId=16, pool=Default}
[2012-09-28 03:21:41,454]   INFO -   jetbrains.buildServer.SERVER - Running build saved to DB: MyProject :: MyBuild {id=bt2364} #2012.928.274 {build id=1342223}, promotion id 3936283, on agent Agent d02, triggered by ##userId='35'
[2012-09-28 03:21:41,486]   INFO -   jetbrains.buildServer.SERVER - Agent description updated for agent: Agent m02 (Calculon x64) {id=30, host=192.168.9.27:9097, agentTypeId=16, pool=Default}
[2012-09-28 03:21:58,810]   INFO -   jetbrains.buildServer.SERVER - Agent description updated for agent: Agent d02 {id=28, host=192.168.9.27:9091, agentTypeId=14, pool=Default}
[2012-09-28 03:22:09,289]   INFO -   jetbrains.buildServer.SERVER - Agent description updated for agent: Agent d02 {id=28, host=192.168.9.27:9091, agentTypeId=14, pool=Default}
[2012-09-28 03:22:11,659]   INFO -   jetbrains.buildServer.SERVER - Agent description updated for agent: Agent d02 {id=28, host=192.168.9.27:9091, agentTypeId=14, pool=Default}
[2012-09-28 03:23:42,721]   INFO - de.impl.history.DBBuildHistory - Start creating history entry for SomeOtherProject :: SomeOtherBuild 1342220, date: 1348816900151
[2012-09-28 03:23:42,770]   INFO - de.impl.history.DBBuildHistory - End creating history entry for SomeOtherProject :: SomeOtherBuild 1342220
[2012-09-28 03:23:42,927]   INFO - ndexer.EventBasedBuildsIndexer - Indexing finishing build: #8988 {build id=1342220}
[2012-09-28 03:23:42,935]   INFO - tbrains.buildServer.ACTIVITIES - Finished 1342220
[2012-09-28 03:24:00,092]   INFO -   jetbrains.buildServer.SERVER - Agent description updated for agent: Agent d02 {id=28, host=192.168.9.27:9091, agentTypeId=14, pool=Default}
[2012-09-28 03:25:44,891]   INFO - de.impl.history.DBBuildHistory - Start creating history entry for MyProject :: MyBuild 1342223, date: 1348817039456
[2012-09-28 03:25:44,944]   INFO - de.impl.history.DBBuildHistory - End creating history entry for MyProject :: MyBuild 1342223
[2012-09-28 03:25:45,512]   INFO - ndexer.EventBasedBuildsIndexer - Indexing finishing build: #2012.928.274 {build id=1342223}
[2012-09-28 03:25:45,515]   INFO - tbrains.buildServer.ACTIVITIES - Finished 1342223



Here is the snippet from the teamcity-vcs.log (again the build configuration is MyProject :: MyBuild {id=bt2364}):

[2012-09-28 03:21:39,501]   INFO [ng build bt2364] -      jetbrains.buildServer.VCS - Finish collecting changes for svn: http://src/svn/k2/trunk/MyProject/MyBuild {instance id=27787, parent id=345} from state SingleVersionRState{97955_2012/09/28 03:15:36 -0400 at Fri Sep 28 03:21:39 EDT 2012} to state SingleVersionRState{97955_2012/09/28 03:20:41 -0400 at Fri Sep 28 03:21:39 EDT 2012}; 0 changes collected 0 changes reported, time spent: 34ms 
[2012-09-28 03:21:39,516]   INFO [ parent id=345}] -      jetbrains.buildServer.VCS - Finish collecting changes for svn: http://src/svn/k2/trunk/UnrelatedProject/UnrelatedBuild {instance id=28025, parent id=345} from state SingleVersionRState{97955_2012/09/28 03:15:35 -0400 at Fri Sep 28 03:21:39 EDT 2012} to state SingleVersionRState{97955_2012/09/28 03:20:42 -0400 at Fri Sep 28 03:21:39 EDT 2012}; 0 changes collected 0 changes reported, time spent: 33ms
[2012-09-28 03:21:39,540]   INFO [parent id=345}]] -      jetbrains.buildServer.VCS - Finished collecting changes for build configurations [MyProject :: MyBuild {id=bt2364}], time spent: 2m:44s,194ms
[2012-09-28 03:21:41,397]   WARN [riggers Monitor] - MavenSnapshotDependencyTrigger - No external snapshot dependencies found - nothing to check; Build type: DifferentProject :: DifferentBuildConfiguration {id=bt2076}
[2012-09-28 03:21:44,318]   INFO [ parent id=345}] -      jetbrains.buildServer.VCS - Finish collecting changes for svn: http://src/svn/k2/trunk/ProjectA/ConfigA {instance id=28043, parent id=345} from state SingleVersionRState{97955_2012/09/28 03:14:51 -0400 at Fri Sep 28 03:21:44 EDT 2012} to state SingleVersionRState{97955_2012/09/28 03:20:41 -0400 at Fri Sep 28 03:21:44 EDT 2012}; 0 changes collected 0 changes reported, time spent: 12ms
[2012-09-28 03:21:44,727]   INFO [TeamCity Agent ] -      jetbrains.buildServer.VCS - Setting build revisions on agent=Agent d02 {id=28, host=192.168.9.27:9091, agentTypeId=14, pool=Default}, buildPromotion=BuildPromotion{myId=3936283, myPersonal=false, myBuildTypeId='bt2364', myModificationId=84191, myRevisions=[BuildRevision[myVcsRootEntry=VcsRootEntry[myVcsRoot=svn: http://src/svn/k2/trunk/MyProject/MyBuild {instance id=27787, parent id=345}, myCheckoutRules==>
], myRevision=RepositoryVersion{myVersion='97203_2012/09/24 16:54:34 -0400', myDisplayVersion='97203', myVcsBranch='null'}]], myAssociatedBuildId=1342223, myBranch=}, revisions={svn: http://src/svn/k2/trunk/MyProject/MyBuild {instance id=27787, parent id=345}=97203_2012/09/24 16:54:34 -0400}


As you can see, it took 2m:44s,194ms to collect changes.

Most of our builds use one parameterized VCS root (approximately 183 build configurations) on SVN. We use the name of the project and build configuration to map to the needed sub directory in the VCS root.

For example:
http://src/svn/k2/trunk/%RelativeToTrunkVcsRoot%
Where:
%RelativeToTrunkVcsRoot%
is defined in the build template to be:
%env.TEAMCITY_PROJECT_NAME%/%env.TEAMCITY_BUILDCONF_NAME%

We do not use checkout rules and use checkout on agent mode.

Any ideas on how we can improve performance?

TeamCity webserver runs on a virtual Ubuntu Linux box with six cores and 10GB of ram, 8GB is dedicated to TeamCity WebServer. The web interface usually seems slow as well.

2 comments
Comment actions Permalink

This slow start can also affect build configurations without attached VCS roots.

0

Please sign in to leave a comment.