My test for G1,the result seems disappointed

BlueDavy Lin bluedavy at gmail.com
Wed Sep 8 22:36:34 PDT 2010


hi!

     Recently I did a test for G1 in on-site application,the env is:
     CPU: 5 core
     Memory: 7.5g
     OS: Redhat 5,kernel: 2.6.18, 64 bit
     JDK: 1.6.0_21 64 bit

     The test result shows:
     when use CMS,application stopped about 80ms every minute by
parnew gc,the avg response time about 113ms.
     when use G1 and set MaxGCPauseMillis=100,
GCPauseIntervalMillis=60000,full gc occurs about 2 every minute and
parallel gc occurs about 1 every minute,application stopped about
2850ms every minute,the avg response time slows down to 170ms.
     when use G1 and only set MaxGCPauseMillis=50,then no full gc,but
parallel gc executes about 45 every minute(about 40ms per parallel
gc),the avg response time slows down to 118ms.

      I hope the application stopped time cause by gc can de decreased
when use g1,but from this two tries for G1,it seems G1 not work
well,does I need adjust some other args?
      below is the more detail test infos.

     ==========CMS================
     The one use below startup args:
     -server -Xms4g -Xmx4g -XX:PermSize=96m -XX:MaxPermSize=256m
-Xmn2560m -XX:SurvivorRatio=10 -XX:+UseConcMarkSweepGC
--XX:CMSMaxAbortablePrecleanTime=5000 -XX:+CMSClassUnloadingEnabled
-XX:CMSInitiatingOccupancyFraction=80
-XX:+DisableExplicitGC-XX:+UseCompressedOops

      its gc log always like this:
      2010-09-09T11:26:04.102+0800: 5151.386: [GC 5151.386: [ParNew:
2195092K->9457K(2403008K), 0.0129360 secs]
2378366K->193170K(3975872K), 0.0131550 secs] [Times: user=0.02
sys=0.00, real=0.01 secs]
2010-09-09T11:26:14.541+0800: 5161.825: [GC 5161.825: [ParNew:
2194033K->7772K(2403008K), 0.0095720 secs]
2377746K->191506K(3975872K), 0.0097820 secs] [Times: user=0.02
sys=0.00, real=0.01 secs]
2010-09-09T11:26:26.636+0800: 5173.920: [GC 5173.920: [ParNew:
2192348K->8644K(2403008K), 0.0133990 secs]
2376082K->192395K(3975872K), 0.0135990 secs] [Times: user=0.03
sys=0.00, real=0.02 secs]
2010-09-09T11:26:36.498+0800: 5183.782: [GC 5183.782: [ParNew:
2193220K->9069K(2403008K), 0.0122710 secs]
2376971K->192841K(3975872K), 0.0124720 secs] [Times: user=0.03
sys=0.00, real=0.01 secs]
2010-09-09T11:26:45.935+0800: 5193.219: [GC 5193.219: [ParNew:
2193645K->10580K(2403008K), 0.0118440 secs]
2377417K->194372K(3975872K), 0.0120420 secs] [Times: user=0.03
sys=0.00, real=0.01 secs]
2010-09-09T11:26:54.682+0800: 5201.965: [GC 5201.965: [ParNew:
2195156K->13065K(2403008K), 0.0124290 secs]
2378948K->196935K(3975872K), 0.0126630 secs] [Times: user=0.03
sys=0.00, real=0.01 secs]

      System response time is about: 113ms.

      ==========G1 First try============

      From this result,we can see application stopped about 80ms every
minute by parnew gc.

      So I first set the goal:every minute max gc pause 100ms for
G1,use below startup args:
      -server -Xms4g -Xmx4g -XX:PermSize=96m -XX:MaxPermSize=256m
