TFS agent-side checkout issue

Hi,

while using agent-side checkout with TFS I  noticed a strange behavior. After the first clean get I'd expect TC to  update the workspace doing a "Get Latest", while instead it looks like  it's trying to get all files from VCS.
I'm saying this because it  takes the same amount of time doing a clean get and a successive get and  furthermore monitoring the tfs-native process I notice it's doing a lot  of work in a temporary directory and in addition on the workspace.

10 comments

In case it's useful, here's the log from the agent during an incremental get which should take only a few seconds:

[2010-04-09 14:47:05,178]   INFO -    jetbrains.buildServer.AGENT - Found runner simpleRunner for 42320
[2010-04-09 14:47:05,193]   INFO - mpl$TeamCitySpringSubConatiner - Refreshing jetbrains.buildServer.spring.SpringSubContainerFactroyImpl$TeamCitySpringSubConatiner@c669e6: display name [SubContext: running build context id=jetbrains.buildServer.agent.impl.AgentRunningBuildImpl@a65f7a]; startup date [Fri Apr 09 14:47:05 CEST 2010]; parent: org.springframework.context.support.ClassPathXmlApplicationContext@1c56c60
[2010-04-09 14:47:05,209]   INFO - mpl$TeamCitySpringSubConatiner - Bean factory for application context [jetbrains.buildServer.spring.SpringSubContainerFactroyImpl$TeamCitySpringSubConatiner@c669e6]: org.springframework.beans.factory.support.DefaultListableBeanFactory@1ad53cf
[2010-04-09 14:47:05,225]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.runStages.ClearExpiredBuildWorkingDirectoriesStage
[2010-04-09 14:47:05,225]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.runStages.FireBuildStartedStage
[2010-04-09 14:47:05,225]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.runStages.CleanBuildCheckoutDirectoryIfNeededStage
[2010-04-09 14:47:05,225]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.runStages.CleanBuildTempDirectoryStage
[2010-04-09 14:47:05,225]   INFO - s.CleanBuildTempDirectoryStage - Clearing temporary directory: E:\BuildAgent\temp\buildTmp
[2010-04-09 14:47:05,240]   INFO - rectories.DirectoryCleanerImpl - Move directory E:\BuildAgent\temp\buildTmp to E:\BuildAgent\temp\.old\buildTmp_13 for cleaning
[2010-04-09 14:47:05,240]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.runStages.CleanAgentTempDirectoryStage
[2010-04-09 14:47:05,240]   INFO - rectories.DirectoryCleanerImpl - Move directory E:\BuildAgent\temp\agentTmp to E:\BuildAgent\temp\.old\agentTmp_13 for cleaning
[2010-04-09 14:47:05,240]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.runStages.CreateAgentTempDirectoryStage
[2010-04-09 14:47:05,240]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.runStages.CreateCheckoutDirectoryStage
[2010-04-09 14:47:05,240]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.runStages.CreateBuildTempDirectoryStage
[2010-04-09 14:47:05,240]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.runStages.DirectoryCleanerForceClean
[2010-04-09 14:47:05,568]   INFO - ges.DirectoryCleanerForceClean - Free space under build checkout directory is 215Gb, required 3Gb
[2010-04-09 14:47:05,568]   INFO - ges.DirectoryCleanerForceClean - Free space under temp directory is 215Gb, required 3Gb
[2010-04-09 14:47:05,568]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.runStages.CleanGeneratedFilesStage
[2010-04-09 14:47:05,568]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.runStages.LogCheckoutDirectoryStage
[2010-04-09 14:47:05,568]   INFO -    jetbrains.buildServer.AGENT - Checkout directory: E:\BuildAgent\work\b1b927ac7b01233
[2010-04-09 14:47:05,568]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.patch.UpdateSourcesFromAgent
[2010-04-09 14:47:05,568]   INFO - ch.UpdateSourcesBuildStageBase - Updating sources: Agent side checkout...
[2010-04-09 14:54:33,277]   INFO -    jetbrains.buildServer.AGENT - Patch applied for build 42320
[2010-04-09 14:54:33,277]   INFO - l.patch.UpdateSourcesFromAgent - Agent sources updated successfully
[2010-04-09 14:54:33,277]   INFO - ch.UpdateSourcesBuildStageBase - Sources updated for 7m:27s
[2010-04-09 14:54:33,277]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.patch.UpdateSourcesFromServer
[2010-04-09 14:54:33,277]   INFO - ch.UpdateSourcesBuildStageBase - Updating sources: server side checkout...
[2010-04-09 14:54:33,277]   INFO - ch.UpdateSourcesBuildStageBase - Sources updated for < 1s
[2010-04-09 14:54:33,277]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.patch.UpdateSourcesFromPersonal
[2010-04-09 14:54:33,277]   INFO - ch.UpdateSourcesBuildStageBase - Updating sources: personal build patch...
[2010-04-09 14:54:33,277]   INFO - ch.UpdateSourcesBuildStageBase - Sources updated for < 1s
[2010-04-09 14:54:33,277]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.runStages.AppendBuildParametersFromFileStage
[2010-04-09 14:54:33,277]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.runStages.ReplaceReferencesInAtrifactDependenciesStage
[2010-04-09 14:54:33,277]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.runStages.DownloadDependenciesStage
[2010-04-09 14:54:33,277]   INFO -    jetbrains.buildServer.AGENT - Finished resolving artifacts
[2010-04-09 14:54:33,277]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.runStages.SavePropertiesToFilesStage
[2010-04-09 14:54:33,309]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.runStages.CreateBuildWorkingDirectoryStage
[2010-04-09 14:54:33,309]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.runStages.FireBeforeRunnerStartedStage
[2010-04-09 14:54:33,309]   INFO - gent.impl.BuildRunTimeoutTimer - Build execution timeout is set to: 30
[2010-04-09 14:54:33,309]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.runStages.UpdateDirectoryMapStage
[2010-04-09 14:54:33,340]   INFO - ectories.DirectoryMapStructure - Remove expired build checkout directory for Nightly Builds::VDS (bt76) at b1b927ac7b01233
[2010-04-09 14:54:33,355]   INFO - rver.agent.impl.BuildRunAction - Call stage jetbrains.buildServer.agent.impl.runStages.CallRunnerStage
[2010-04-09 14:54:33,355]   INFO - impl.runStages.CallRunnerStage - Start actual runner for build 42320 simpleRunner

