JDK-6396953 : Code runs slower after optimization when using server compiler
  • Type: Bug
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: 6
  • Priority: P4
  • Status: Closed
  • Resolution: Duplicate
  • OS: linux
  • CPU: x86
  • Submitted: 2006-03-10
  • Updated: 2010-04-02
  • Resolved: 2009-08-18
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 7
7Resolved
Related Reports
Duplicate :  
Description
FULL PRODUCT VERSION :
java version "1.6.0-beta2"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.6.0-beta2-b72)
Java HotSpot(TM) Client VM (build 1.6.0-beta2-b72, mixed mode, sharing)

ADDITIONAL OS VERSION INFORMATION :
Linux localhost.localdomain 2.6.11-1.1369_FC4 #1 Thu Jun 2 22:55:56 EDT 2005 i686 athlon i386 GNU/Linux

EXTRA RELEVANT SYSTEM CONFIGURATION :
Tested on:
AMD Duron 800
Amd Athlon X2 4400+

A DESCRIPTION OF THE PROBLEM :
When executing the sample code the code runs first quite fast till hotspot server completly has "optimized" all methods when suddenly performance falls down and stays there.

There are 3 tests, test 1 and 2 are slower after optimization, only test 3 runs faster after optimization using the server runtime (C2).
I marked this one as regression since the strange behaviour was introduced with java-1.4, java-1.3.1 worked quite well.
With the client jvm a small speedup can be measured during execution, how it should be.

Here are my benchmark results with the code above on a Duron800, a quite outdated CPU:
1.6.0-beta2-b72 / Java HotSpot(TM) Server VM
2.871 secs 2.827 secs 5.525 secs
2.742 secs 2.772 secs 5.473 secs
4.665 secs 4.336 secs 2.784 secs <<--- What happens here?
4.661 secs 4.334 secs 2.78 secs

1.4.2_06-b03 / Java HotSpot(TM) Server VM
3.104 secs 3.01 secs 4.953 secs
4.827 secs 4.2 secs 2.82 secs <<-- Here the same, but earlier
4.832 secs 4.207 secs 2.823 secs
4.832 secs 4.208 secs 2.829 secs

1.3.1_16-b06 / Java HotSpot(TM) Server VM
6.312 secs 6.292 secs 5.875 secs
4.729 secs 4.663 secs 4.676 secs -->> No bug, but slow. right behaviour, everything gets faster...
4.72 secs 4.686 secs 4.666 secs


This is the output of PrintCompilation, tests are labeld with (test):
1.6.0-beta2-b72 / Java HotSpot(TM) Server VM
1% ArrayDemo::test1 @ 46 (103 bytes)
3.077 secs(1) 2% ArrayDemo::test2 @ 46 (100 bytes)
3.033 secs(2) 3% ArrayDemo::test3 @ 46 (87 bytes)
5.65 secs(3)
1 ArrayDemo::test1 (103 bytes)
2.946 secs(1) 2 ArrayDemo::test2 (100 bytes)
2.975 secs(2) 3 ArrayDemo::test3 (87 bytes)
5.599 secs(3)
4.778 secs 4.425 secs 2.982 secs

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
run the sample code using the java server runtime.

EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
when hotspot has finished with compilation performance should be better instead of worse.
ACTUAL -
when hotspot has finished compilation the test1 and test2 run slower than before.

REPRODUCIBILITY :
This bug can be reproduced always.

---------- BEGIN SOURCE ----------
public class ArrayDemo
{
	private final int[] a = new int[20*1024];
	private final int[] b = new int[a.length];
	private final int LOOPS = 5000;

	public ArrayDemo()
	{
		init = false;

		for(int k = 0; k < 500; k++) {
			test1(LOOPS);
			test2(LOOPS);
			test3(LOOPS);
			System.out.println();
		}
	}

	private long start;
	private boolean init = true;

	private void end()
	{
		if(init) return;
		long dur = (System.currentTimeMillis() - start);
		System.out.print((dur/1000d)+" secs  ");
	}

	private void test1(final int loops)
	{
		start = System.currentTimeMillis();

		for(int k = 0; k < loops; k++) {
			int ia = 0;
			int ib = 0;
			while(true) {
				int t = a.length - ia;
				if(t == 0) break;
				if(t > 1024) t = 1024;
				do {
					if(b[ib] == 0xfe)break;
					a[ia++] = b[ib++];
				} while(--t > 0);
			}
		}

		end();
	}

	private void test2(final int loops)
	{
		start = System.currentTimeMillis();

		for(int k = 0; k < loops; k++) {
			int ia = 0;
			int ib = 0;
			while(true) {
				int t = a.length - ia;
				if(t == 0) break;
				if(t > 1024) t = 1024;
				do {
					if(b[ib] == 0xfe)/*break*/;
					a[ia++] = b[ib++];
				} while(--t > 0);
			}
		}

		end();
	}