-XX:+UnlockExperimentalVMOptions -XX:+UseG1GC -XX:MaxGCPauseMillis=100
-XX:GCPauseIntervalMillis=60000 -XX:+DisableExplicitGC

      its gc log always like this:
      2010-09-09T13:10:00.361+0800: 174.381: [GC pause (young), 0.08201400 secs]
   [Parallel Time:  63.6 ms]
      [Update RS (Start) (ms):  174409.8  174414.8  174407.7  174409.8]
      [Update RS (ms):  2.8  0.0  5.3  2.8
       Avg:   2.7, Min:   0.0, Max:   5.3]
         [Processed Buffers : 24 0 48 57
          Sum: 129, Avg: 32, Min: 0, Max: 57]
      [Ext Root Scanning (ms):  20.5  24.5  18.4  20.5
       Avg:  21.0, Min:  18.4, Max:  24.5]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  2.4  0.3  2.0  2.3
       Avg:   1.7, Min:   0.3, Max:   2.4]
      [Object Copy (ms):  37.4  38.3  37.4  37.4
       Avg:  37.6, Min:  37.4, Max:  38.3]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Other:   0.5 ms]
   [Clear CT:   1.1 ms]
   [Other:  17.4 ms]
   [ 3311M->142M(4096M)]
 [Times: user=0.25 sys=0.00, real=0.08 secs]
2010-09-09T13:10:21.523+0800: 195.543: [Full GC 4046M->134M(4096M),
1.4183880 secs]
 [Times: user=1.55 sys=0.00, real=1.42 secs]
2010-09-09T13:10:40.664+0800: 214.684: [Full GC 4037M->134M(4096M),
1.3687460 secs]
 [Times: user=1.56 sys=0.00, real=1.37 secs]
2010-09-09T13:10:58.700+0800: 232.721: [GC pause (young), 0.06309300 secs]
   [Parallel Time:  44.2 ms]
      [Update RS (Start) (ms):  232753.3  232749.4  232750.4  232750.4]
      [Update RS (ms):  0.0  4.1  2.9  3.0
       Avg:   2.5, Min:   0.0, Max:   4.1]
         [Processed Buffers : 1 40 57 40
          Sum: 138, Avg: 34, Min: 1, Max: 57]
      [Ext Root Scanning (ms):  22.9  19.9  21.0  20.8
       Avg:  21.1, Min:  19.9, Max:  22.9]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  2.0  1.7  1.9  1.9
       Avg:   1.9, Min:   1.7, Max:   2.0]
      [Object Copy (ms):  19.0  18.1  18.0  18.1
       Avg:  18.3, Min:  18.0, Max:  19.0]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Other:   0.4 ms]
   [Clear CT:   0.7 ms]
   [Other:  18.2 ms]
   [ 3615M->141M(4096M)]
 [Times: user=0.16 sys=0.01, real=0.07 secs]
2010-09-09T13:11:18.905+0800: 252.926: [Full GC 4036M->134M(4096M),
1.4136770 secs]
 [Times: user=1.58 sys=0.00, real=1.41 secs]
2010-09-09T13:11:38.433+0800: 272.453: [Full GC 4044M->135M(4096M),
1.3858410 secs]
 [Times: user=1.56 sys=0.00, real=1.38 secs]
2010-09-09T13:11:58.365+0800: 292.385: [GC pause (young), 0.08650100 secs]
   [Parallel Time:  64.7 ms]
      [Update RS (Start) (ms):  292417.1  292414.8  292414.3  292420.5]
      [Update RS (ms):  1.7  4.2  4.5  0.0
       Avg:   2.6, Min:   0.0, Max:   4.5]
         [Processed Buffers : 31 49 69 0
          Sum: 149, Avg: 37, Min: 0, Max: 69]
      [Ext Root Scanning (ms):  22.2  20.0  19.5  24.7
       Avg:  21.6, Min:  19.5, Max:  24.7]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  2.5  2.2  2.4  0.8
       Avg:   2.0, Min:   0.8, Max:   2.5]
      [Object Copy (ms):  38.0  37.8  37.8  38.8
       Avg:  38.1, Min:  37.8, Max:  38.8]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Other:   0.5 ms]
   [Clear CT:   1.0 ms]
   [Other:  20.8 ms]
   [ 3946M->143M(4096M)]
 [Times: user=0.27 sys=0.00, real=0.09 secs]
2010-09-09T13:12:18.393+0800: 312.414: [Full GC 4045M->136M(4096M),
1.4378720 secs]
 [Times: user=1.63 sys=0.00, real=1.43 secs]
2010-09-09T13:12:39.868+0800: 333.889: [Full GC 4048M->137M(4096M),
1.3862310 secs]
 [Times: user=1.57 sys=0.00, real=1.38 secs]
