Like many Java-based products, we use Ant to build NeXpose. While helping a coworker investigate performance issues, I noticed that Ant tasks creating jar archives containing many files were taking a lot of CPU time. I want to demonstrate via this blog post how a simple performance problem can be easily investigated and fixed. The resulting bugfix (1-line patch) was contributed to Ant and is included in version 1.8.1 which was released on 2010-05-07.
The Ant task creating the jar archive looked like this:
<jar destfile="foo.jar" basedir="directoryname"/>
The directory contained about 50 thousand files, and running the Ant task seemed to be about three times slower than creating the archive from the command line with the jar(1) command (103 sec vs. ~30 sec).
So I peeked at what Ant was doing with the excellent VisualVM debugger. When looking at a couple of stack traces taken at a random intervals, I noticed many were similar to this one:
"main" prio=10 tid=0x0000000041767000 nid=0x2174 runnable [0x00007fe89d117000..0x00007fe89d118eb0]
java.lang.Thread.State: RUNNABLE
at java.util.Hashtable.contains(Hashtable.java:270)
- locked <0x00007fe81c738ff0> (a java.util.Hashtable)
at org.apache.tools.ant.taskdefs.Zip.zipFile(Zip.java:1448)
at org.apache.tools.ant.taskdefs.Jar.zipFile(Jar.java:602)
at org.apache.tools.ant.taskdefs.Zip.zipFile(Zip.java:1551)
at org.apache.tools.ant.taskdefs.Zip.addResources(Zip.java:792)
at org.apache.tools.ant.taskdefs.Zip.addResources(Zip.java:853)
at org.apache.tools.ant.taskdefs.Zip.executeMain(Zip.java:499)
at org.apache.tools.ant.taskdefs.Zip.execute(Zip.java:416)
[...]
Why do I see Ant apparently spending so much time in Hashtable.contains() in my handful of stack trace samples, when a hashtable lookup has a time complexity of O(1)? Looking at Ant's code, I saw that it was using this hashtable as a set —storing the same object as a key and value— to represent entries that already exist in the jar archive, so that it could determine if a file to be added to the archive needs to have an entry created or updated. There were 50 thousand files in the archive. Worst case, a hashtable lookup costs a RAM access, or roughly 50 ns on a modern processor if not cached in the CPU caches. So 50k lookups should take a handful of milliseconds. However in my case it was apparent that Ant was spending about a minute doing nothing but lookups. I was more familiar with the Map class rather than the Hashtable class, so I glanced at the Hashtable.contains() documentation to confirm a suspicion...
public boolean contains(Object value)
Tests if some key maps into the specified value in this hashtable.
Yikes! This method checks for values instead of keys! Instead of doing an O(1) lookup with containsKey(), contains() iterates over all values for each file to be added to the archive. This explains the approximate minute of wasted CPU time: 25000 (average iterations) * 50000 (files) * 50 ns = 62.5 sec.
I changed the contains() call to containsKey() and recompiled Ant. It sped up the jar creation by 3x by shaving a minute from the execution time (103 sec down to 32 sec). I submitted a bug report (bug 48755 - Zip task does O(n) lookup in hashtable) and a patch to the Ant developers. The fix is included in Ant 1.8.1 which was released last month.
The whole investigation and fix took less than an hour. This is a great demonstration of the advantages of open source tools. Anyone can fix anything to help everyone.