TeamCity extending the build by several minutes after a maven build has completed

Hi,

I have a maven build configuration setup in teamcity that should only take a little of 2 minutes but teamcity reports it as taking 10 minutes.  When looking in the log file I see TeamCity is taking around 7 minutes between the message "Number of processed tests: 11718" and "Publishing artifacts".  What is TeamCity doing during that 7 minutes?  I don't have any artifacts I'm posting so it can't be that.  Any help would be great.

[12:03:48]: [INFO] BUILD SUCCESSFUL
[12:03:48]: [INFO] ------------------------------------------------------------------------
[12:03:48]: [INFO] Total time: 2 minutes 38 seconds
[12:03:48]: [INFO] Finished at: Wed Dec 01 12:03:48 EST 2010
[12:03:49]: [INFO] Final Memory: 50M/208M
[12:03:49]: [INFO] ------------------------------------------------------------------------
[12:03:49]: Number of processed tests: 11718
[12:10:54]: Publishing artifacts
[12:10:54]: [Publishing artifacts] Paths to publish: [teamcity-info.xml]
[12:10:54]: [Publishing artifacts] Publishing files
[12:10:54]: Build finished

Thanks,
Jay
17 comments

Hi, Jason  Could you please provide the corresponding snippet from the agent log file.  What TeamCity version are you using? Is this a stable effect?

0

Hi Sergie,

We are using 5.1.4 and yes this is a stable effect, happens for all builds with Maven.

Here is an example using ant as the build runner which then in turn calls maven and it doesn't extend the build:

[23:20:39]: * * * *  buildFinished(). Event = null
[23:20:39]: Process exit code: 0
[23:20:44]: Surefire report watcher
[23:20:44]: [Surefire report watcher] 205 file(s) found
[23:20:44]: Publishing artifacts (2s)
[23:20:44]: [Publishing artifacts] Paths to publish: [dev/index.html => dev, **/build/tests/report/**, **/build/test/report/**, dev/dependency-reports/** => dev/dependency-reports, dev/origin/build/tests/junit.log => junit.log, teamcity-info.xml]
[23:20:46]: [Publishing artifacts] Artifacts path **/build/tests/report/** not found
[23:20:46]: [Publishing artifacts] Artifacts path **/build/test/report/** not found
[23:20:46]: [Publishing artifacts] Artifacts path dev/origin/build/tests/junit.log not found
[23:20:46]: [Publishing artifacts] Publishing files
[23:20:47]: Build finished


Here is the teamcity output from the teamcity GUI:

[11:23:55]: [INFO] BUILD SUCCESSFUL
[11:23:55]: [INFO] ------------------------------------------------------------------------
[11:23:55]: [INFO] Total time: 2 minutes 33 seconds
[11:23:55]: [INFO] Finished at: Mon Dec 06 11:23:55 EST 2010
[11:23:56]: [INFO] Final Memory: 47M/206M
[11:23:56]: [INFO] ------------------------------------------------------------------------
[11:23:59]: Number of processed tests: 11718
[11:34:44]: Publishing artifacts
[11:34:44]: [Publishing artifacts] Paths to publish: [teamcity-info.xml]
[11:34:44]: [Publishing artifacts] Publishing files
[11:34:44]: Build finished


Here is the output from the teamcity-agent.log during that time:


[2010-12-06 11:21:21,731]   INFO - impl.runStages.CallRunnerStage - ----------------------------------------- [ Gobbles::Continuous #89 (buildId = 121201) ] -----------------------------------------
[2010-12-06 11:21:21,775]   INFO - er.agent.runner.PropertyFinder - Took value for target.jdk.home from env.JAVA_HOME, value: /usr/java/latest
[2010-12-06 11:21:21,792]   INFO - nner2.OsProcessHandlerListener - sh /opt/packages/teamcity/plugins/maven/bin/mvn -f /home/buildacct/work/cc91ba546482f0a4/gobbles/pom.xml -B -Dteamcity.version=5.1.4 (build 13550) clean verify
[2010-12-06 11:23:59,638]   INFO - nner2.OsProcessHandlerListener -
[2010-12-06 11:34:44,741]   INFO -    jetbrains.buildServer.AGENT - Start: Searching for artifacts to publish
[2010-12-06 11:34:44,741]   INFO -    jetbrains.buildServer.AGENT - Artifacts path teamcity-info.xml not found
[2010-12-06 11:34:44,741]   INFO -    jetbrains.buildServer.AGENT - Done:  Searching for artifacts to publish
[2010-12-06 11:34:44,741]   INFO -    jetbrains.buildServer.AGENT - Start: Pre-processing artifacts if needed (archiving)
[2010-12-06 11:34:44,741]   INFO -    jetbrains.buildServer.AGENT - Done: Pre-processing artifacts if needed (archiving)
[2010-12-06 11:34:44,741]   INFO -    jetbrains.buildServer.AGENT - Start: Publishing files
[2010-12-06 11:34:44,741]   INFO -    jetbrains.buildServer.AGENT - Done:  Publishing files
[2010-12-06 11:34:44,746]   INFO -    jetbrains.buildServer.AGENT - Build finished: 121201



Here is the output from the teamcity-build.log on the agent during that time:

[2010-12-06 11:23:55,896] out - [INFO] ------------------------------------------------------------------------
[2010-12-06 11:23:55,896] out - [INFO] BUILD SUCCESSFUL
[2010-12-06 11:23:55,896] out - [INFO] ------------------------------------------------------------------------
[2010-12-06 11:23:55,897] out - [INFO] Total time: 2 minutes 33 seconds
[2010-12-06 11:23:55,897] out - [INFO] Finished at: Mon Dec 06 11:23:55 EST 2010
[2010-12-06 11:23:56,229] out - [INFO] Final Memory: 47M/206M
[2010-12-06 11:23:56,229] out - [INFO] ------------------------------------------------------------------------
[2010-12-06 11:23:59,638] err -
[2010-12-06 11:23:59,638] out -
[2010-12-06 11:23:59,638] err -
0

Jason  Unfortunately, it didn't add much. Please enable debug logging (uncomment DEBUG declarations in teamcity-agent-log4j.xml), restart the agent, run a build and send me the log again. Also take a thread dump (or better several dumps) of the agent process when it's stuck. Please refer to http://confluence.jetbrains.net/display/TCD6/Reporting+Issues#ReportingIssues-Threaddumptakingapproaches  Thank you.

0

Hi Sergei,

After turning on DEBUG and doing some observation on my part I think I have it narrowed down.  It looks as though when using the maven build runner that it is slow at sending all the build output and test results back to the teamcity server.  So viewing the teamcity-build.log the build and tests finish but from the teamcity servers perspective the tests are still running and reporting.  After the build completed the teamcity-agent.log continued sending data to the server.  Why doesn't any of this happen in real time, is there something configured incorrectly?

<jetbrains.buildServer.messages.BuildMessage1><mySourceId>DefaultMessage</mySourceId><myTimestamp>1291657311778</myTimestamp><myStatus>1</myStatus><myTypeId>BlockStart</myTypeId><myFlowId></myFlowId><myValue ><blockName>com.brightcove.gobbles.frontend.PlayerServletTest.testModifiedSinceDisabled404[16]</blockName><blockType>$TEST_BLOCK$</blockType></myValue></jetbrains.buildServer.messages.BuildMessage1>]]></value><value><![CDATA[<?xml version="1.0" encoding="UTF-8" ?>


This build has 10k tests but adding 7 - 8 minutes to this build to send the data to the server is pretty insane, considering the build only takes 2 - 3 minutes.

Do you need the thread dumps or what I state above is enough?

Thanks,
Jay
0

Jason

Your observations look plausible given the big number of tests reported (about 11k). However I agree 7-8 minutes is quite long unless your tests produce a lot of console output which may significantly increase the traffic.
The agent accumulates build output to send it to the server in big portions to minimize network overhead. That's why there can be lags between actual build events and their reflections on the server side. But such big lags in your case indicate that the transferring of the build output is much slower than its generation.

Are your agent and server in the same local area network?
Just to see whether it a network related issue you can run both the agent and the server on the same machine, run the build and compare results.

0

Yes, the agent and server are both on the same network.  Does the amount of memory the agent is using have any reflection on the agent sending this data faster?  I just think it sends the wrong results back to the user stating that the build takes that long but when you go and look a the log the build really only took X.  

0

By the way the console output is 4480 lines.

0

I tried running the same build on one of our macs that has an SSD hard drive.  This speeds up the build but the transfer extended build time we were seeing on the same build is even longer on this machine, up around 20 minutes.  See the time gap below:

[22:12:12]: [INFO] BUILD SUCCESSFUL
[22:12:12]: [INFO] ------------------------------------------------------------------------
[22:12:12]: [INFO] Total time: 1 minute 31 seconds
[22:12:12]: [INFO] Finished at: Sun Dec 05 22:12:12 EST 2010
[22:12:12]: [INFO] Final Memory: 64M/123M
[22:12:12]: [INFO] ------------------------------------------------------------------------
[22:12:12]: Number of processed tests: 11718
[22:31:55]: Publishing artifacts
[22:31:55]: [Publishing artifacts] Paths to publish: [teamcity-info.xml]
[22:31:55]: [Publishing artifacts] Publishing files
[22:31:55]: Build finished
0

Jason

First of all, before we dig in the logs, let's see whether it a network-related problem. Is it possible to install an agent on the same machine where the server is running and run this build?

0

Since you don't have any OutOfMemoryErrors, I don't think changing the amount of memory will affect performance somehow. Let's move step by step. See my later reply.

0

Hi Sergey,

I ran the build on the teamcity server so it was local and 3 minutes was still added to the end of the build which is kind of a lot considering the build is only 3 minutes long.

[10:41:50]: [INFO] BUILD SUCCESSFUL
[10:41:50]: [INFO] ------------------------------------------------------------------------
[10:41:50]: [INFO] Total time: 3 minutes 9 seconds
[10:41:50]: [INFO] Finished at: Fri Dec 10 10:41:50 EST 2010
[10:41:51]: [INFO] Final Memory: 85M/676M
[10:41:51]: [INFO] ------------------------------------------------------------------------
[10:41:55]: Number of processed tests: 11718
[10:45:01]: Publishing artifacts
[10:45:01]: [Publishing artifacts] Paths to publish: [teamcity-info.xml]
[10:45:01]: [Publishing artifacts] Publishing files
[10:45:01]: Build finished
0

OK. This is still much better than 8-10 minutes. Now we know the network adds about 5-7 minutes to the build time.

Now could you please send me the full build log.
If you don't want to expose it in the public forum, you can send it as an email to teamcity-feedback@jetbrains.com.

Thank you.

0

Hi, Jason

I've looked into the log. Assuming this buld run on the same machine with the server, I almost sure this slowdown is related to the database. I know from your previous posts, you're using MySQL with MyISAM, which is known not very good for numerous inserts (given the number of tests in your build there are definitely a lot of inserts).
Regardless of whether this particular problem related to the database, I would recomment you migrating to InnoDB, which not only faster for inserts but also allows deep performance tuning.

If you consider this experiment too expensive and want to be absolutely sure if this related to the database prior to any migration actions, then we need some deeper investigation.
Ideally we'd like to have a CPU snapshot. See http://confluence.jetbrains.net/display/TCD5/Reporting+Issues#ReportingIssues-ServerPerformance .
Less helpful but likely good enough are a number (the more the better) of server thread dumps, taken within the period of slowdown. Please see http://confluence.jetbrains.net/display/TCD5/Reporting+Issues#ReportingIssues-Threaddumptakingapproaches

And please run the builds on the server machine to avoid network interference.

Thank you.

0

Hi Sergey,

I'm converting the TeamCity database to InnoDB and it is taking a really long time, upward of around 6.5 hours so far.  All the time seems to spent in inserting the test_info table.  Each line in the import file of test_info is taking around 50 seconds, they started around 8 seconds and have grown over time.  The file I am importing is 993MB and the ibdata1 file has grown to about 3.2GB now and growing slowly.  I used the tuning tips mysql recommended but thought it would have been faster than this.  Is this normal?

http://dev.mysql.com/doc/refman/5.1/en/innodb-tuning.html

Thanks,
Jay

0

Hi, Jason

The size doesn't look weird. As for timing, theoretically an import could be quite slow. We know cases when a TeamCity database has been imported for 8-10 hours. It may depend on a particular import tool or method.
Also, are you sure you don't have problems with your hardware?

0

The import finished, took around 9 hours.  Our last server had hardware issues but this one is fine.  I'll double check but we are now running with InnoDB.

0

Please sign in to leave a comment.