2010-09-09T13:12:57.555+0800: 351.576: [GC pause (young), 0.07091500 secs]
   [Parallel Time:  48.1 ms]
      [Update RS (Start) (ms):  351612.2  351607.3  351610.8  351608.4]
      [Update RS (ms):  0.0  4.8  1.2  3.5
       Avg:   2.4, Min:   0.0, Max:   4.8]
         [Processed Buffers : 0 55 17 69
          Sum: 141, Avg: 35, Min: 0, Max: 69]
      [Ext Root Scanning (ms):  26.1  21.4  24.7  21.7
       Avg:  23.5, Min:  21.4, Max:  26.1]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  1.8  1.8  2.1  2.0
       Avg:   1.9, Min:   1.8, Max:   2.1]
      [Object Copy (ms):  19.7  19.5  19.7  20.3
       Avg:  19.8, Min:  19.5, Max:  20.3]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Other:   0.5 ms]
   [Clear CT:   1.8 ms]
   [Other:  21.0 ms]
   [ 3697M->144M(4096M)]
 [Times: user=0.19 sys=0.00, real=0.07 secs]

      System response time slows down to 170ms.

       I even if try to set  -XX:MaxGCPauseMillis=1000,but the result
still like above.

      From the above test result,G1 seems not work well,then I adjust the args.

     ==========G1 Second try============

     use below startup args to test:
     -server -Xms4g -Xmx4g -XX:PermSize=96m -XX:MaxPermSize=256m
-XX:+UnlockExperimentalVMOptions -XX:+UseG1GC -XX:MaxGCPauseMillis=50
-XX:+DisableExplicitGC

     its gc log always like this:
     2010-09-09T13:24:02.078+0800: 113.627: [GC pause (young), 0.04145200 secs]
   [Parallel Time:  39.2 ms]
      [Update RS (Start) (ms):  113636.9  113634.5  113634.2  113634.4]
      [Update RS (ms):  2.3  4.7  5.0  4.8
       Avg:   4.2, Min:   2.3, Max:   5.0]
         [Processed Buffers : 14 41 36 24
          Sum: 115, Avg: 28, Min: 14, Max: 41]
      [Ext Root Scanning (ms):  8.4  5.5  5.8  6.1
       Avg:   6.5, Min:   5.5, Max:   8.4]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  0.3  0.1  0.1  0.1
       Avg:   0.1, Min:   0.1, Max:   0.3]
      [Object Copy (ms):  27.7  28.2  27.6  27.6
       Avg:  27.8, Min:  27.6, Max:  28.2]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Other:   0.6 ms]
   [Clear CT:   0.2 ms]
   [Other:   2.1 ms]
   [ 650M->310M(4096M)]
 [Times: user=0.13 sys=0.00, real=0.04 secs]
2010-09-09T13:24:03.411+0800: 114.960: [GC pause (young), 0.03899600 secs]
   [Parallel Time:  36.8 ms]
      [Update RS (Start) (ms):  114967.1  114967.1  114966.7  114969.4]
      [Update RS (ms):  3.8  3.8  4.2  1.5
       Avg:   3.3, Min:   1.5, Max:   4.2]
         [Processed Buffers : 19 21 57 15
          Sum: 112, Avg: 28, Min: 15, Max: 57]
      [Ext Root Scanning (ms):  6.1  5.4  5.7  8.2
       Avg:   6.4, Min:   5.4, Max:   8.2]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  0.1  0.0  0.1  0.3
       Avg:   0.1, Min:   0.0, Max:   0.3]
      [Object Copy (ms):  26.6  27.2  26.5  26.6
       Avg:  26.7, Min:  26.5, Max:  27.2]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Other:   0.3 ms]
   [Clear CT:   0.2 ms]
   [Other:   2.0 ms]
   [ 650M->309M(4096M)]
 [Times: user=0.11 sys=0.00, real=0.04 secs]
