Monday, August 27, 2012

Ant Profiling

In my new job at Assurity Consulting I've been looking at some large builds. Some that take 6 hours or more to run in the Continuous Integration Server. There's a fairly random mix of Ant, Maven and good old shell. The last few days I spent some time diving into the details of a fairly large Ant build.

I've been using a combination of three techniques to analyze where the time is being spent in this build:

  1. Analysis by inspection.
  2. Analysis of "ant -d" output.
  3. Ant Profiler.

There are a number of files and many tasks and targets in this build, and I haven't been able to walk through the entire thing yet. But by browsing through "interesting" parts, I have been able to find out some significant things about the build.

For example, the build makes extensive use of <antcall>. Sometimes people use <antcall> when they don't understand the correct usage of "depends" on Ant targets. In this build, many of the <antcall> usages would be more appropriately done with <macrodef>. <antcall> is inefficient to use on targets within the same build file, because it reparses and copies properties. Please learn to use <macrodef> with Ant. It is your friend.

To extract some data about the Ant build as a whole, I ran it with "ant -d". On this particular build, it generates 600,000 lines of output. Again, a lot of detail.

With some shell piping we can see potential areas of duplication, or work being repeated:

ant -d >ant.debug.out 
sort ant.debug.out | uniq -c | sort -nr | head

For example, we can see whether certain Java source files are compiled more than once during the build:

egrep "^ *\\[javac\\]" ant.debug.out | sort | uniq -c | sort -nr | less

In this case I found that some classes are compiled twice, three, four or five times. Unfortunately, not enough classes to make a large difference to the build time, but still ...

Finally, I found a great Ant profiler called antro. This profiler is really neat. It is completely non-invasive. It uses the Ant listeners feature, and can be run like this to analyze a build:

ant -listener ru.jkff.antro.ProfileListener -lib ~/antro/antro.jar build.xml

This generates a JSON file, which can then be loaded into the profiler's GUI. The GUI is run simply with:

java -jar antro.jar

What could be simpler?

It provides a tree view of the build times, where you can drill down into any node and explore the detail. Using this tool it's easy to get a bird's eye view of the build time breakdown, as well as drill into areas of interest. For example, I was able to assess the overhead of <antcall> by looking at some of those nodes. Unfortunately, there seems to be no way to see the total number or overhead for a single task type such as <antcall> across the whole build. I was able to find the total number of <antcall>s (not the times though) from the "ant -d" output. This allowed me to estimate the total time overhead of <antcall> for this build.


jkff said...

Hey, I'm the author of antro and I'm glad to see that you found it useful :)

rajesh said...

Very interesting to use your commands in my build. I have problem with my build which is taking to much time as unsuspected. have many antcalls inside the build.xml and can not able to locate which one taking more time to build. Can you help me how can i use this Profiling.

Thank you

jkff said...

Rajesh, the post describes exactly how the tool is used: run ant with the listener to obtain a .json report; then open the report in the GUI. Which step are you having trouble with?

rajesh said...

I have problems in running in this command ant -listener ru.jkff.antro.ProfileListener -lib ~/antro/antro.jar build.xml

I have add jars to my antro calsspath and unable to modify this command. i am like junior in this area. can you help me how exactly frame this command

Thank you.

jkff said...

Rajesh, you can specify multiple -lib flags: -lib ........../antro.jar -lib ......./your-other-library1.jar etc. Does this solve your problem?