possible performance regression on xalan on classpath 0.96

Problem has repeated across a couple of performance runs, so it looks real.

Sanity check of 0.96.1 shows that all Jikes RVM patches were applied.

Looking at profile data for 0.95 and 0.96 the top 5 methods for 0.95 are:

61.0 (1.9457735247208932%) Lorg/jikesrvm/jni/VM_JNIFunctions;.ReleaseStringUTFChars (Lorg/jikesrvm/jni/VM_JNIEnvironment;ILorg/vmmagic/unboxed/Address;)V BOOT
67.0 (2.1371610845295055%) Lorg/jikesrvm/runtime/VM_Runtime;.clone (Ljava/lang/Object;)Ljava/lang/Object; BOOT
82.0 (2.615629984051037%) Lorg/jikesrvm/runtime/VM_Runtime;.resolvedNewArray (III[Ljava/lang/Object;IIII)Ljava/lang/Object; BOOT
89.0 (2.8389154704944177%) Lorg/apache/xalan/serialize/SerializerToXML;.characters ([CII)V
114.0 (3.6363636363636362%) Lorg/jikesrvm/scheduler/greenthreads/VM_FileSystem;.writeBytes (I[BII)I BOOT
151.0 (4.81658692185008%) Lorg/apache/xalan/templates/ElemApplyTemplates;.transformSelectedNodes (Lorg/apache/xalan/transformer/TransformerImpl;)V

and 0.96 are:

72.0 (2.187784867821331%) Lorg/jikesrvm/runtime/VM_Runtime;.clone (Ljava/lang/Object;)Ljava/lang/Object; BOOT
94.0 (2.8562746885445156%) Lorg/jikesrvm/scheduler/greenthreads/VM_FileSystem;.writeBytes (I[BII)I BOOT
107.0 (3.2512914007900338%) Lgnu/java/nio/charset/ISO_8859_1$Encoder;.encodeLoop (Ljava/nio/CharBuffer;Ljava/nio/ByteBuffer;)Ljava/nio/charset/CoderResult; BOOT
109.0 (3.3120632026739596%) Lorg/apache/xalan/serialize/SerializerToXML;.characters ([CII)V
159.0 (4.831358249772106%) Lorg/apache/xalan/templates/ElemApplyTemplates;.transformSelectedNodes (Lorg/apache/xalan/transformer/TransformerImpl;)V

my eye is drawn to Lgnu/java/nio/charset/ISO_8859_1$Encoder;.encodeLoop which is a loop that reads from a buffer a char then writes to another buffer a byte. It appears in the 0.96 trace but not the 0.95 trace. There is a TODO item to make this use array copies (I did a patch for this a while ago but never replicated it for other charsets). I'm going to repeat profiling to see if its possible to clearly identify the culprit.

Running the benchmark 3 times on 0.95 and 0.96 confirms the same result. With 0.95 we see encodeLoop in the profiler output once with 1 sample (much < 1% of execution time). With 0.96 it's always in the profiler output with a % of execution time of between 2.4% and 3.25% (for 10 normal size iterations). Our slow down with 0.96 is 3.7% off peak.

Reverting to Classpath 0.95's ISO_8859_1 encoder reverts the following change:

http://developer.classpath.org/pipermail/classpath-patches/2007-July/005548.html

this means that no encoder is installed for output stream writing. Presumably as the encoder should be matching the string ISO8859-1. Without the encoder string the encoder loop is no longer a hot method.

I'm tempted to say this is a won't fix bug. The problem here is that Classpath 0.95 wasn't correctly getting the character set encoding. This has been fixed in 0.96, and reverting to 0.95 seems counterintuitive to me (we break our character sets in order to not use them and thereby get a performance boost). If we want to revert to the Classpath 0.95 behavior we can reverse the patch above, or provide our own character set encoding.

In the longer term character set encoders need optimizing, in particular for the case where they are just copying between arrays (see comment in ISO_8859_1.java).

Ian's detective work indicates that the performance loss happened because between 0.95 and 0.96 a GNU classpath bug was fixed. The performance on 0.95 in effect was cheating by not doing the required char encoding on output.