2010-09-09T13:24:05.167+0800: 116.716: [GC pause (young), 0.04297900 secs]
   [Parallel Time:  40.6 ms]
      [Update RS (Start) (ms):  116723.5  116724.2  116723.3  116725.5]
      [Update RS (ms):  4.4  3.8  4.7  2.5
       Avg:   3.8, Min:   2.5, Max:   4.7]
         [Processed Buffers : 20 41 17 29
          Sum: 107, Avg: 26, Min: 17, Max: 41]
      [Ext Root Scanning (ms):  5.6  6.9  6.1  8.1
       Avg:   6.7, Min:   5.6, Max:   8.1]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  0.1  0.1  0.1  0.2
       Avg:   0.1, Min:   0.1, Max:   0.2]
      [Object Copy (ms):  30.1  29.4  29.4  29.5
       Avg:  29.6, Min:  29.4, Max:  30.1]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Other:   0.4 ms]
   [Clear CT:   0.3 ms]
   [Other:   2.1 ms]
   [ 662M->310M(4096M)]
 [Times: user=0.16 sys=0.00, real=0.04 secs]



Disabling Explicit GC


2010-09-09T13:24:06.506+0800: 118.055: [GC pause (young), 0.04068000 secs]
   [Parallel Time:  38.4 ms]
      [Update RS (Start) (ms):  118066.3  118065.8  118065.1  118063.3]
      [Update RS (ms):  3.0  3.6  4.2  6.1
       Avg:   4.2, Min:   3.0, Max:   6.1]
         [Processed Buffers : 20 31 31 37
          Sum: 119, Avg: 29, Min: 20, Max: 37]
      [Ext Root Scanning (ms):  10.0  8.5  8.7  0.1
       Avg:   6.8, Min:   0.1, Max:  10.0]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  0.2  0.1  0.1  0.1
       Avg:   0.1, Min:   0.1, Max:   0.2]
      [Object Copy (ms):  25.1  26.0  25.1  24.4
       Avg:  25.1, Min:  24.4, Max:  26.0]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Other:   2.2 ms]
   [Clear CT:   0.3 ms]
   [Other:   2.0 ms]
   [ 634M->311M(4096M)]
 [Times: user=0.12 sys=0.01, real=0.05 secs]
2010-09-09T13:24:08.787+0800: 120.336: [GC pause (young), 0.04042800 secs]
   [Parallel Time:  38.0 ms]
      [Update RS (Start) (ms):  120346.4  120344.4  120344.2  120344.4]
      [Update RS (ms):  3.0  4.9  5.1  5.0
       Avg:   4.5, Min:   3.0, Max:   5.1]
         [Processed Buffers : 36 37 26 32
          Sum: 131, Avg: 32, Min: 26, Max: 37]
      [Ext Root Scanning (ms):  9.0  7.0  5.9  7.0
       Avg:   7.2, Min:   5.9, Max:   9.0]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  0.2  0.1  0.1  0.1
       Avg:   0.1, Min:   0.1, Max:   0.2]
      [Object Copy (ms):  25.4  25.3  26.2  25.3
       Avg:  25.6, Min:  25.3, Max:  26.2]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Other:   0.6 ms]
   [Clear CT:   0.3 ms]
   [Other:   2.2 ms]
   [ 651M->310M(4096M)]
 [Times: user=0.12 sys=0.01, real=0.04 secs]
2010-09-09T13:24:10.686+0800: 122.235: [GC pause (young), 0.03933000 secs]
   [Parallel Time:  37.0 ms]
      [Update RS (Start) (ms):  122242.6  122242.2  122243.2  122245.1]
      [Update RS (ms):  5.0  5.4  4.4  2.5
       Avg:   4.3, Min:   2.5, Max:   5.4]
         [Processed Buffers : 25 23 36 16
          Sum: 100, Avg: 25, Min: 16, Max: 36]
      [Ext Root Scanning (ms):  6.2  5.9  6.1  8.6
       Avg:   6.7, Min:   5.9, Max:   8.6]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  0.1  0.0  0.2  0.3
       Avg:   0.1, Min:   0.0, Max:   0.3]
      [Object Copy (ms):  25.2  25.1  25.8  25.3
       Avg:  25.4, Min:  25.1, Max:  25.8]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Other:   0.5 ms]
   [Clear CT:   0.1 ms]
   [Other:   2.2 ms]
   [ 686M->311M(4096M)]
 [Times: user=0.13 sys=0.00, real=0.04 secs]