0

How many VCS root were used for the build configuration?

Do you run build agent and server on the same machine?

Does build agent TFS user account allowed to create TFS workspaces? Is that possible to create TFS workspace in the build checkout directory? Do you use default build checkout directory?

Please attach a dump of all TFS worcpaces on the machine with name containng TeamCity.

Thanks, sorry for delay!

0

How many VCS root were used for the build configuration?

1

Do you run build agent and server on the same machine?


No, different machines

Does build agent TFS user account allowed to create TFS workspaces? Is that possible to create TFS workspace in the build checkout directory? Do you use default build checkout directory?

3 Yeses. The workspace is created correctly, and it's populated correctly and the build runs successfully. The only problem I notice is on subsequent gets from VCS where they seem not to update the workspace but instead get all the files once again. Note however that the checkout directory (which is the same as the workspace) is not "cleaned and filled from scratch" just like it would happen on a clean checkout, instead the impression is that the TFS client is simply going over all files once again.
As a side note, if I log into the agent machine and open up an instance of VS running with the credentials of the agent service user (which is the same used to connect to TFS) - thus effectively being able to access the TC workspace - then doing a "get latest" operation is as fast as it's supposed to be, about a couple of seconds.

Please attach a dump of all TFS worcpaces on the machine with name containng TeamCity.

Ho do I do this?

Thanks, sorry for delay!

No problem

0

What Tfs is doing to update working copy are:
- refresh workspace
- revert all pending changes
- do update

Probably one of mentioned operations works faster if VS is running.

Do you use checkout rules? Please attach rules.

0

eugene.petrenko wrote:

What Tfs is doing to update working copy are:
- refresh workspace
- revert all pending changes
- do update

Probably one of mentioned operations works faster if VS is running.

Do you use checkout rules? Please attach rules.


What does it mean to "refresh the workspace"?
There should not be any pending changes on th workspace so I don't think it should be talking long.
The update itself should take only a few seconds, since we are tyring it out and usually there are no changes on the VCS.

Note that when I said that from VS it's faster I mean doing that FROM Visual Studio, not from TeamCity while VS is running.

No checkout rules as per the docs which say that they are not performant when checking out on the agent side.

0

I found the bug. I'll attach you a patch as the result.

0

Thanks, I'll be waiting for the patch. Please take into account that we're running 5.0.2, not yet upgraded to 5.0.3, in case it makes any difference.

0

I've added an issue for you at
http://youtrack.jetbrains.net/issue/TW-11601

BTW. Not TFS implentation on agent performs TFS update to a version with overwrite of all files. The fix will start performing update only for changed files (i.e. TFS Get Latest Version command)

Please watch or vote for the issue. I'll attach a patch there.

0

Please sign in to leave a comment.