JDK-4653558 : Java Application startup time is SLOW in JDK 1.4 compared to JDK 1.3.1_02
  • Type: Bug
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 1.4.0
  • Priority: P2
  • Status: Closed
  • Resolution: Fixed
  • OS: windows_nt
  • CPU: x86
  • Submitted: 2002-03-15
  • Updated: 2012-10-08
  • Resolved: 2002-05-23
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.
Other
1.4.1 betaFixed
Related Reports
Relates :  
JDK-4712392 - REGRESSION: Reduced default resolution for Thread.sleep() breaks apps.
Relates :  
JDK-4717583 - High resolution Thread.sleep() needs lower overhead on Windohs
Relates :  
JDK-4679390 - sun.misc.Unsafe needs to bind to new JVM native methods
Relates :  
JDK-5005837 - rework win32 timebeginperiod usage
Relates :  
JDK-4717079 - Sybase Java Application startup time is SLOW in JDK 1.4 compared to JDK 1.3.1_02
Relates :  
JDK-4616656 - Need a more portable way to unsafely access fields in JDk 1.4
Relates :  
JDK-4546426 - JVM_Clone clears newly allocated object
Relates :  
JDK-4690509 - Sybase Java Application startup time is SLOW in JDK 1.4 compared to JDK 1.3.1_02
Description
Customer Problem Description:
----------------------------

----
We have noticed here that jdk 1.4 starts our applications slower than
Jdk 1.3.1 did.  In fact we have found it to be about 50% worse.  I
thought I had heard that startup time was improved with JRE 1.4.

I have attached a log file that shows my results for one application.  I
compared different java compilers, jar indexing, and the 1.3.1_02 and 1.4
VMs.

Are these the results I should be expecting when comparing 1.3.1_02 with
1.4?

I have attached a sample application which shows this behavior

Unzip it into a directory.  PerfTest2 is the batch file
that runs everything.  You will have to change:
 set jdk=1.3.1_02 to match your machine.

PerfRun.bat assumes that your jre's are installed with the naming pattern
c:\jdk followed by the setting for jdk in PerfTest2.bat.

Note: I run the test once and throw the results away.  Then I run it again
- that way everything should be in memory.

In our case jdk_1.3.1_02_13.log is the same as jdk_1.3.1_02_13c.log
as we only run with Sun's javac compiler.


(See attached file: perfTest2.log)