2010-09-09T13:24:12.074+0800: 123.623: [GC pause (young), 0.04201300 secs]
   [Parallel Time:  39.6 ms]
      [Update RS (Start) (ms):  123633.2  123630.1  123630.1  123630.4]
      [Update RS (ms):  1.7  4.8  4.8  4.4
       Avg:   3.9, Min:   1.7, Max:   4.8]
         [Processed Buffers : 25 36 22 35
          Sum: 118, Avg: 29, Min: 22, Max: 36]
      [Ext Root Scanning (ms):  8.8  5.9  6.0  5.5
       Avg:   6.5, Min:   5.5, Max:   8.8]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  0.3  0.1  0.1  0.1
       Avg:   0.1, Min:   0.1, Max:   0.3]
      [Object Copy (ms):  28.5  28.3  28.2  28.9
       Avg:  28.5, Min:  28.2, Max:  28.9]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Other:   0.6 ms]
   [Clear CT:   0.3 ms]
   [Other:   2.1 ms]
   [ 687M->312M(4096M)]
 [Times: user=0.14 sys=0.00, real=0.05 secs]
2010-09-09T13:24:14.181+0800: 125.730: [GC pause (young), 0.04815900 secs]
   [Parallel Time:  45.8 ms]
      [Update RS (Start) (ms):  125736.9  125737.7  125737.1  125739.5]
      [Update RS (ms):  5.5  4.7  5.3  2.9
       Avg:   4.6, Min:   2.9, Max:   5.5]
         [Processed Buffers : 34 22 34 31
          Sum: 121, Avg: 30, Min: 22, Max: 34]
      [Ext Root Scanning (ms):  5.9  6.8  5.5  8.4
       Avg:   6.7, Min:   5.5, Max:   8.4]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  0.1  0.1  0.1  0.3
       Avg:   0.1, Min:   0.1, Max:   0.3]
      [Object Copy (ms):  33.6  33.6  34.2  33.7
       Avg:  33.8, Min:  33.6, Max:  34.2]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Other:   0.6 ms]
   [Clear CT:   0.2 ms]
   [Other:   2.1 ms]
   [ 661M->314M(4096M)]
 [Times: user=0.18 sys=0.00, real=0.05 secs]
2010-09-09T13:24:14.966+0800: 126.514: [GC pause (young), 0.04331000 secs]
   [Parallel Time:  42.1 ms]
      [Update RS (Start) (ms):  126521.9  126521.9  126522.3  126523.7]
      [Update RS (ms):  3.4  3.4  3.1  1.6
       Avg:   2.9, Min:   1.6, Max:   3.4]
         [Processed Buffers : 11 17 13 22
          Sum: 63, Avg: 15, Min: 11, Max: 22]
      [Ext Root Scanning (ms):  6.4  5.8  6.7  8.0
       Avg:   6.7, Min:   5.8, Max:   8.0]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  0.0  0.0  0.0  0.2
       Avg:   0.1, Min:   0.0, Max:   0.2]
      [Object Copy (ms):  31.7  32.3  31.7  31.8
       Avg:  31.9, Min:  31.7, Max:  32.3]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Other:   0.5 ms]
   [Clear CT:   0.1 ms]
   [Other:   1.1 ms]
   [ 495M->314M(4096M)]
 [Times: user=0.17 sys=0.00, real=0.05 secs]
2010-09-09T13:24:15.796+0800: 127.345: [GC pause (young), 0.04752200 secs]
   [Parallel Time:  45.9 ms]
      [Update RS (Start) (ms):  127354.5  127354.9  127352.2  127352.7]
      [Update RS (ms):  2.5  2.1  4.8  4.3
       Avg:   3.4, Min:   2.1, Max:   4.8]
         [Processed Buffers : 13 21 22 30
          Sum: 86, Avg: 21, Min: 13, Max: 30]
      [Ext Root Scanning (ms):  7.4  9.0  6.3  5.3
       Avg:   7.0, Min:   5.3, Max:   9.0]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  0.1  0.2  0.0  0.0
       Avg:   0.1, Min:   0.0, Max:   0.2]
      [Object Copy (ms):  35.6  34.4  34.2  34.1
       Avg:  34.6, Min:  34.1, Max:  35.6]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Other:   0.8 ms]
   [Clear CT:   0.5 ms]
   [Other:   1.2 ms]
   [ 495M->315M(4096M)]
 [Times: user=0.16 sys=0.00, real=0.04 secs]
