Getting source code takes a long time on two agents

I've done some searching of the forums and open issues for this but couldn't find anything recent. We have a TC server with some thirty-odd projects on it and have three agents. All agents are configured identically as far as I can tell except for the ports. All run as services with the same user account on a Windows 2003 server. TeamCity itself is on a separate Windows 2003 server. As far as I can tell, the permissions are identical for each agent's folder.

The issue is that for two agents (the second two we set up), retrieving source takes a pretty long time. Sometimes hours. But on the first agent, it is fine. Usually takes a few minutes depending on the project. I've verified this happens for projects that use SVN as well as ones that use GIT.

For SVN, we have configured the projects to checkout automatically on the server and we don't use the default checkout directory. That is, we specify a directory for the agents to checkout to (D:\Builds\<projectName>). We do not have the option set to clean all files before a build. For Git, projects are configured to checkout on the agent and we don't specify a checkout directory for those. Again, we don't clean before we build.

We're using TeamCity 4.5.3 (build 9035). I notice there is a new version and I was about to install it to see if it will solve the issue. But I see this has happened to others so perhaps there is something else at play here?

9 comments
Comment actions Permalink

Could you please make a simple test: try to download an artifact from the TeamCity server on these three agents and see whether the same problem persists. If so then issue can be related to agent hardware or operating system settings.

0
Comment actions Permalink

Pavel,

Not sure if this was the right procedure but here's what I did:

- Found a project that has recently been built on all three agents. It took 47 seconds on the first agent and 38 min and 48 min on the other two respectively
- Download the artifacts from each build. They total about 6MB each.

Based on that, there was no discernible difference in the download times.

Thanks
Kyle

0
Comment actions Permalink

Could you please compare build logs of slow and fast builds, is it possible that slow builds always receive clean patch (clean checkout), while fast build receives incremental patch?

0
Comment actions Permalink

You may be on to something but I can't find anything consistent. Sometimes it's not able to delete a temp directory but that doesn't always indicate whether it will be slow or fast. It looks like all three agents have both slow and fast builds though so my original assumption that one was working and the other two weren't was incorrect.

Here is the history for one project that is representative of the problem we're having (you can log in as a guest)

http://teamcity.codebetter.com/viewType.html?buildTypeId=bt5&tab=buildTypeHistoryList

Feel free to look through some of the other projects if they will help.

Thanks
Kyle

0
Comment actions Permalink

Pavel,

Upon re-reading the documentation, I think it could be a problem with our configuration: http://www.jetbrains.net/confluence/display/TCD4/Setting+up+and+Running+Additional+Build+Agents

At the bottom it says that they shouldn't be using an absolute checkout directory (which we have for most projects) or that we should enable "clean checkout" and ensure builds can't run in parallel. Which alternative would you recommend?

0
Comment actions Permalink

Custom checkout directory should not be a problem. At least in this case. In the logs of the slow build I see:

[14:02:18]: Updating sources (11s)
[14:02:14]: [Updating sources] Building incremental patch for VCS root: SourceForge SVN
[14:02:30]: [Updating sources] Repository sources transferred: 46.55Kb total
[14:02:30]: [Updating sources] Updating D:\Builds\StructureMap
[14:51:20]: Starting build process in D:\Builds\StructureMap


Note that 49 minutes were spent on some activity after the sources were updated but before build was started. Unfortunately the only way to determine what was this activity is to take a look at the agent log. Probably you can ask administrators of teamcity.codebetter.com to provide agent logs when next time this problem occurs.
0
Comment actions Permalink

Pavel,

I am one of the administrators for that server. I found the logs for that agent but only the wrapper.log had anything from that date. Here is the entry for that specific build:

