Skip to main content

Performance regression in simple program?

4 replies [Last post]
Joined: 2004-08-15

Can anyone repeat what I'm seeing here:

With Mustang b74 the program below starts out fast, then slows down by 3x.

time 331 ms, eq 250000000 <- starts out at 330 ms
time 330 ms, eq 250000000
time 1042 ms, eq 250000000 <- sudden slowdown
time 1081 ms, eq 250000000
time 1062 ms, eq 250000000

1.5.0_06 runs at ~330 ms without the slowdown. I'm trying this with Windows XP on IA32. Looking at the output of -XX:PrintCompilation I'm guessing doit() is getting recompiled into a slower version? Though I don't really know how to interpret that output.

Run with "java -server".

<br />
public class Test<br />
{<br />
    public static void main(String args[])<br />
    {<br />
	for (int n = 0; n < 5; n++)<br />
	    doit();<br />
<p>    public static void doit()<br />
    {<br />
	Integer a = new Integer(1);<br />
	Integer b = new Integer(1);<br />
	int eq = 0;</p>
<p>        long start = System.currentTimeMillis();</p>
<p>        for (int n = 0; n < 50000000; n++) {<br />
	    if (a.intValue() == b.intValue()) eq++;<br />
	    if (a.intValue() == b.intValue()) eq++;<br />
	    if (a.intValue() == b.intValue()) eq++;<br />
	    if (a.intValue() == b.intValue()) eq++;<br />
	    if (a.intValue() == b.intValue()) eq++;<br />
	}<br />
        long end = System.currentTimeMillis();</p>
<p>        System.out.println("time " + (end - start) + " ms, eq " + eq);<br />
    }<br />
}<br />

Reply viewing options

Select your preferred way to display the comments and click "Save settings" to activate your changes.
Joined: 2005-06-21

I can't repeat your slowdown, either.

But let me try to explain the PrintCompilation output, though.

> 1% Sjasja::doit @ 27 (153 bytes)

As Peter indicated, the "%" means an on-stack-replacement compilation. The "1" means it is the first compilation of its kind (OSR), followed by the method name, the OSR bci and size of the method's bytecodes.

> 1% made not entrant Sjasja::doit @ 27 (153 bytes)

This indicates that the code for the previous compilation can no longer be entered, due to the code being invalidated or otherwise undesireable.

> 1 Sjasja::doit (153 bytes)

The method "doit" has been entry-compiled. It is the first entry compilation for the JIT.

> 2% Sjasja::doit @ 27 (153 bytes)

The same method is recompiled for OSR at bci 27. It is the second OSR compile for the JIT.

Sometimes mysterious code letters other "%" appear next to the compilation number. The letter "s" indicates that the method is synchronized; "!" indicates a method with an exception handler; "b" means a blocking compile - that is, -Xbatch was used.

Joined: 2003-06-19

Have you tried it moving the timing code outside of the timed method? Often large methods mixing inner loops with rarely executed code will hurt performance.

By my calculations, each loop takes about 8 cycles. So I don't think it's measuring anything particularly important. Perhaps the slow version is just doing each if statement individually.

(FWIW, on Fedore Core 4 with a Celeron D 315, I get times: 279, 223, 187, 186, 188 ms. So, no problem here, although is starts off a little slower than 1.5.0_06 -server.)

Joined: 2004-08-15

Peculiar. Could it be something CPU dependent like differences in branch prediction logic, cache conflicts, preferred instruction alignment in loops, ...? I'm trying this on Pentium M 725 at 1.6GHz.

Moving the comparisons to another function does affect things: the slowdown no longer occurs. Also if the two Integers have different values the speed stays constant.

I noticed this when comparing the speed of JDK 1.5 vs Mustang by timing some jUnit tests. 165 out of 200 tests get faster in Mustang-b74, 35 get (mostly by a little bit) slower. This one was originally a test of equals() methods; "a.equals(b)" with two java.lang.Integer objects shows a similar slowdown.

This is an artificial benchmark, not from any application of mine. So treat it with that level of seriousness :-[i][/i])

Joined: 2004-10-27

I can [b]not[/b] repeat what you are seeing. Running on a P4/3GHz machine running Windows 2000 Pro (having renamed your class Sjasja because otherwise I'd have a [b]lot[/b] of classes named "Test") I see:
[pre] $ $Deployed/JDK-1.6.0/bin/java -showversion -server -XX:+PrintCompilation Sjasja
java version "1.6.0-beta2"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.6.0-beta2-b74)
Java HotSpot(TM) Server VM (build 1.6.0-beta2-b74, mixed mode)
1% Sjasja::doit @ 27 (153 bytes)
1% made not entrant Sjasja::doit @ 27 (153 bytes)
time 359 ms, eq 250000000
1 Sjasja::doit (153 bytes)
2% Sjasja::doit @ 27 (153 bytes)
time 391 ms, eq 250000000
time 313 ms, eq 250000000
time 312 ms, eq 250000000
time 297 ms, eq 250000000[/pre]
I'm pretty sure the "1%" compilation is an "on stack replacement" compilation to take over from the interpreter, and the "1" compilation is the regular compilation to be used the next time Sjasja.doit is invoked. The regular compilation looks like it didn't finish in time for the second call, which might explain the second on stack replacement compilation. But I know whom to ask for a definitive answer.

But, except for the allowable overheads of compilation, I see the expected progression of times downward.