2010-09-09T13:24:16.482+0800: 128.030: [GC pause (young), 0.04810400 secs]
   [Parallel Time:  47.2 ms]
      [Update RS (Start) (ms):  128042.6  128041.2  128043.8  128042.1]
      [Update RS (ms):  2.9  4.4  1.8  3.5
       Avg:   3.2, Min:   1.8, Max:   4.4]
         [Processed Buffers : 21 11 16 13
          Sum: 61, Avg: 15, Min: 11, Max: 21]
      [Ext Root Scanning (ms):  11.0  9.0  12.5  10.6
       Avg:  10.8, Min:   9.0, Max:  12.5]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  0.1  0.0  0.1  0.0
       Avg:   0.0, Min:   0.0, Max:   0.1]
      [Object Copy (ms):  32.9  33.3  32.5  32.3
       Avg:  32.7, Min:  32.3, Max:  33.3]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Other:   0.4 ms]
   [Clear CT:   0.2 ms]
   [Other:   0.8 ms]
   [ 424M->313M(4096M)]
 [Times: user=0.15 sys=0.00, real=0.05 secs]
2010-09-09T13:24:17.117+0800: 128.665: [GC pause (young), 0.04878500 secs]
   [Parallel Time:  47.4 ms]
      [Update RS (Start) (ms):  128675.2  128677.3  128674.6  128675.1]
      [Update RS (ms):  3.8  1.7  4.4  3.9
       Avg:   3.4, Min:   1.7, Max:   4.4]
         [Processed Buffers : 13 30 34 19
          Sum: 96, Avg: 24, Min: 13, Max: 34]
      [Ext Root Scanning (ms):  8.7  10.7  7.1  3.8
       Avg:   7.6, Min:   3.8, Max:  10.7]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  0.1  0.2  0.0  0.0
       Avg:   0.1, Min:   0.0, Max:   0.2]
      [Object Copy (ms):  34.2  34.2  35.0  33.7
       Avg:  34.3, Min:  33.7, Max:  35.0]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Other:   2.0 ms]
   [Clear CT:   0.2 ms]
   [Other:   1.2 ms]
   [ 500M->314M(4096M)]
 [Times: user=0.16 sys=0.01, real=0.05 secs]
2010-09-09T13:24:17.624+0800: 129.173: [GC pause (young), 0.04827900 secs]
   [Parallel Time:  47.2 ms]
      [Update RS (Start) (ms):  129182.1  129182.7  129182.1  129180.8]
      [Update RS (ms):  2.4  1.8  2.4  3.7
       Avg:   2.6, Min:   1.8, Max:   3.7]
         [Processed Buffers : 14 20 12 14
          Sum: 60, Avg: 15, Min: 12, Max: 20]
      [Ext Root Scanning (ms):  8.3  8.9  7.4  5.3
       Avg:   7.5, Min:   5.3, Max:   8.9]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  0.1  0.1  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.1]
      [Object Copy (ms):  35.8  35.8  36.7  35.4
       Avg:  35.9, Min:  35.4, Max:  36.7]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Other:   1.1 ms]
   [Clear CT:   0.2 ms]
   [Other:   0.9 ms]
   [ 436M->315M(4096M)]
 [Times: user=0.17 sys=0.00, real=0.04 secs]
2010-09-09T13:24:18.295+0800: 129.843: [GC pause (young), 0.04680800 secs]
   [Parallel Time:  45.8 ms]
      [Update RS (Start) (ms):  129853.1  129852.9  129853.4  129852.4]
      [Update RS (ms):  2.6  2.7  2.2  3.3
       Avg:   2.7, Min:   2.2, Max:   3.3]
         [Processed Buffers : 17 15 18 8
          Sum: 58, Avg: 14, Min: 8, Max: 18]
      [Ext Root Scanning (ms):  8.6  8.5  8.2  0.0
       Avg:   6.3, Min:   0.0, Max:   8.6]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  0.1  0.0  0.1  0.0
       Avg:   0.0, Min:   0.0, Max:   0.1]
      [Object Copy (ms):  34.1  34.1  34.7  33.4
       Avg:  34.1, Min:  33.4, Max:  34.7]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Other:   2.7 ms]
   [Clear CT:   0.1 ms]
   [Other:   0.8 ms]
   [ 437M->314M(4096M)]
 [Times: user=0.15 sys=0.00, real=0.04 secs]
