My test for G1,the result seems disappointed
BlueDavy Lin
bluedavy at gmail.com
Thu Sep 9 05:36:34 UTC 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