Slow Artifact Dependency Resolution

Just a quick update, removed the clean step, and it's still taking a while.

Nowhere near as bad, but I could still perform a 'build' of my libs in that time potentially.
I can work with 8 minutes, while not ideal, it's definitely better than 22 minutes.

Thanks,

Hello Jim.

Surely, 8 minutes is far too much for 200Mb archive.

While your set up seems ok, could you please enable sever and agent debug logging and post results, relevant to artifact resolution process, here?

Hi Nikita,

Looking at another example in our build logs suggest the following, that the build was started at 11:19 and lasted 18 minutes

#101

Success

17 Jan 12 11:19

18m:23s

None

Pin

So checking the Agent logs in teamcity-build.log, I can see the first activity relating to this step was at 11:36:
[2012-01-17 11:36:16,526] out - ----------------------------------------- [ Tools::Deploy PC HAL Packages #101 (buildId = 958) ] -----------------------------------------



So it appears that the job isn't being sent to the machine until 11:36? - here's the agent log from teamcity-agent.log:
[2012-01-17 11:36:16,526]   INFO - erStages.start.CallRunnerStage - Found runner simpleRunner for 958
[2012-01-17 11:36:16,526]   INFO - erStages.start.CallRunnerStage - Start build runner for build 958 simpleRunner
[2012-01-17 11:36:16,526]   INFO - erStages.start.CallRunnerStage - ----------------------------------------- [ Tools::Deploy PC HAL Packages #101 (buildId = 958) ] -----------------------------------------
[2012-01-17 11:36:16,555]   INFO - nner2.OsProcessHandlerListener - C:\BuildAgent\work\7d9fb3b885c52763\Tests\HAL\packages\_BuildPackages.bat PC
[2012-01-17 11:37:37,796]   INFO - nner2.OsProcessHandlerListener -  
[2012-01-17 11:37:37,797]   INFO - ildStages.RunnerStagesExecutor - Call stage jetbrains.buildServer.agent.impl.buildStages.runnerStages.start.InternalErrorsChecker
[2012-01-17 11:37:37,821]   INFO - mpl$TeamCitySpringSubConatiner - Closing jetbrains.buildServer.spring.SpringSubContainerFactroyImpl$TeamCitySpringSubConatiner@1bb4302: display name [SubContext: running build runner context id=958 runner 2 of 2]; startup date [Tue Jan 17 11:36:16 GMT 2012]; parent: jetbrains.buildServer.spring.SpringSubContainerFactroyImpl$TeamCitySpringSubConatiner@4d7fd5
[2012-01-17 11:37:37,829]   INFO - ernalArtifactsProcessingLogger - Publishing artifacts process started
[2012-01-17 11:37:37,829]   INFO - ernalArtifactsProcessingLogger - Start: Searching for artifacts to publish
[2012-01-17 11:37:37,830]   INFO - ernalArtifactsProcessingLogger - Done:  Searching for artifacts to publish
[2012-01-17 11:37:37,830]   INFO - ernalArtifactsProcessingLogger - Start: Pre-processing artifacts if needed (archiving)
[2012-01-17 11:37:37,830]   INFO - ernalArtifactsProcessingLogger - Done: Pre-processing artifacts if needed (archiving)
[2012-01-17 11:37:37,830]   INFO - ernalArtifactsProcessingLogger - Publishing artifacts process started
[2012-01-17 11:37:37,830]   INFO - ernalArtifactsProcessingLogger - Start: Searching for artifacts to publish
[2012-01-17 11:37:37,830]   INFO -    jetbrains.buildServer.AGENT - Internal artifact path teamcity-info.xml not found
[2012-01-17 11:37:37,830]   INFO - ernalArtifactsProcessingLogger - Done:  Searching for artifacts to publish
[2012-01-17 11:37:37,830]   INFO - ernalArtifactsProcessingLogger - Start: Pre-processing artifacts if needed (archiving)
[2012-01-17 11:37:37,830]   INFO - ernalArtifactsProcessingLogger - Done: Pre-processing artifacts if needed (archiving)
[2012-01-17 11:37:37,830]   INFO -    jetbrains.buildServer.AGENT - Publishing artifacts process started
[2012-01-17 11:37:37,831]   INFO -    jetbrains.buildServer.AGENT - Start: Searching for artifacts to publish
[2012-01-17 11:37:37,837]   INFO -    jetbrains.buildServer.AGENT - Done:  Searching for artifacts to publish
[2012-01-17 11:37:37,837]   INFO -    jetbrains.buildServer.AGENT - Start: Pre-processing artifacts if needed (archiving)
[2012-01-17 11:37:42,806]   INFO - ernalArtifactsProcessingLogger - Start: Sending files
[2012-01-17 11:37:42,816]   INFO - ernalArtifactsProcessingLogger - Done publishing artifacts to .teamcity/properties, total files published: 1
[2012-01-17 11:37:42,816]   INFO - ernalArtifactsProcessingLogger - Done: Sending files
[2012-01-17 11:37:42,822]   INFO - ernalArtifactsProcessingLogger - Publishing artifacts process finished
[2012-01-17 11:37:43,391]   INFO -    jetbrains.buildServer.AGENT - Done: Pre-processing artifacts if needed (archiving)


Here's hopefully the relevent info from the Server machine's log, but let me know if you need anything else:
[2012-01-17 11:16:17,682]   INFO - tbrains.buildServer.ACTIVITIES - Configuration added to queue; name=Tools :: Deploy PC HAL Packages {id=bt7}; requestor=Subversion; Runtime PC :: Run HAL PC Tests; promotion id=1286
[2012-01-17 11:19:15,200]   INFO - tbrains.buildServer.ACTIVITIES - Build started; name=Tools :: Deploy PC HAL Packages, personal=false, buildId=958
[2012-01-17 11:19:15,202]   INFO - tbrains.buildServer.ACTIVITIES - Configuration removed from queue; name=Tools :: Deploy PC HAL Packages, requestor=Subversion; Runtime PC :: Run HAL PC Tests, comment=null, user=null, promotion id=1286
[2012-01-17 11:19:15,202]   INFO -   jetbrains.buildServer.SERVER - Flush queue finished, number of builds started: 1
[2012-01-17 11:19:15,228]   INFO -   jetbrains.buildServer.SERVER - Running build saved to DB: Tools :: Deploy PC HAL Packages {id=bt7} # #101 {build id=958} on agent pc623 triggered by ##vcsName='svn' buildTypeId='bt9'
[2012-01-17 11:37:38,522]   INFO - de.impl.history.DBBuildHistory - Start creating history entry for Tools :: Deploy PC HAL Packages 958, date: 1326800263000
[2012-01-17 11:37:38,523]   INFO - de.impl.history.DBBuildHistory - End creating history entry for Tools :: Deploy PC HAL Packages 958
[2012-01-17 11:37:38,527]   INFO - tbrains.buildServer.ACTIVITIES - Finished 958


Thanks for your assistance.

Having read your response more thoroughly, I've yet to enable debug logging, and am still using the default values for logs.
I'll enable the debug logging for both server and agent, and get back to you with some more useful info.

Jim,

My mistake: would you mind attaching debug logs once you have them (instead of posting)?

ok, I think I've enabled the Debug server and agent logging, but can't see anything specifically different in them (just more of them), so perhaps I've made a mistake in following the required steps somewhere.

I've attached the relevent logs for the times we're seeing the problem.
In this example, we're looking at 'Tools::Create/Update Database #26 (buildId = 1032)'

which performs the following:

Jim,

Thank you for the logs. Though they showed no clue to root cause of the issue.

Do you have slow artifact resolution for all build configurations on the server, or just for this specific one?

Can you try to download artifact to agent machine without unpacking? To do this, just limit the pattern to EditorExes*.zip
Also, to get a comparison, would you mind to try to download artifact to agent machine manually (eg., via TeamCity UI)?

The slow artifact resolution can appear on any artifact dependent config on this server.

One thing to note is that as far as I can see, it's only happening when the artifacts are created on a different machine to the one running the current step.
Eg. PC898 builds my Editor executables, then PC623 runs my world file deployment step (which needs my Editor's exes from PC898)

Downloading the zip itself through the UI as 'open' (saving to %temp%) took roughly 2-3 mins averaging at 3MB/sec, but interestingly failed at the final percent due to a connection to the server being 'reset', tried this twice and both failed.
Downloading the zip itself through the UI as 'save' (saving to 'Downloads') was pretty much instant, and completed successfully.

I've just attempted limiting to 'EditorExes*.zip' as suggested, and the same problem persists.


Perhaps this server connection reset issue is causing the problem?

Thanks for all the suggestions so far.

EDIT: Just attempted to download the zip through the UI with Firefox, and had better luck, that final percentage causing IE to give up, took Firefox an extra minute to resolve. So that's about 4 minutes in itself.

JimParker wrote:

One thing to note is that as far as I can see, it's only happening when the artifacts are created on a different machine to the one running the current step.
Eg. PC898 builds my Editor executables, then PC623 runs my world file deployment step (which needs my Editor's exes from PC898)

If you have snapshot dependencies along  with artifact dependencies, "run build on the same agent" option may be a workaround.

Thanks for that suggestion,
I'm happy to use that option, it just makes creating an 'artifact dependency' a pointless task (as the exe's will all be on that machine anyway)

As we're only using 3 agents at the moment, the level of parallelism that can be achieved is quite low in any case, so it'll be fine for now.

My only fear is a config that relies on 2-3 artifacts destined for different machines, based on 'agent requirements'.
eg. a Testing step that relies on an executable that can only be compiled on one machine, with test data that can only be deployed on another.

I'll have a go with the most problematic cases and see if I can get a working solution.

Thanks

Forcing all of the steps previously using artifacts from my EditorExes.zip to now not rely on artifacts, and run on the same machine appears to have resolved all the artifact issues.

An example being one test case that grabs artifacts from three configs and resolves them quickly enough:

Though the problem definetly have its root in file transfer, http transport layer does not report any failures (no socket timeout exceptions and other things)...

Is there anything specific in your network configuration? Any firewalls or caching proxies between Teamcity server and agents? Distant agents with ureliable connections?

What really makes it interesting is that limiting builds to same machine lowered transfer times that significantly...

While I changed the EditorExe reliant steps to use the same machine and no artifact dependency, I kept my other artifact dependent steps the same, so the example provided was gathering artifacts from different machines.
All of the machines are on our internal network, and so I'm unsure if there's anything specific that could be causing this issue, I have an open ticket with our IT department to look into this further.

I've studied the 3 successful builds of my 'Run PC Tests' step, and the results make little sense.

PC898 (Gathering 3 Artifact packages from PC590) - 25 secs ~ This example used in previous post
PC590 (Gathering 2 Artifact packages from PC898) - 1 min 40 secs
PC623 (Gathering 2 artifact packages from PC623) - 3 min 10 secs

I'll follow up with our IT department.

I should add that in my set up, the TeamCity server is running on PC898.
So I'm guessing from the times specified, that archives are uploaded to the server machine upon creation? (so it doesn't matter which agent built them as I wrongly suggested in my example above)

So it appears clear that there's a potential descrepency between network speeds of our machines (PC590 and PC623), but furthermore, that if 2 mins for around 100MB of data is 'normal' in my case, we should be looking at around 6-9 mins for that larger troublesome package.

In any case, I'm still following this up internally, so thank you for your help and suggestions so far.

Jim,

Thank you very much for posting back your thoughts.

Your guess is absolutely correct: artifacts are first uploaded to TeamCity server, than dowloaded back again. We are working to improve this: http://youtrack.jetbrains.net/issue/TW-15448
So for builds running on server machine (PC898) will always have shortest artifact downloading times.

Is it possible to split troublesome package EditorExes*.zip into, say, 2 archives of smaller size? If yes, could you try it and remove "run on same agent" limitation.

Jim,

Thank you very much for posting back your thoughts.

Your guess is absolutely correct: artifacts are first uploaded to TeamCity server, than dowloaded back again. We are working to improve this: http://youtrack.jetbrains.net/issue/TW-15448
So for builds running on server machine (PC898) will always have shortest artifact downloading times.

Is it possible to split troublesome package EditorExes*.zip into, say, 2 archives of smaller size? If yes, could you try it and remove "run on same agent" limitation.

Hi again,

I split up my 'EditorExe' package into 3  smaller packages (as a result of this, I managed to remove some extra  filetypes I didn't require) and ended up with 3 zip files.
EditorExes -39MB
EditorGPIs -8.5MB
EditorDLLs - 26MB

By reducing the file sizes you've helped my create a system that is much more managable with a resolution time of:

Having tested this a bit further, I'm still having issues.

I'm interested to see whether the problem is at download time, or the time taken to populate the working copy with these downloaded files.

I have an example here:

Jim,

As far as I can see, you have migrated to TeamCity 7.0. May I ask you to attach new debug logs (as described in my older reply) for slow resolution ?

Hi Nikita,

That's correct, we are now using TeamCity 7.0.2.

Apologies for the delayed response, I'd set my fast turnaround builds to run on the same agent as the dependent steps and so had no logs.
I've set things back up to be artifact dependent and available to run on any agent, and replicated the problem, and have attached some zips of the log files.

The exact case is as follows.

The problem build is buildId 14722 (Frequent Builds > Runtime Debug Smoke Tests Xbox360) and the build type id is bt21.
This was build #667 (09 Jul 08:38)

This config's specific run is snapshot and artifact dependent on
- 'Frequent Builds > Deploy Smoke Packages Xbox360' - buildId 14673, buildTypeId bt20, build #727 (06 Jul 12 18:54)
- 'Frequent Builds > Runtime Debug 2010 Libs Xbox360' - buildid 14664, buildTypeId bt5, build #1898 (06 Jul 12 18:38)

And produced the following output:
[08:38:09]Resolving artifact dependencies (11m:42s)
[08:40:46][Resolving artifact dependencies] 37 files retrieved for [*.zip!**=>C:\BlitzTech_TC] downloading pattern
[08:49:52][Resolving artifact dependencies] 2 files retrieved for [TestExe*.zip!**=>C:\BlitzTech_TC] downloading pattern

Let me know if there's anything else I can supply.

Thanks again for the assistance with this.

Jim,

Apologize for the delay.

Unfortunately, your last build agent logs didn't have debug enabled. Please, follow the instructions here to enable the debug and reproduce the issue.

Hi,

I've hopefully added some agent logs with debug information this time.
BuildID - 20154
BuildTypeID - bt16
Build #360

I've enabled debugging, and have included every file modified during the build to ensure I've not missed anything.

Thanks,

Jim,

Thank you for the logs.
I can see that the artifact download times are heavely affected by this issue: http://youtrack.jetbrains.com/issue/TW-22001

It was fixed in recent 7.0.4 release and I recommend you to upgrade your installation, if possible.

Hi Nikita,

Thanks for the reply, I'm just in the process of upgrading to 7.1, so I'll let you know the status of this post-upgrade.

Thanks,

Hi again,

I can confirm that since moving to TeamCity 7.1, artifact resolution appears to be much faster, averaging at around the 2 minute mark.
I've marked your post requesting the move to this version as the 'correct answer' to this thread.

Thanks for all of your help.
Jim

Thank you for letting us know about it. Good luck!