Reading assembly descriptor taking longer on new install

We have TeamCity running in EC2.  We recently moved it from an m1.small instance to an m1.large and now java builds take longer than they did before which is obviously not what we wanted.  We noticed that the step:

Reading assembly descriptor

is what's taking the extra time - went from a few seconds to a minute.  New insance is running a newer version of TeamCity (17985 vs 17795).  Also, the m1.small runs a 32bit OS where the m1.large a 64 bit.  Both are linux although not the same distribution.  Both are Ubuntu, old is 10.04 and new is 11.04.

Any idea what could cause the increase in time?

6 comments
Comment actions Permalink

I turned on debug logging in maven and I can see it's whatever process (jar?) that's creating the zip?  The other difference between the two machines is our old instance is running sun java:

bitnami@ip-10-162-30-192:/usr/lib/youtrack3.0/standalone$ java -version
java version "1.6.0_24"
Java(TM) SE Runtime Environment (build 1.6.0_24-b07)
Java HotSpot(TM) Client VM (build 19.1-b02, mixed mode, sharing)

vs open jdk on the new:

ubuntu@ip-10-171-54-43:/home/youtrack/standalone$ java -version
java version "1.6.0_22"
OpenJDK Runtime Environment (IcedTea6 1.10.2) (6b22-1.10.2-0ubuntu1~11.04.1)
OpenJDK 64-Bit Server VM (build 20.0-b11, mixed mode)

Debug log snippits:

old:

[21:41:34]: [com.oggifinogi:logpusher] [DEBUG]   cglib:cglib:jar:2.2.2:runtime (selected for runtime)
[21:41:34]: [com.oggifinogi:logpusher] [DEBUG]     asm:asm:jar:3.3.1:runtime (selected for runtime)
[21:41:34]: [com.oggifinogi:logpusher] [DEBUG]  Adding file:  /usr/lib/teamcity6.5/buildAgent/work/303822e41e7d9710/com.oggifinogi.logpusher/../com.oggifinogi.build/win/install-service.cmd  to archive location: install-service.cmd
[21:41:35]: [com.oggifinogi:logpusher] [DEBUG]  Adding file:  /usr/lib/teamcity6.5/buildAgent/work/303822e41e7d9710/com.oggifinogi.logpusher/../com.oggifinogi.build/win/prunmgr.exe  to archive location: logpusherw.exe
[21:41:35]: [com.oggifinogi:logpusher] [DEBUG]  Adding file:  /usr/lib/teamcity6.5/buildAgent/work/303822e41e7d9710/com.oggifinogi.logpusher/../com.oggifinogi.build/win/prunsrv.exe  to archive location: logpusher.exe
[21:41:35]: [com.oggifinogi:logpusher] [DEBUG]  Adding file:  /usr/lib/teamcity6.5/buildAgent/work/303822e41e7d9710/com.oggifinogi.logpusher/bin/maven/logpusher-5.0.1-SNAPSHOT.jar  to archive location: oggifinogi-logpusher.jar
[21:41:35]: [com.oggifinogi:logpusher] [DEBUG]  Adding file:  /usr/lib/teamcity6.5/buildAgent/work/303822e41e7d9710/com.oggifinogi.logpusher/../com.oggifinogi.build/nix/log-pusher.sh  to archive location: log-pusher.sh
[21:41:35]: [com.oggifinogi:logpusher] [DEBUG] Processing DependencySet (output=/lib)
[21:41:35]: [com.oggifinogi:logpusher] [DEBUG] Dependencies for project: com.oggifinogi:logpusher:jar:5.0.1-SNAPSHOT are:
[21:41:35]: [com.oggifinogi:logpusher] active project artifact:
[21:41:35]: [com.oggifinogi:logpusher]      artifact = com.oggifinogi:basement:jar:5.0.1-SNAPSHOT:compile;


new:
[21:30:36]: [com.oggifinogi:logpusher] [DEBUG]   cglib:cglib:jar:2.2.2:runtime (selected for runtime)
[21:30:36]: [com.oggifinogi:logpusher] [DEBUG]     asm:asm:jar:3.3.1:runtime (selected for runtime)
[21:30:36]: [com.oggifinogi:logpusher] [DEBUG]  Adding file:  /home/teamcity/teamcity6.5/buildAgent/work/303822e41e7d9710/com.oggifinogi.logpusher/../com.oggifinogi.build/win/install-service.cmd  to archive location: install-service.cmd
[21:30:38]: [com.oggifinogi:logpusher] [DEBUG]  Adding file:  /home/teamcity/teamcity6.5/buildAgent/work/303822e41e7d9710/com.oggifinogi.logpusher/../com.oggifinogi.build/win/prunmgr.exe  to archive location: logpusherw.exe
[21:30:39]: [com.oggifinogi:logpusher] [DEBUG]  Adding file:  /home/teamcity/teamcity6.5/buildAgent/work/303822e41e7d9710/com.oggifinogi.logpusher/../com.oggifinogi.build/win/prunsrv.exe  to archive location: logpusher.exe
[21:30:41]: [com.oggifinogi:logpusher] [DEBUG]  Adding file:  /home/teamcity/teamcity6.5/buildAgent/work/303822e41e7d9710/com.oggifinogi.logpusher/bin/maven/logpusher-5.0.1-SNAPSHOT.jar  to archive location: oggifinogi-logpusher.jar
[21:30:42]: [com.oggifinogi:logpusher] [DEBUG]  Adding file:  /home/teamcity/teamcity6.5/buildAgent/work/303822e41e7d9710/com.oggifinogi.logpusher/../com.oggifinogi.build/nix/log-pusher.sh  to archive location: log-pusher.sh
[21:30:43]: [com.oggifinogi:logpusher] [DEBUG] Processing DependencySet (output=/lib)
[21:30:43]: [com.oggifinogi:logpusher] [DEBUG] Dependencies for project: com.oggifinogi:logpusher:jar:5.0.1-SNAPSHOT are:
[21:30:43]: [com.oggifinogi:logpusher] active project artifact:
[21:30:43]: [com.oggifinogi:logpusher]      artifact = com.oggifinogi:basement:jar:5.0.1-SNAPSHOT:compile;
0
Comment actions Permalink

Hi Jerry,

Why do you think this effect is related to TeamCity?

Did you try to perfrom this command manually and check the time?

0
Comment actions Permalink

I don't know that it is and likely it's not.  But I thought someone on this forum might have an idea to help me...  And I haven't yet tried running the commands manually but will.

How do I execute maven commands locally using the plugin?

0
Comment actions Permalink

Hi Jerry,

just login to this machine under the agent's account, go to the checkout directory, and run the build from the command line.
If you still observe slowness then TeamCity hardly has something to do with it.

0
Comment actions Permalink

I think I'm seeing the same issue. I tried Sergey's suggestion of running it locally and found that it was much faster, however when run through teamcity it's much slower.

I turned on verbose garbage collection logging and found that reading from the assembly-descriptor.xml and building the artifact often kicks off a full GC. Any idea why a remote build would trigger longer more frequent full GC's?

details:
apache-maven-2.2.1
jdk1.6.0_21
build agent 5.1.3

0
Comment actions Permalink

In which JVM you were seeing GC working hard - the agent's or the Maven's one?

0

Please sign in to leave a comment.