Same testcase composed of the following stages were run with
JDK 142_16 and 6u21
a. startup
b. process request (db query)
c. process db query results
d. output
Common options:
-server
-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps
-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime
-XX:+PrintCompilation -XX:-BackgroundCompilation -Xbatch -XX:CICompilerCount=1
-XX:PermSize=256m -XX:MaxPermSize=256m
JDK 142_16 specific options:
-Xms256m -Xmx256m -Xrunhprof:cpu=samples
JDK 6u21 specific options:
-Xms1536m -Xmx1536m -agentlib:hprof=cpu=samples
Elapsed time for testcase execution
JDK 1.4.2_16 : 82
JDK 6u21 : 422
CPU sample hprof - big differences between 142_16 and 6u21
JDK 1.4.2_16
/cores_data/pool-1/data6/73055010/09Aug2010PrintCompHprof/JDK142_16_hprof_cpusamples.08_09_2010.22_26_15
CPU SAMPLES BEGIN (total = 3388) Mon Aug 9 22:27:38 2010
rank self accum count trace method
1 27.33% 27.33% 926 117 java.io.FileOutputStream.openAppend
2 15.05% 42.38% 510 112 java.nio.HeapByteBuffer.<init>
3 8.26% 50.65% 280 65 java.net.SocketInputStream.socketRead0
4 6.38% 57.02% 216 109 java.io.FileOutputStream.writeBytes
5 2.54% 59.56% 86 118 sun.nio.cs.StreamEncoder.forOutputStreamWriter
6 2.33% 61.89% 79 116 java.io.FileOutputStream.close0
7 1.95% 63.84% 66 114 java.nio.CharBuffer.allocate
8 1.42% 65.26% 48 110 sun.nio.cs.ISO_8859_1$Encoder.<init>
9 1.27% 66.53% 43 126 java.lang.StringBuffer.expandCapacity
10 1.15% 67.68% 39 167 java.io.FileWriter.<init>
11 1.03% 68.71% 35 127 sun.nio.cs.ISO_8859_1.newEncoder
12 1.03% 69.75% 35 145 java.lang.StringBuffer.expandCapacity
13 1.00% 70.75% 34 111 sun.nio.cs.ISO_8859_1.newDecoder
14 0.97% 71.72% 33 173 java.io.FileWriter.<init>
15 0.97% 72.70% 33 131 sun.nio.cs.StreamEncoder.write
JDK 6u21
/cores_data/pool-1/data6/73055010/09Aug2010PrintCompHprof/2_jdk6_hprof_cpusamples.08_09_2010.18_33_27
CPU SAMPLES BEGIN (total = 21132) Mon Aug 9 18:40:30 2010
rank self accum count trace method
1 11.27% 11.27% 2382 300852 java.lang.Integer.parseInt
2 10.56% 21.83% 2231 300761 java.lang.Object.<init>
3 6.97% 28.80% 1472 300756 java.io.FileOutputStream.openAppend
4 4.08% 32.88% 863 300766 java.io.FileOutputStream.writeBytes
5 2.82% 35.70% 596 300674 java.util.Arrays.copyOfRange
6 2.03% 37.72% 428 300884 com.verizon.common.services.svcAddrVal.components.irepmw.TLVMessage.retrieveField
7 2.00% 39.72% 422 300880 com.verizon.common.services.svcAddrVal.components.irepmw.TLVMessage.retrieveField
8 1.31% 41.03% 277 300663 java.net.SocketInputStream.socketRead0
9 1.13% 42.16% 238 300870 com.verizon.common.services.svcAddrVal.components.irepmw.TLVMessage.retrieveField
10 1.07% 43.23% 226 300934 com.verizon.common.services.svcAddrVal.components.irepmw.TLVMessage.retrieveField
11 1.06% 44.28% 223 300863 com.verizon.common.services.svcAddrVal.components.irepmw.TLVMessage.retrieveField
12 1.05% 45.33% 222 300905 com.verizon.common.services.svcAddrVal.components.irepmw.TLVMessage.retrieveField
13 1.05% 46.38% 221 300919 com.verizon.common.services.svcAddrVal.components.irepmw.TLVMessage.retrieveField
14 1.05% 47.43% 221 300930 com.verizon.common.services.svcAddrVal.components.irepmw.TLVMessage.retrieveField
15 1.05% 48.47% 221 300926 com.verizon.common.services.svcAddrVal.components.irepmw.TLVMessage.retrieveField
It seems a lot of time in 6u21 was spent in Integer.parseInt.
The Integer.parseInt method was noted to be compiled in both 142_16 and 6u21,
JDK 142_16
/cores_data/pool-1/data6/73055010/09Aug2010PrintCompHprof/JDK142_16_AddrOut.log
25 b java.lang.Integer::parseInt (269 bytes)
JDK 6u21
/cores_data/pool-1/data6/73055010/09Aug2010PrintCompHprof/2_AddrOut.log
84 b java.lang.Integer::parseInt (269 bytes)
The source code of
com.verizon.common.services.svcAddrVal.components.irepmw.TLVMessage.retrieveField
in /cores_data/pool-1/data6/73055010/09Aug2010/code.snippet
In addition, /cores_data/pool-1/data6/73055010/09Aug2010/log.diff showed
big differences in execution time around the area surrounding
Integer.parseInt from code.snippet (trace the message "returning Data ...")
GC statistics - total GC time rather insignificant, compared to the total execution time
JDK 142_16
what count total mean max stddev
gen1t(s) 2 0.267 0.13337 0.254 0.1703
GC(s) 2 0.267 0.13337 0.254 0.1703
used1b(MB) 2 165.672 82.83594 165.672 117.1477
used1a(MB) 2 10.280 5.14014 10.202 7.1588
used_b(MB) 2 248.618 124.30908 248.484 175.6104
used_a(MB) 2 10.280 5.14014 10.202 7.1588
safept_gc(s) 2 0.267 0.13373 0.254 0.1703
safept_gc_delta(s) 2 0.001 0.00036 0.000 0.0000
safept(s) 4554 9.513 0.00209 0.639 0.0339
apptime(s) 4554 73.547 0.01615 0.066 0.0099
alloc/elapsed_time = 0.000 MB / 82.931 s = 0.000 MB/s
alloc/tot_cpu_time = 0.000 MB / 82.931 s = 0.000 MB/s
alloc/mut_cpu_time = 0.000 MB / 82.664 s = 0.000 MB/s
promo/elapsed_time = 0.000 MB / 82.931 s = 0.000 MB/s
promo/gc0_time = 0.000 MB / 0.000 s = 0.000 MB/s
gc_seq_load = 0.267 s / 82.931 s = 0.322%
gc_conc_load = 0.000 s / 82.931 s = 0.000%
gc_tot_load = 0.267 s / 82.931 s = 0.322%
JDK 6u21
what count total mean max stddev
gen0t(s) 201 4.958 0.02467 0.282 0.0384
GC(s) 201 4.958 0.02467 0.282 0.0384
alloc(MB) 201 93648.118 465.91104 511.125 83.3421
promo(MB) 201 694.590 3.45567 90.465 14.1692
used0b(MB) 201 94576.668 470.53069 511.510 76.9097
used0a(MB) 201 928.919 4.62149 119.307 17.3632
used_b(MB) 201 228881.429 1138.71358 1206.095 147.5986
used_a(MB) 201 135928.270 676.26005 694.974 87.3069
commit0(MB) 201 97956.250 487.34453 511.562 48.1931
commit1(MB) 201 205824.000 1024.00000 1024.000 0.0000
commit(MB) 201 303780.250 1511.34453 1535.562 48.1931
safept_gc(s) 201 5.081 0.02528 0.283 0.0384
safept_gc_delta(s) 201 0.124 0.00062 0.001 0.0001
safept(s) 21271 20.520 0.00096 0.283 0.0044
apptime(s) 21272 401.338 0.01887 0.091 0.0024
alloc/elapsed_time = 93648.118 MB / 401.471 s = 233.262 MB/s
alloc/tot_cpu_time = 93648.118 MB / 401.471 s = 233.262 MB/s
alloc/mut_cpu_time = 93648.118 MB / 396.513 s = 236.179 MB/s
promo/elapsed_time = 694.590 MB / 401.471 s = 1.730 MB/s
promo/gc0_time = 694.590 MB / 4.958 s = 140.101 MB/s
gc_seq_load = 4.958 s / 401.471 s = 1.235%
gc_conc_load = 0.000 s / 401.471 s = 0.000%
gc_tot_load = 0.267 s / 82.931 s = 0.322%
Additional tests:
1. 6u21 with -XX:PerfDataSamplingInterval=500 - doesn't help
2. 6u21 with -XX:-UseBiasedLocking doesn't help
3. 6u21 with -XX:ParallelGCThreads=4 -XX:+UseParallelGC doesn't help
4. 6u21 with -Dsun.security.pkcs11.enable-solaris=false doesn't help
JDK 142_16 and 6u21
a. startup
b. process request (db query)
c. process db query results
d. output
Common options:
-server
-verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps
-XX:+PrintGCApplicationStoppedTime -XX:+PrintGCApplicationConcurrentTime
-XX:+PrintCompilation -XX:-BackgroundCompilation -Xbatch -XX:CICompilerCount=1
-XX:PermSize=256m -XX:MaxPermSize=256m
JDK 142_16 specific options:
-Xms256m -Xmx256m -Xrunhprof:cpu=samples
JDK 6u21 specific options:
-Xms1536m -Xmx1536m -agentlib:hprof=cpu=samples
Elapsed time for testcase execution
JDK 1.4.2_16 : 82
JDK 6u21 : 422
CPU sample hprof - big differences between 142_16 and 6u21
JDK 1.4.2_16
/cores_data/pool-1/data6/73055010/09Aug2010PrintCompHprof/JDK142_16_hprof_cpusamples.08_09_2010.22_26_15
CPU SAMPLES BEGIN (total = 3388) Mon Aug 9 22:27:38 2010
rank self accum count trace method
1 27.33% 27.33% 926 117 java.io.FileOutputStream.openAppend
2 15.05% 42.38% 510 112 java.nio.HeapByteBuffer.<init>
3 8.26% 50.65% 280 65 java.net.SocketInputStream.socketRead0
4 6.38% 57.02% 216 109 java.io.FileOutputStream.writeBytes
5 2.54% 59.56% 86 118 sun.nio.cs.StreamEncoder.forOutputStreamWriter
6 2.33% 61.89% 79 116 java.io.FileOutputStream.close0
7 1.95% 63.84% 66 114 java.nio.CharBuffer.allocate
8 1.42% 65.26% 48 110 sun.nio.cs.ISO_8859_1$Encoder.<init>
9 1.27% 66.53% 43 126 java.lang.StringBuffer.expandCapacity
10 1.15% 67.68% 39 167 java.io.FileWriter.<init>
11 1.03% 68.71% 35 127 sun.nio.cs.ISO_8859_1.newEncoder
12 1.03% 69.75% 35 145 java.lang.StringBuffer.expandCapacity
13 1.00% 70.75% 34 111 sun.nio.cs.ISO_8859_1.newDecoder
14 0.97% 71.72% 33 173 java.io.FileWriter.<init>
15 0.97% 72.70% 33 131 sun.nio.cs.StreamEncoder.write
JDK 6u21
/cores_data/pool-1/data6/73055010/09Aug2010PrintCompHprof/2_jdk6_hprof_cpusamples.08_09_2010.18_33_27
CPU SAMPLES BEGIN (total = 21132) Mon Aug 9 18:40:30 2010
rank self accum count trace method
1 11.27% 11.27% 2382 300852 java.lang.Integer.parseInt
2 10.56% 21.83% 2231 300761 java.lang.Object.<init>
3 6.97% 28.80% 1472 300756 java.io.FileOutputStream.openAppend
4 4.08% 32.88% 863 300766 java.io.FileOutputStream.writeBytes
5 2.82% 35.70% 596 300674 java.util.Arrays.copyOfRange
6 2.03% 37.72% 428 300884 com.verizon.common.services.svcAddrVal.components.irepmw.TLVMessage.retrieveField
7 2.00% 39.72% 422 300880 com.verizon.common.services.svcAddrVal.components.irepmw.TLVMessage.retrieveField
8 1.31% 41.03% 277 300663 java.net.SocketInputStream.socketRead0
9 1.13% 42.16% 238 300870 com.verizon.common.services.svcAddrVal.components.irepmw.TLVMessage.retrieveField
10 1.07% 43.23% 226 300934 com.verizon.common.services.svcAddrVal.components.irepmw.TLVMessage.retrieveField
11 1.06% 44.28% 223 300863 com.verizon.common.services.svcAddrVal.components.irepmw.TLVMessage.retrieveField
12 1.05% 45.33% 222 300905 com.verizon.common.services.svcAddrVal.components.irepmw.TLVMessage.retrieveField
13 1.05% 46.38% 221 300919 com.verizon.common.services.svcAddrVal.components.irepmw.TLVMessage.retrieveField
14 1.05% 47.43% 221 300930 com.verizon.common.services.svcAddrVal.components.irepmw.TLVMessage.retrieveField
15 1.05% 48.47% 221 300926 com.verizon.common.services.svcAddrVal.components.irepmw.TLVMessage.retrieveField
It seems a lot of time in 6u21 was spent in Integer.parseInt.
The Integer.parseInt method was noted to be compiled in both 142_16 and 6u21,
JDK 142_16
/cores_data/pool-1/data6/73055010/09Aug2010PrintCompHprof/JDK142_16_AddrOut.log
25 b java.lang.Integer::parseInt (269 bytes)
JDK 6u21
/cores_data/pool-1/data6/73055010/09Aug2010PrintCompHprof/2_AddrOut.log
84 b java.lang.Integer::parseInt (269 bytes)
The source code of
com.verizon.common.services.svcAddrVal.components.irepmw.TLVMessage.retrieveField
in /cores_data/pool-1/data6/73055010/09Aug2010/code.snippet
In addition, /cores_data/pool-1/data6/73055010/09Aug2010/log.diff showed
big differences in execution time around the area surrounding
Integer.parseInt from code.snippet (trace the message "returning Data ...")
GC statistics - total GC time rather insignificant, compared to the total execution time
JDK 142_16
what count total mean max stddev
gen1t(s) 2 0.267 0.13337 0.254 0.1703
GC(s) 2 0.267 0.13337 0.254 0.1703
used1b(MB) 2 165.672 82.83594 165.672 117.1477
used1a(MB) 2 10.280 5.14014 10.202 7.1588
used_b(MB) 2 248.618 124.30908 248.484 175.6104
used_a(MB) 2 10.280 5.14014 10.202 7.1588
safept_gc(s) 2 0.267 0.13373 0.254 0.1703
safept_gc_delta(s) 2 0.001 0.00036 0.000 0.0000
safept(s) 4554 9.513 0.00209 0.639 0.0339
apptime(s) 4554 73.547 0.01615 0.066 0.0099
alloc/elapsed_time = 0.000 MB / 82.931 s = 0.000 MB/s
alloc/tot_cpu_time = 0.000 MB / 82.931 s = 0.000 MB/s
alloc/mut_cpu_time = 0.000 MB / 82.664 s = 0.000 MB/s
promo/elapsed_time = 0.000 MB / 82.931 s = 0.000 MB/s
promo/gc0_time = 0.000 MB / 0.000 s = 0.000 MB/s
gc_seq_load = 0.267 s / 82.931 s = 0.322%
gc_conc_load = 0.000 s / 82.931 s = 0.000%
gc_tot_load = 0.267 s / 82.931 s = 0.322%
JDK 6u21
what count total mean max stddev
gen0t(s) 201 4.958 0.02467 0.282 0.0384
GC(s) 201 4.958 0.02467 0.282 0.0384
alloc(MB) 201 93648.118 465.91104 511.125 83.3421
promo(MB) 201 694.590 3.45567 90.465 14.1692
used0b(MB) 201 94576.668 470.53069 511.510 76.9097
used0a(MB) 201 928.919 4.62149 119.307 17.3632
used_b(MB) 201 228881.429 1138.71358 1206.095 147.5986
used_a(MB) 201 135928.270 676.26005 694.974 87.3069
commit0(MB) 201 97956.250 487.34453 511.562 48.1931
commit1(MB) 201 205824.000 1024.00000 1024.000 0.0000
commit(MB) 201 303780.250 1511.34453 1535.562 48.1931
safept_gc(s) 201 5.081 0.02528 0.283 0.0384
safept_gc_delta(s) 201 0.124 0.00062 0.001 0.0001
safept(s) 21271 20.520 0.00096 0.283 0.0044
apptime(s) 21272 401.338 0.01887 0.091 0.0024
alloc/elapsed_time = 93648.118 MB / 401.471 s = 233.262 MB/s
alloc/tot_cpu_time = 93648.118 MB / 401.471 s = 233.262 MB/s
alloc/mut_cpu_time = 93648.118 MB / 396.513 s = 236.179 MB/s
promo/elapsed_time = 694.590 MB / 401.471 s = 1.730 MB/s
promo/gc0_time = 694.590 MB / 4.958 s = 140.101 MB/s
gc_seq_load = 4.958 s / 401.471 s = 1.235%
gc_conc_load = 0.000 s / 401.471 s = 0.000%
gc_tot_load = 0.267 s / 82.931 s = 0.322%
Additional tests:
1. 6u21 with -XX:PerfDataSamplingInterval=500 - doesn't help
2. 6u21 with -XX:-UseBiasedLocking doesn't help
3. 6u21 with -XX:ParallelGCThreads=4 -XX:+UseParallelGC doesn't help
4. 6u21 with -Dsun.security.pkcs11.enable-solaris=false doesn't help