	private void test3(final int loops)
	{
		start = System.currentTimeMillis();

		for(int k = 0; k < loops; k++) {
			int ia = 0;
			int ib = 0;
			while(true) {
				int t = a.length - ia;
				if(t == 0) break;
				if(t > 1024) t = 1024;
				do {
/*					if(b[ib] == 0xfe)break;*/
					a[ia++] = b[ib++];
				} while(--t > 0);
			}
		}

		end();
	}

	public static void main(String[] args)
	{
		System.out.println(System.getProperty("java.vm.version")+" / "+System.getProperty("java.vm.name"));
		new ArrayDemo();
	}
}
---------- END SOURCE ----------

Comments
EVALUATION This was fixed by 6384206 which corrected the loop head cloning in ciTypeFlow a long with other things. The build before this fix shows the problem: 14.0-b04-2008-09-17-164137.rasbold.6711100 / OpenJDK Server VM 0.082 secs 0.07 secs 0.393 secs 0.071 secs 0.062 secs 0.387 secs 0.072 secs 0.066 secs 0.064 secs 0.073 secs 0.065 secs 0.065 secs 0.072 secs 0.066 secs 0.065 secs 0.072 secs 0.065 secs 0.065 secs The build with the fix is fine. 14.0-b04-2008-09-17-200034.never.6384206 / OpenJDK Server VM 0.095 secs 0.077 secs 0.076 secs 0.082 secs 0.067 secs 0.068 secs 0.217 secs 0.064 secs 0.065 secs 0.217 secs 0.064 secs 0.065 secs 0.216 secs 0.064 secs 0.064 secs 0.217 secs 0.065 secs 0.064 secs
18-08-2009

