Pause between build completion and post processing

We're seeing weird behavior. Once our build is complete there is a two and a half minute pause in the logs before the TeamCity post processing (artifact publishing) begins. This is worrysome because it is 50% of the build time.



[16:03:20]: [INFO] ------------------------------------------------------------------------
[16:03:20]: [INFO] BUILD SUCCESSFUL
[16:03:20]: [INFO] ------------------------------------------------------------------------
[16:03:20]: [INFO] Total time: 1 minute 32 seconds
[16:03:20]: [INFO] Finished at: Thu Nov 05 16:03:20 EST 2009
[16:03:21]: [INFO] Final Memory: 37M/137M
[16:03:21]: [INFO] ------------------------------------------------------------------------
[16:03:21]: Process exited with code 0
[16:05:52]: Surefire report watcher
[16:05:52]: [Surefire report watcher] 1 file(s) found


Any idea what could be causing this, or what the agent is doing during this time?


Thanks,


Matthew Jaskula
15 comments
Comment actions Permalink

Agent logs could help to discover this issue (teamcity-build.log & teamcity-agent.log)

0
Comment actions Permalink

According to the debug logs it looks like the agent is processing the build output long after the build is completed. I've seen symptoms of this before when refreshing the full log page of a running build the timestamp of the latest message is well behind the current time. Are our builds producing more output than teamcity can handle?

I will email you the log files that show this.

Thanks.

--
Matthew Jaskula

0
Comment actions Permalink

Hello, Mathew

Aside from this problem, you don't have to use XML report processing with Maven2 runner, which is capable of reading surefire reports itself.

0
Comment actions Permalink

What runner do you use?

0
Comment actions Permalink

Unfortunately we're using the command line runner rather than the maven runner because we have some pre-processing steps to run before we invoke maven. We are looking forward to the ability to assign multiple runners to a build configuration.

0
Comment actions Permalink

Where is the agent installed: in the same network as server, on the same PC as server?

0
Comment actions Permalink

Also could you please enable Verbose mode in the xml report plugin and send us logs again.

0
Comment actions Permalink

The agent and server are on separate machines. Our ops guys say that they are on the same switch and that the network between them is 'fast as hell'.

--
Matthew Jaskula

0
Comment actions Permalink

| Also could you please enable Verbose mode in the xml report plugin and send us logs again.

Sure, how do I do that?

--
Matthew Jaskula

0
Comment actions Permalink

There is a checkbox "Verbose output:" on the runner settings page.

0
Comment actions Permalink

It was already checked!

--
Matthew Jaskula

0
Comment actions Permalink

It seems the server is slowly processing messages logged by the agent. Given that most of the messages are just plain text chances are the disk on the server is slow, or there is a lot of IO operations on the server side.

0
Comment actions Permalink

From our ops guys:

The TeamCity server is also hosting our issue tracker and wiki. So there is likely some resource contention.

It would be helpful to know what exactly the agent and the server are doing during that period. Agent send something to the server? How it is happening? What protocol do they use?  Any DNS lookups during that time?

Thanks.

--
Matthew Jaskula

0
Comment actions Permalink

Agent sends messages to the server. The messages are sent in packs and from the log we see that it takes significant time to process these messages on the server (20-40 seconds). If we sum up this time we will have about 13 minutes.

Most of the messages are simple text output, processing of such messages should be fast - they are written to the build log which is stored on disk (no database interaction). I tried to reproduce this problem but in my case server imports your log file in about 2 seconds. In your case it is about 13 minutes which is strange.

It would be helpful if you install this plugin http://www.jetbrains.net/confluence/display/TW/Server+Profiling on your server and try to take CPU snapshot while your build is running.

0
Comment actions Permalink

Thanks.

It looks like this machine may have issues on its own, which are likely the cause of this slowdown. We'll investigate this internally and comback with a CPU snapshot if we cannot solve it.

Thaks for your help.

--
Matthew Jaskula

0

Please sign in to leave a comment.