INFO   | jvm 1    | 2009/07/07 14:02:30 | [2009-07-07 14:02:30,218]   WARN - tories.DirectoryMapPersistance - Failed to save directory.map to D:\BuildAgent-02\work\directory.map. D:\BuildAgent-02\work\directory.map (Access is denied) 
INFO   | jvm 1    | 2009/07/07 14:02:30 | java.io.FileNotFoundException: D:\BuildAgent-02\work\directory.map (Access is denied)
INFO   | jvm 1    | 2009/07/07 14:02:30 |     at java.io.FileOutputStream.open(Native Method)
INFO   | jvm 1    | 2009/07/07 14:02:30 |     at java.io.FileOutputStream.<init>(FileOutputStream.java:179)
INFO   | jvm 1    | 2009/07/07 14:02:30 |     at java.io.FileOutputStream.<init>(FileOutputStream.java:131)
INFO   | jvm 1    | 2009/07/07 14:02:30 |     at java.io.FileWriter.<init>(FileWriter.java:73)
INFO   | jvm 1    | 2009/07/07 14:02:30 |     at jetbrains.buildServer.agent.impl.directories.DirectoryMapPersistance.writeFile(DirectoryMapPersistance.java:108)
INFO   | jvm 1    | 2009/07/07 14:02:30 |     at jetbrains.buildServer.agent.impl.directories.DirectoryMapPersistance.save(DirectoryMapPersistance.java:102)
INFO   | jvm 1    | 2009/07/07 14:02:30 |     at jetbrains.buildServer.agent.impl.directories.DirectoryMapPersistance.withDirectoriesMap(DirectoryMapPersistance.java:40)
INFO   | jvm 1    | 2009/07/07 14:02:30 |     at jetbrains.buildServer.agent.impl.directories.DirectoryMapImpl.updateDirectoryMapOnBuild(DirectoryMapImpl.java:98)
INFO   | jvm 1    | 2009/07/07 14:02:30 |     at jetbrains.buildServer.agent.impl.directories.DirectoryMapWatcher.beforeRunnerStart(DirectoryMapWatcher.java:98)
INFO   | jvm 1    | 2009/07/07 14:02:30 |     at sun.reflect.GeneratedMethodAccessor19.invoke(Unknown Source)
INFO   | jvm 1    | 2009/07/07 14:02:30 |     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
INFO   | jvm 1    | 2009/07/07 14:02:30 |     at java.lang.reflect.Method.invoke(Method.java:585)
INFO   | jvm 1    | 2009/07/07 14:02:30 |     at jetbrains.buildServer.util.EventDispatcher.dispatch(EventDispatcher.java:83)
INFO   | jvm 1    | 2009/07/07 14:02:30 |     at jetbrains.buildServer.util.EventDispatcher$1.invoke(EventDispatcher.java:38)
INFO   | jvm 1    | 2009/07/07 14:02:30 |     at $Proxy7.beforeRunnerStart(Unknown Source)
INFO   | jvm 1    | 2009/07/07 14:02:30 |     at jetbrains.buildServer.agent.impl.BuildAgentImpl$1.beforeRunnerStarted(BuildAgentImpl.java:233)
INFO   | jvm 1    | 2009/07/07 14:02:30 |     at jetbrains.buildServer.agent.impl.runStages.FireBeforeRunnerStartedStage.doBuildStage(FireBeforeRunnerStartedStage.java:21)
INFO   | jvm 1    | 2009/07/07 14:02:30 |     at jetbrains.buildServer.agent.impl.BuildRunAction.doStages(BuildRunAction.java:135)
INFO   | jvm 1    | 2009/07/07 14:02:30 |     at jetbrains.buildServer.agent.impl.BuildRunAction.access$000(BuildRunAction.java:21)
INFO   | jvm 1    | 2009/07/07 14:02:30 |     at jetbrains.buildServer.agent.impl.BuildRunAction$1.run(BuildRunAction.java:91)
INFO   | jvm 1    | 2009/07/07 14:02:30 |     at java.lang.Thread.run(Thread.java:595)
INFO   | jvm 1    | 2009/07/07 14:52:00 | [2009-07-07 14:52:00,796]   WARN - tories.DirectoryMapPersistance - Failed to save directory.map to D:\BuildAgent-02\work\directory.map. D:\BuildAgent-02\work\directory.map (Access is denied) 
INFO   | jvm 1    | 2009/07/07 14:52:00 | java.io.FileNotFoundException: D:\BuildAgent-02\work\directory.map (Access is denied)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at java.io.FileOutputStream.open(Native Method)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at java.io.FileOutputStream.<init>(FileOutputStream.java:179)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at java.io.FileOutputStream.<init>(FileOutputStream.java:131)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at java.io.FileWriter.<init>(FileWriter.java:73)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at jetbrains.buildServer.agent.impl.directories.DirectoryMapPersistance.writeFile(DirectoryMapPersistance.java:108)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at jetbrains.buildServer.agent.impl.directories.DirectoryMapPersistance.save(DirectoryMapPersistance.java:102)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at jetbrains.buildServer.agent.impl.directories.DirectoryMapPersistance.withDirectoriesMap(DirectoryMapPersistance.java:40)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at jetbrains.buildServer.agent.impl.directories.DirectoryMapImpl.moveExpired2Old(DirectoryMapImpl.java:129)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at jetbrains.buildServer.agent.impl.directories.DirectoryMapWatcher$1.run(DirectoryMapWatcher.java:61)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at jetbrains.buildServer.agent.impl.directories.DirectoryMapWatcher.addCleanupAlarm(DirectoryMapWatcher.java:82)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at jetbrains.buildServer.agent.impl.directories.DirectoryMapWatcher.buildFinished(DirectoryMapWatcher.java:104)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at sun.reflect.GeneratedMethodAccessor21.invoke(Unknown Source)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at java.lang.reflect.Method.invoke(Method.java:585)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at jetbrains.buildServer.util.EventDispatcher.dispatch(EventDispatcher.java:83)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at jetbrains.buildServer.util.EventDispatcher$1.invoke(EventDispatcher.java:38)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at $Proxy7.buildFinished(Unknown Source)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at jetbrains.buildServer.agent.impl.BuildAgentImpl$1.buildFinished(BuildAgentImpl.java:257)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at jetbrains.buildServer.agent.impl.BuildRunAction$1$1.run(BuildRunAction.java:104)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at jetbrains.buildServer.agent.impl.GuardedAction.runGuarded(GuardedAction.java:29)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at jetbrains.buildServer.agent.impl.BuildRunAction$1.run(BuildRunAction.java:102)
INFO   | jvm 1    | 2009/07/07 14:52:00 |     at java.lang.Thread.run(Thread.java:595)

0
Comment actions Permalink

Pavel,

From that log, the problem appears to be permission-related. I checked the server and the account that is running the agent services did not have explicit write permissions to the work folders in *any* of the agents. I added it (as well as to the temp and agent home directories as per documentation) and I think that has solved the issue. That is, I re-ran a couple of builds on the various agents and it no longer hangs on the update step as it did before.

0
Comment actions Permalink

Glad to hear the problem is not reproducing anymore.

0

Please sign in to leave a comment.