EVALUATION This bug no longer exists in the current VMs, and I am going to close it. Here is the tests on sparc and x86: (1) sparc 64 bit server [cf231476@escuintla ~]$ /java/re/jdk/1.7.0/promoted/all/b02/binaries/solaris-sparcv9/bin/java -server ArrayDemo 1.7.0-ea-b02 / Java HotSpot(TM) Server VM 0.406 secs 0.275 secs 0.873 secs 0.376 secs 0.25 secs 0.857 secs 0.833 secs 0.392 secs 0.251 secs // <--- reproducible 0.834 secs 0.392 secs 0.252 secs 0.832 secs 0.393 secs 0.252 secs [cf231476@escuintla ~]$ /java/re/jdk/1.7.0/promoted/all/b03/binaries/solaris-sparcv9/bin/java -server ArrayDemo 1.7.0-ea-b03 / Java HotSpot(TM) Server VM 0.41 secs 0.275 secs 0.875 secs 0.358 secs 0.248 secs 0.859 secs 0.377 secs 0.247 secs 0.249 secs // <--- disappeared from 1.7.0-ea-b03 0.376 secs 0.247 secs 0.25 secs 0.376 secs 0.247 secs 0.249 secs 0.376 secs 0.247 secs 0.248 secs [cf231476@escuintla ~]$ /java/re/jdk/1.7.0/promoted/all/b68/binaries/solaris-sparcv9/bin/java -server ArrayDemo 16.0-b07 / Java HotSpot(TM) Server VM 0.412 secs 0.275 secs 0.271 secs 0.377 secs 0.249 secs 0.247 secs 0.363 secs 0.25 secs 0.249 secs // <--- current vm still good 0.362 secs 0.25 secs 0.25 secs 0.362 secs 0.251 secs 0.249 secs 0.363 secs 0.249 secs 0.249 secs 0.363 secs 0.25 secs 0.249 secs (2) sparc 32-bit server: [cf231476@escuintla ~]$ /java/re/jdk/1.7.0/promoted/all/b02/binaries/solaris-sparc/bin/java -server ArrayDemo 1.7.0-ea-b02 / Java HotSpot(TM) Server VM 0.405 secs 0.274 secs 0.872 secs 0.378 secs 0.249 secs 0.858 secs 0.833 secs 0.391 secs 0.253 secs // <--- reproducible 0.834 secs 0.393 secs 0.251 secs 0.833 secs 0.39 secs 0.253 secs 0.833 secs 0.393 secs 0.252 secs [cf231476@escuintla ~]$ /java/re/jdk/1.7.0/promoted/all/b03/binaries/solaris-sparc/bin/java -server ArrayDemo 1.7.0-ea-b03 / Java HotSpot(TM) Server VM 0.386 secs 0.272 secs 0.876 secs 0.357 secs 0.247 secs 0.858 secs 0.378 secs 0.247 secs 0.249 secs // <--- disappeared from 1.7.0-ea-b03 0.377 secs 0.246 secs 0.248 secs 0.378 secs 0.247 secs 0.248 secs 0.378 secs 0.247 secs 0.249 secs 0.378 secs 0.247 secs 0.248 secs 0.377 secs 0.246 secs ^C^[[24;5~[cf231476@escuintla ~]$ /java/re/jdk/1.7.0/promoted/all/b68/binaries/solaris-sparc/bin/java -server ArrayDemo 16.0-b07 / Java HotSpot(TM) Server VM 0.413 secs 0.272 secs 0.271 secs 0.376 secs 0.246 secs 0.25 secs 0.361 secs 0.249 secs 0.249 secs // <--- current vm still good 0.362 secs 0.25 secs 0.248 secs 0.363 secs 0.249 secs 0.248 secs 0.362 secs 0.25 secs 0.249 secs 0.361 secs 0.249 secs 0.249 secs (3) x86 64-bit server: [cf231476@pathscale ~]$ /java/re/jdk/1.7.0/promoted/all/b02/binaries/solaris-amd64/bin/java -server ArrayDemo 1.7.0-ea-b02 / Java HotSpot(TM) Server VM 0.166 secs 0.091 secs 0.474 secs 0.084 secs 0.083 secs 0.468 secs 0.334 secs 0.263 secs 0.069 secs // <--- reproducible 0.334 secs 0.263 secs 0.068 secs 0.334 secs 0.264 secs 0.068 secs 0.335 secs 0.264 secs 0.068 secs [cf231476@pathscale ~]$ /java/re/jdk/1.7.0/promoted/all/b03/binaries/solaris-amd64/bin/java -server ArrayDemo 1.7.0-ea-b03 / Java HotSpot(TM) Server VM 0.204 secs 0.078 secs 0.298 secs 0.121 secs 0.069 secs 0.293 secs 0.085 secs 0.065 secs 0.069 secs // <--- disappeared from 1.7.0-ea-b03 0.086 secs 0.064 secs 0.069 secs 0.086 secs 0.065 secs 0.069 secs 0.085 secs 0.065 secs 0.069 secs 0.085 secs 0.065 secs 0.069 secs 0.085 secs 0.065 secs 0.069 secs 0.085 secs 0.065 secs 0.069 secs [cf231476@pathscale ~]$ /java/re/jdk/1.7.0/promoted/all/b68/binaries/solaris-amd64/bin/java -server ArrayDemo 16.0-b07 / Java HotSpot(TM) Server VM 0.163 secs 0.087 secs 0.082 secs 0.068 secs 0.074 secs 0.073 secs 0.075 secs 0.074 secs 0.074 secs // <--- current vm still good 0.074 secs 0.074 secs 0.074 secs 0.074 secs 0.074 secs 0.074 secs 0.073 secs 0.074 secs 0.074 secs 0.074 secs 0.074 secs 0.074 secs 0.076 secs 0.074 secs 0.074 secs (4) x64 64-bit server: [cf231476@pathscale ~]$ /java/re/jdk/1.7.0/promoted/all/b02/binaries/solaris-i586/bin/java -server ArrayDemo 1.7.0-ea-b02 / Java HotSpot(TM) Server VM 0.167 secs 0.09 secs 0.474 secs 0.085 secs 0.085 secs 0.468 secs 0.335 secs 0.264 secs 0.068 secs // <--- reproducible 0.335 secs 0.263 secs 0.069 secs 0.334 secs 0.264 secs 0.069 secs 0.334 secs 0.264 secs 0.068 secs 0.335 secs 0.265 secs 0.068 secs [cf231476@pathscale ~]$ /java/re/jdk/1.7.0/promoted/all/b03/binaries/solaris-i586/bin/java -server ArrayDemo 1.7.0-ea-b03 / Java HotSpot(TM) Server VM 0.203 secs 0.078 secs 0.299 secs 0.121 secs 0.07 secs 0.294 secs 0.085 secs 0.065 secs 0.073 secs // <--- disappeared from 1.7.0-ea-b03 0.086 secs 0.064 secs 0.069 secs 0.086 secs 0.064 secs 0.069 secs 0.086 secs 0.064 secs 0.069 secs 0.086 secs 0.064 secs 0.068 secs [cf231476@pathscale ~]$ /java/re/jdk/1.7.0/promoted/all/b68/binaries/solaris-i586/bin/java -server ArrayDemo 16.0-b07 / Java HotSpot(TM) Server VM 0.163 secs 0.087 secs 0.082 secs 0.069 secs 0.073 secs 0.074 secs 0.074 secs 0.074 secs 0.073 secs // <--- current vm still good 0.074 secs 0.074 secs 0.074 secs 0.074 secs 0.074 secs 0.074 secs 0.074 secs 0.074 secs 0.074 secs 0.074 secs 0.074 secs 0.074 secs
13-08-2009

EVALUATION The unusual loop constructs in the test case (infinite loop with internal break surrounding a do-while with a pre-decrement) are causing confusion in the server compiler. The faster times are a result of the OSR compilation; slower timings happen after entry-compilation. CITypeFlow loop-head duplication is likely at fault. Changes there happened in the 1.4.2 time frame due to changes in javac default bytecode constructs.
13-03-2006