Note: We haven't tested this application on Sparc platforms. But, if the
performance problem does show up on Sparc, please fix it as we have
customers using our application on Sun's UltraSparc servers.
-----
Comments
CONVERTED DATA BugTraq+ Release Management Values COMMIT TO FIX: hopper-beta FIXED IN: hopper-beta INTEGRATED IN: hopper-beta
14-06-2004
EVALUATION Further data points (suggested by Fred Oliver): (All these run's are default mem/gc params.) 1)1.3.1 JDK 10 runs: jdk_1.3.1_03_13.log Total time: min: 3.1 max: 3.3 average: 3.2000003 Total CPU: min: 2.9 max: 3.2 average: 3.0900002 Total kernel: min: 0.4 max: 0.5 average: 0.48000002 Total user: min: 2.5 max: 2.7 average: 2.6100001 10 runs: jdk_1.3.1_03_13i.log Total time: min: 3.0 max: 3.2 average: 3.1500003 Total CPU: min: 2.9 max: 3.2 average: 3.0900002 Total kernel: min: 0.4 max: 0.5 average: 0.47000003 Total user: min: 2.4 max: 2.7 average: 2.6200001 2)1.3.1 JDK using 1.4 client vm 10 runs: jdk_1.3.1_03+1.4vm_13.log Total time: min: 3.4 max: 3.7 average: 3.55 Total CPU: min: 3.2 max: 3.5 average: 3.4299998 Total kernel: min: 0.5 max: 0.6 average: 0.53 Total user: min: 2.7 max: 3.0 average: 2.9 10 runs: jdk_1.3.1_03+1.4vm_13i.log Total time: min: 3.5 max: 3.7 average: 3.5899997 Total CPU: min: 3.4 max: 3.6 average: 3.4699998 Total kernel: min: 0.5 max: 0.6 average: 0.53000003 Total user: min: 2.8 max: 3.0 average: 2.94 3)1.4.0 JDK 10 runs: jdk_1.4.0_13.log Total time: min: 4.5 max: 4.7 average: 4.5699997 Total CPU: min: 4.3 max: 4.5 average: 4.45 Total kernel: min: 0.4 max: 0.6 average: 0.52 Total user: min: 3.8 max: 4.0 average: 3.9299998 10 runs: jdk_1.4.0_13i.log Total time: min: 4.6 max: 4.7 average: 4.6299996 Total CPU: min: 4.4 max: 4.6 average: 4.4900002 Total kernel: min: 0.5 max: 0.6 average: 0.56 Total user: min: 3.8 max: 4.0 average: 3.9299998 I am also counting class loads (using -XX:+TraceClassLoading ), and will add that info when I summarize it, but on preliminary analysis it looks like the difference in the times from 2 & 3 above is just about the ratio of the difference in the number of classes loaded between 1.3.1 and 1.4, so there is probably little that can be done to improve the picture beyond using the -ms128M -mx128M -XX:PermSize=8M options to avoid the full gc. ###@###.### 2002-04-08 Another anomaly noted in this test case between 1.3.1 and 1.4 is the following: Old style profiling 1.4.0 gets the following top "hot method": Sparc: 513952 java.lang.reflect.Method.getReturnType()Ljava/lang/Class; java.lang.Class.removeByNameAndSignature(Ljava/util/Collection;Ljava/lang/reflect/Method;)V 3503 Win32: 511200 java.lang.reflect.Method.getReturnType()Ljava/lang/Class; java.lang.Class.removeByNameAndSignature(Ljava/util/Collection;Ljava/lang/reflect/Method;)V 3154 (count differs but its the same top on both solaris sparc and win32). 1.3.1 shows sparc: 64390 java.lang.String.indexOf(Ljava/lang/String;I)I sun.awt.X11GraphicsEnvironment.getFontField(Ljava/lang/String;I)Ljava/lang/String; 562 win32: 11465 java.lang.String.charAt(I)C java.util.Properties.loadConvert(Ljava/lang/String;)Ljava/lang/String; 70 Looking at the methods invoked: egrep reflect 131-trace [Loaded java.lang.reflect.AccessibleObject from /usr/local/java/1.3.1/jre/lib/rt.jar] [Loaded java.lang.reflect.Member from /usr/local/java/1.3.1/jre/lib/rt.jar] [Loaded java.lang.reflect.Method from /usr/local/java/1.3.1/jre/lib/rt.jar] [Loaded java.lang.reflect.Constructor from /usr/local/java/1.3.1/jre/lib/rt.jar] [Loaded java.lang.reflect.ReflectPermission from /usr/local/java/1.3.1/jre/lib/rt.jar] [Loaded java.lang.reflect.Field from /usr/local/java/1.3.1/jre/lib/rt.jar] [Loaded java.lang.reflect.Proxy from /usr/local/java/1.3.1/jre/lib/rt.jar] [Loaded java.lang.reflect.InvocationHandler from /usr/local/java/1.3.1/jre/lib/rt.jar] egrep reflect 131-trace | wc -l 8 So we load ~ 8 reflection methods, but in 1.4: egrep reflect 140-trace [Loaded java.lang.reflect.AccessibleObject from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded java.lang.reflect.Member from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded java.lang.reflect.Field from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded java.lang.reflect.Method from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded java.lang.reflect.Constructor from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.MagicAccessorImpl from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.MethodAccessor from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.MethodAccessorImpl from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.ConstructorAccessor from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.ConstructorAccessorImpl from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.DelegatingClassLoader from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded java.lang.reflect.ReflectPermission from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.ReflectionFactory$GetReflectionFactoryAction from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.ReflectionFactory from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.Reflection from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded java.lang.reflect.Modifier from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.LangReflectAccess from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded java.lang.reflect.ReflectAccess from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.ReflectionFactory$1 from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.NativeConstructorAccessorImpl from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.DelegatingConstructorAccessorImpl from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded java.lang.reflect.Array from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.UnsafeFieldAccessorFactory from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.FieldAccessor from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.FieldAccessorImpl from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.UnsafeFieldAccessorImpl from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.UnsafeStaticFieldAccessorImpl from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.UnsafeStaticIntegerFieldAccessorImpl from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.NativeMethodAccessorImpl from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.DelegatingMethodAccessorImpl from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded java.lang.reflect.Proxy from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded java.lang.reflect.InvocationHandler from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.ClassFileConstants from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.AccessorGenerator from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.MethodAccessorGenerator from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.ByteVectorFactory from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.ByteVector from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.ByteVectorImpl from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.ClassFileAssembler from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.UTF8 from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.Label from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.Label$PatchInfo from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.MethodAccessorGenerator$1 from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.ClassDefiner from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.ClassDefiner$1 from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.SerializationConstructorAccessorImpl from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.GeneratedSerializationConstructorAccessor1] [Loaded sun.reflect.BootstrapConstructorAccessorImpl from /usr/local/java/1.4.0/jre/lib/rt.jar] [Loaded sun.reflect.GeneratedMethodAccessor1] [Loaded sun.reflect.GeneratedMethodAccessor2] [Loaded sun.reflect.GeneratedMethodAccessor3] [Loaded sun.reflect.GeneratedMethodAccessor4] [Loaded sun.reflect.GeneratedMethodAccessor5] [Loaded sun.reflect.GeneratedMethodAccessor6] egrep reflect 140-trace | wc -l 54 Is this part of the problem ? ###@###.### 2002-04-12 I've added Ken Russel to the interest list as he has some insight into the "reflection" changes in 1.4. More interesting Solaris sparc sample points: 1st "vanilla" with verbose:gc 145 % ./tperf 1.3.1 [GC 2047K->475K(3520K), 0.0320291 secs] [GC 3146K->1624K(3776K), 0.0524988 secs] real 10.7 user 3.3 sys 0.5 146 % ./tperf 1.4.0 [GC 2047K->756K(3520K), 0.0918030 secs] [GC 2803K->1227K(3520K), 0.1338603 secs] [Full GC 3044K->1770K(3520K), 0.2391637 secs] real 12.3 user 5.0 sys 0.5 So we see maybe 20% slower. 2nd we remove the compiler: 147 % ./tperf 1.4.0 -Xint [GC 2047K->756K(3520K), 0.0384700 secs] [GC 2803K->1227K(3520K), 0.0456678 secs] [Full GC 3044K->1770K(3520K), 0.1997679 secs] real 12.9 user 10.4 sys 0.3 148 % ./tperf 1.3.1 -Xint [GC 2047K->475K(3520K), 0.0262458 secs] [GC 2523K->1494K(3648K), 0.0516885 secs] real 7.4 user 5.0 sys 0.4 Yipes! Almost 50% slower... SO always compile? 149 % ./tperf 1.4.0 -Xcomp [GC 2048K->756K(3520K), 0.0347887 secs] [GC 2803K->1225K(3520K), 0.0445286 secs] [Full GC 1781K->1154K(3520K), 0.5614298 secs] real 33.2 user 26.3 sys 1.0 150 % ./tperf 1.3.1 -Xcomp [GC 2047K->475K(3520K), 0.0236259 secs] [GC 2310K->1033K(3520K), 0.0867496 secs] real 16.3 user 11.2 sys 1.0 Nope, still 50% slower. Maybe get rid of GC issue? 153 % ./tperf 1.4.0 -ms128M -mx128M -XX:PermSize=8m -Xint real 13.5 user 10.0 sys 0.3 154 % ./tperf 1.3.1 -ms128M -mx128M -XX:PermSize=8m -Xint real 7.0 user 4.7 sys 0.4 So taking the compilers and GC out of it we are in even worse shape... Anyone ? ###@###.### 2002-04-12 Update requested, Not much to say, Ken Russell says the reflection issue above is an artifact and not a major contributor, and the stats from hprof seem to verify this: 1.4.0 13 0.29% 76.44% 40992 732 40992 732 2925 java.lang.reflect.Method 34 0.13% 80.42% 18760 335 18760 335 2915 java.lang.reflect.Method 50 0.10% 82.23% 14392 257 14392 257 3025 java.lang.reflect.Method 58 0.08% 82.95% 12000 250 12000 250 2251 java.lang.reflect.Field 141 0.03% 87.09% 4568 19 4568 19 2954 java.lang.reflect.Method 147 0.03% 87.27% 4160 6 4160 6 2944 java.lang.reflect.Method 157 0.03% 87.56% 4032 72 4032 72 2962 java.lang.reflect.Method 165 0.03% 87.78% 3712 2 3712 2 3996 java.lang.reflect.Method 166 0.03% 87.80% 3704 13 3704 13 2951 java.lang.reflect.Method 172 0.02% 87.95% 3472 38 3472 38 2925 java.lang.reflect.Method 182 0.02% 88.19% 3264 68 3264 68 2257 java.lang.reflect.Field 220 0.02% 88.97% 2592 54 2592 54 2281 java.lang.reflect.Field 331 0.01% 90.58% 1648 23 1648 23 2915 java.lang.reflect.Method 332 0.01% 90.60% 1648 16 1648 16 2959 java.lang.reflect.Method .83 1.3.1: 73 0.10% 71.21% 6240 195 6240 195 2276 java.lang.reflect.Field 436 0.02% 84.34% 1040 26 1040 26 2684 java.lang.reflect.Method 543 0.01% 86.04% 832 26 832 26 1575 java.lang.reflect.Field 597 0.01% 86.72% 720 18 720 18 2757 java.lang.reflect.Method 635 0.01% 87.15% 640 16 640 16 1914 java.lang.reflect.Method .15% Still investigating other causes and possible workarounds related to class loading - but none that have provided any significant relief beyond that provided by increasing the permanent generation. ###@###.### 2002-05-02 ###@###.### 2002-05-09 Can't be accepted for 1.4.1 as we don't have enough analysis. ###@###.### 2002-05-17 The following data was collected using a 1.4.1 JVM in both the 1.3.1 JRE and the 1.4.1 JRE for comparison. A small JVMDI agent was used to identify and count the number of Java language methods called during the startup time for this application. Result: There are ~422,000 methods called in JRE 1.3.1, vs. ~1,661,000 methods called in JRE 1.4.1, or about 3.9x. Of the additional 1.2 million method calls, more than 800,000 are to three routines (about equally) in java.util.LinkedList$ListItr. Essentially all of the LinkedList manipulations derive from Class.getMethod(), which is used by Swing, and extensively by this test application. This LinkedList processing is part of the reflection "improvements" added to the 1.4.0 JRE. ------- This bug has been marked as committed to hopper-beta in advance of the bug review meeting later today. ###@###.### 2002-05-20 Work has been ongoing recently to investigate and decrease Java's startup time on all platforms, not just Windows. Initial results have been encouraging on Solaris but were significantly less profitable on Windows. Investigation into why this was the case turned up a longstanding issue with the JVM and JDK related to interaction with one of the core Windows components. This issue has been present since JDK 1.2. Fixing this issue improves startup time on Windows substantially. Startup time for small Swing applications like Stylepad is significantly better than with JDK 1.3.1. The fix for this longstanding issue is small and has been put back for 1.4.1. It decreases Windows startup time to the point where the customer should be satisfied, and there is nothing more we can do in this area for 1.4.1. The cross-platform startup time work carries more work and risk and is being targeted for 1.4.2. The comments section contains more details. ###@###.### 2002-05-21 ###@###.### 2002-05-21 I've brought over the latest changes putback to main_baseline, and measure no difference in performance at all (i.e. still bad). In addition, since the 1.4.1 JVM plugged into the 1.3.1 JRE still shows relatively good performance, the problem is not in the JRE. ----- Please try running with the builds pointed to in the comments. The performance fix requires both JDK and JVM changes. There is certainly more work being done at startup in JDK 1.4.0 compared to 1.3.1, but the performance increase due to the Windows dependency removal dwarfs that increase on all the systems I've tested on. ###@###.### 2002-05-21 A few people have tested with the binaries I provided and not seen any startup time decrease; I subsequently tested on five other machines around the office and did not see the high cost of initializing this particular Windows component on any of them. Therefore the problem noted in the comments is rare and won't address the customer's problem. I've asked CTE to open a new bug for this escalation under which I'll investigate the reflection problem noted above. (This bug ID has already been used for the putbacks to the JVM and JDK of the dependency removal noted in the comments.) ###@###.### 2002-05-22
22-05-2002