Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-6975830

Performance degradation in JDK6 compare to JDK142

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Not an Issue
    • Icon: P2 P2
    • None
    • 6u21
    • hotspot
    • sparc
    • solaris_10

      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

            dmeetry Dmeetry Degrave (Inactive)
            lkchow Lawrence Chow
            Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

              Created:
              Updated:
              Resolved:
              Imported:
              Indexed: