Andrus Adamchik wrote:
> Did anyone noticed a weird behavior of Xalan during unit tests report
> generation. After I upgraded from JDK 1.4.0 to 1.4.1, any attempts to
> generate reports from JUnit xml output would hang the build
> indefinitely with 100% CPU consumption. Xalan seems to be bundled with
Funny, I always thought that this was normal.. :-)
Highly annoying though, since it totally hogs even my 2.4GHz machine, and
I always wondered what the hell was going on there. It does not hang
indefinitely, though: on my machine it takes ~2 minutes between the
"junit-test-report" output and the start of Xalan, during which it is
extremely unresponsive. I usually run the tests with lower priority (start
/LOW) so that I can do at least something else while it chugs along.
> JDK now, I wonder if this is the cause of the problem? Interesting that
I investigated. The problem boils down to a terrible String/StringBuffer
bug/design deficiency which is actually at the top of the bugparade
(http://developer.java.sun.com/developer/bugParade/bugs/4724129.html).
Read on for a new episode of why I would really like to see JavaSoft burn
down.
- first suspect GC trashing - not the case, running the test VM with
maxmemory=128m did not change anything; in fact neither junit nor Xalan
ever use more than ~40 MB.
- I ran -Xrunprof via ant to generate a CPU sampling. This indicated that
>50% of the runtime was spent in StringBuffer.copy() which does a System.arraycopy() - this explains why the machine totally bogs down, JNI hits are still very expensive.
- running the junit VM with -server actually slows the junit tests down,
since most methods are run only once and have very irregular call chains;
the junitreport collection stage is not accelerated in any way (the VM
cannot magically speed up JNI hits).
- since during the long hogging period the harddisk was constantly
accessed, I used FileMon
(http://www.sysinternals.com/ntw2k/source/filemon.shtml) to trace what
exactly was happening. Guess what: for over two minutes (!)
TESTS-TestSuites.xml is written in pieces of ~70-200 bytes.
- since this happens before Xalan is started, I looked into the
junit-report task and specifically XMLResultAggregator. execute() calls
writeDOMTree() and this is the culprit. First thing I did was to make both
the output stream and writer buffered, but other than reduced file access
this had little effect. Doesn't hurt, though.
- I look into ant's DOMElementWriter and see a shared StringBuffer ivar sb
that seems to be reused. An alarm bell goes off. Every written DOM element
string is mangled via encode(), where I see that the shared StringBuffer
is first set to size 0, then filled, then at the very end - the terrible
toString() happens. I replace toString() with substring(0, sb.length()),
run the unit test suite and start to create all reports.
- KABOOM! ** _1_ second ** for collecting all tests into the single XML
file before feeding it into Xalan (which takes its usual 9 seconds). Yes,
the generated output is still correct.
Any suggestion about what to do now? Could someone please take the time to
report both the output buffering and toString() problems to the ant folks?
I just checked the ant 1.5.3rc1 source and it's still in there. Btw,
regarding ant: 1.5.2 creates 'broken' archives; I'll see that we get 1.5.3
into cvs as soon as it's released (and verifiably works).
If they refuse to fix this for whatever political reasons I can pack up a
little ant-fix.jar, so that we don't waste more time waiting for reports.
Holger
This archive was generated by hypermail 2.0.0 : Sun Mar 30 2003 - 10:06:13 EST