2010-09-09T13:24:19.062+0800: 130.611: [GC pause (young), 0.04281800 secs]
   [Parallel Time:  41.9 ms]
      [Update RS (Start) (ms):  130618.4  130620.4  130620.3  130620.3]
      [Update RS (ms):  4.4  2.4  2.5  2.4
       Avg:   2.9, Min:   2.4, Max:   4.4]
         [Processed Buffers : 19 14 18 12
          Sum: 63, Avg: 15, Min: 12, Max: 19]
      [Ext Root Scanning (ms):  5.9  8.6  8.5  8.5
       Avg:   7.9, Min:   5.9, Max:   8.6]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  0.0  0.0  0.1  0.1
       Avg:   0.0, Min:   0.0, Max:   0.1]
      [Object Copy (ms):  30.8  30.1  30.0  30.1
       Avg:  30.2, Min:  30.0, Max:  30.8]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Other:   0.8 ms]
   [Clear CT:   0.1 ms]
   [Other:   0.8 ms]
   [ 431M->314M(4096M)]
 [Times: user=0.15 sys=0.00, real=0.05 secs]
2010-09-09T13:24:20.416+0800: 131.965: [GC pause (young), 0.04591200 secs]
   [Parallel Time:  43.6 ms]
      [Update RS (Start) (ms):  131972.9  131972.7  131975.2  131972.6]
      [Update RS (ms):  4.2  4.5  1.9  4.5
       Avg:   3.8, Min:   1.9, Max:   4.5]
         [Processed Buffers : 18 24 23 26
          Sum: 91, Avg: 22, Min: 18, Max: 26]
      [Ext Root Scanning (ms):  6.5  6.2  8.6  5.5
       Avg:   6.7, Min:   5.5, Max:   8.6]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  0.1  0.1  0.2  0.1
       Avg:   0.1, Min:   0.1, Max:   0.2]
      [Object Copy (ms):  32.5  32.5  32.7  33.2
       Avg:  32.7, Min:  32.5, Max:  33.2]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Other:   0.3 ms]
   [Clear CT:   0.3 ms]
   [Other:   2.0 ms]
   [ 635M->314M(4096M)]
 [Times: user=0.15 sys=0.00, real=0.05 secs]
2010-09-09T13:24:20.948+0800: 132.497: [GC pause (young), 0.03678800 secs]
   [Parallel Time:  35.6 ms]
      [Update RS (Start) (ms):  132506.5  132504.1  132504.4  132504.1]
      [Update RS (ms):  0.9  3.3  3.0  3.3
       Avg:   2.6, Min:   0.9, Max:   3.3]
         [Processed Buffers : 12 20 15 16
          Sum: 63, Avg: 15, Min: 12, Max: 20]
      [Ext Root Scanning (ms):  8.7  5.8  6.6  6.3
       Avg:   6.8, Min:   5.8, Max:   8.7]
      [Mark Stack Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Scan-Only Scanning (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
         [Scan-Only Regions : 0 0 0 0
          Sum: 0, Avg: 0, Min: 0, Max: 0]
      [Scan RS (ms):  0.1  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.1]
      [Object Copy (ms):  25.8  26.1  25.7  25.7
       Avg:  25.8, Min:  25.7, Max:  26.1]
      [Termination (ms):  0.0  0.0  0.0  0.0
       Avg:   0.0, Min:   0.0, Max:   0.0]
      [Other:   0.3 ms]
   [Clear CT:   0.1 ms]
   [Other:   1.1 ms]
   [ 423M->314M(4096M)]
 [Times: user=0.13 sys=0.01, real=0.04 secs]

     System response time slows down to 118ms.

-- 
=============================
bluedavy http://www.bluedavy.com
=============================


More information about the hotspot-gc-dev mailing list