Runtime.getRuntime().freeMemory() can report wrong values when collector is CMS?
ahmet mırçık
ahmetmircik at gmail.com
Wed Jun 22 10:42:31 UTC 2016
As Jon requested, adding whole logs of run with -XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
0.387: [GC0.387: [ParNew: 1908416K->1478K(2146944K), 0.1184640 secs]
1908416K->1478K(62676032K), 0.1186650 secs] [Times: user=1.46
sys=0.06, real=0.12 secs] 2.044: [GC2.044: [ParNew:
1909894K->238528K(2146944K), 1.0219420 secs]
1909894K->990306K(62676032K), 1.0221530 secs] [Times: user=3.43
sys=0.65, real=1.03 secs]
5.371: [GC5.371: [ParNew: 2146944K->238528K(2146944K), 0.7925770 secs]
2898722K->2563370K(62676032K), 0.7928370 secs] [Times: user=3.91
sys=0.92, real=0.79 secs]
6.212: [GC [1 CMS-initial-mark: 2324842K(60529088K)]
2970151K(62676032K), 0.0798090 secs] [Times: user=0.07 sys=0.01,
real=0.08 secs]
6.292: [CMS-concurrent-mark-start]
6.409: [CMS-concurrent-mark: 0.117/0.117 secs] [Times: user=1.11
sys=0.03, real=0.12 secs]
6.409: [CMS-concurrent-preclean-start]
6.488: [CMS-concurrent-preclean: 0.079/0.079 secs] [Times: user=0.30
sys=0.01, real=0.08 secs]
6.488: [CMS-concurrent-abortable-preclean-start]
8.608: [GC8.608: [ParNew: 2146944K->238528K(2146944K), 0.6036620 secs]
4471786K->4179773K(62676032K), 0.6038550 secs] [Times: user=4.74
sys=0.85, real=0.60 secs]
10.330: [CMS-concurrent-abortable-preclean: 2.932/3.842 secs] [Times:
user=18.73 sys=0.98, real=3.84 secs]
10.331: [GC[YG occupancy: 1202595 K (2146944 K)]10.331: [Rescan
(parallel) , 0.1014670 secs]10.432: [weak refs processing, 0.0000220
secs]10.432: [scrub string table, 0.0001390 secs] [1 CMS-remark:
3941245K(60529088K)] 5143841K(62676032K), 0.1017860 secs] [Times:
user=2.01 sys=0.01, real=0.10 secs]
10.432: [CMS-concurrent-sweep-start]
10.855: [CMS-concurrent-sweep: 0.423/0.423 secs] [Times: user=1.83
sys=0.02, real=0.43 secs]
10.856: [CMS-concurrent-reset-start]
11.225: [CMS-concurrent-reset: 0.369/0.369 secs] [Times: user=1.41
sys=0.33, real=0.37 secs]
12.042: [GC12.042: [ParNew: 2146944K->238528K(2146944K), 0.5858140
secs] 6084759K->5903972K(62676032K), 0.5859810 secs] [Times: user=4.58
sys=0.84, real=0.59 secs]
12.638: [GC [1 CMS-initial-mark: 5665444K(60529088K)]
5979114K(62676032K), 0.0419200 secs] [Times: user=0.04 sys=0.00,
real=0.04 secs]
12.680: [CMS-concurrent-mark-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=660M, runtime.usedMemory=60546M,
runTime.availableMemory=660M, freeHeapPercentage=1.08
13.083: [CMS-concurrent-mark: 0.393/0.403 secs] [Times: user=4.16
sys=0.05, real=0.40 secs]
13.083: [CMS-concurrent-preclean-start]
13.221: [CMS-concurrent-preclean: 0.135/0.138 secs] [Times: user=0.74
sys=0.00, real=0.14 secs]
13.221: [CMS-concurrent-abortable-preclean-start]
15.433: [GC15.433: [ParNew: 2146944K->238528K(2146944K), 0.6007190
secs] 7812388K->7683258K(62676032K), 0.6008890 secs] [Times: user=5.73
sys=0.89, real=0.60 secs]
17.907: [CMS-concurrent-abortable-preclean: 3.832/4.686 secs] [Times:
user=27.47 sys=0.99, real=4.69 secs]
17.907: [GC[YG occupancy: 1343364 K (2146944 K)]17.907: [Rescan
(parallel) , 0.0650330 secs]17.972: [weak refs processing, 0.0000260
secs]17.972: [scrub string table, 0.0001410 secs] [1 CMS-remark:
7444730K(60529088K)] 8788094K(62676032K), 0.0653380 secs] [Times:
user=1.14 sys=0.01, real=0.06 secs]
17.973: [CMS-concurrent-sweep-start]
18.748: [CMS-concurrent-sweep: 0.775/0.775 secs] [Times: user=3.85
sys=0.03, real=0.78 secs]
18.748: [CMS-concurrent-reset-start]
18.870: [CMS-concurrent-reset: 0.122/0.122 secs] [Times: user=0.57
sys=0.00, real=0.12 secs]
19.489: [GC19.489: [ParNew: 2146944K->238528K(2146944K), 0.6780350
secs] 9577677K->9505999K(62676032K), 0.6781850 secs] [Times: user=7.28
sys=0.93, real=0.68 secs]
20.188: [GC [1 CMS-initial-mark: 9267471K(60529088K)]
9620491K(62676032K), 0.0422140 secs] [Times: user=0.05 sys=0.00,
real=0.04 secs]
20.230: [CMS-concurrent-mark-start]
21.059: [CMS-concurrent-mark: 0.829/0.829 secs] [Times: user=8.05
sys=0.13, real=0.83 secs]
21.059: [CMS-concurrent-preclean-start]
21.253: [CMS-concurrent-preclean: 0.188/0.194 secs] [Times: user=0.94
sys=0.00, real=0.19 secs]
21.253: [CMS-concurrent-abortable-preclean-start]
23.664: [GC23.664: [ParNew: 2146944K->238528K(2146944K), 0.6295930
secs] 11414415K->11354247K(62676032K), 0.6297570 secs] [Times:
user=9.36 sys=1.17, real=0.63 secs]
26.011: [CMS-concurrent-abortable-preclean: 3.811/4.757 secs] [Times:
user=30.09 sys=1.26, real=4.76 secs]
26.011: [GC[YG occupancy: 1231128 K (2146944 K)]26.011: [Rescan
(parallel) , 0.0362050 secs]26.047: [weak refs processing, 0.0000230
secs]26.047: [scrub string table, 0.0001350 secs] [1 CMS-remark:
11115719K(60529088K)] 12346847K(62676032K), 0.0365120 secs] [Times:
user=0.72 sys=0.01, real=0.04 secs]
26.048: [CMS-concurrent-sweep-start]
27.247: [CMS-concurrent-sweep: 1.199/1.199 secs] [Times: user=5.95
sys=0.02, real=1.20 secs]
27.247: [CMS-concurrent-reset-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=404M, runtime.usedMemory=60802M,
runTime.availableMemory=404M, freeHeapPercentage=0.66
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=404M, runtime.usedMemory=60802M,
runTime.availableMemory=404M, freeHeapPercentage=0.66
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=404M, runtime.usedMemory=60802M,
runTime.availableMemory=404M, freeHeapPercentage=0.66
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=404M, runtime.usedMemory=60802M,
runTime.availableMemory=404M, freeHeapPercentage=0.66
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=404M, runtime.usedMemory=60802M,
runTime.availableMemory=404M, freeHeapPercentage=0.66
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=404M, runtime.usedMemory=60802M,
runTime.availableMemory=404M, freeHeapPercentage=0.66
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=404M, runtime.usedMemory=60802M,
runTime.availableMemory=404M, freeHeapPercentage=0.66
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=404M, runtime.usedMemory=60802M,
runTime.availableMemory=404M, freeHeapPercentage=0.66
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=404M, runtime.usedMemory=60802M,
runTime.availableMemory=404M, freeHeapPercentage=0.66
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=404M, runtime.usedMemory=60802M,
runTime.availableMemory=404M, freeHeapPercentage=0.66
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=404M, runtime.usedMemory=60802M,
runTime.availableMemory=404M, freeHeapPercentage=0.66
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=404M, runtime.usedMemory=60802M,
runTime.availableMemory=404M, freeHeapPercentage=0.66
27.370: [CMS-concurrent-reset: 0.123/0.123 secs] [Times: user=0.59
sys=0.00, real=0.12 secs]
27.781: [GC27.781: [ParNew: 2146944K->238528K(2146944K), 0.7943920
secs] 13143349K->13102932K(62676032K), 0.7945470 secs] [Times:
user=6.38 sys=0.84, real=0.80 secs]
28.582: [GC [1 CMS-initial-mark: 12864404K(60529088K)]
13127809K(62676032K), 0.0449620 secs] [Times: user=0.05 sys=0.00,
real=0.05 secs]
28.627: [CMS-concurrent-mark-start]
29.683: [CMS-concurrent-mark: 1.055/1.055 secs] [Times: user=11.21
sys=0.10, real=1.05 secs]
29.683: [CMS-concurrent-preclean-start]
29.898: [CMS-concurrent-preclean: 0.209/0.215 secs] [Times: user=1.33
sys=0.01, real=0.22 secs]
29.898: [CMS-concurrent-abortable-preclean-start]
31.486: [GC31.486: [ParNew: 2146944K->238528K(2146944K), 0.6539690
secs] 15011348K->14984067K(62676032K), 0.6541020 secs] [Times:
user=6.12 sys=0.95, real=0.65 secs]
34.126: [CMS-concurrent-abortable-preclean: 3.350/4.228 secs] [Times:
user=25.87 sys=1.04, real=4.23 secs]
34.126: [GC[YG occupancy: 1561671 K (2146944 K)]34.126: [Rescan
(parallel) , 0.0510120 secs]34.177: [weak refs processing, 0.0000230
secs]34.177: [scrub string table, 0.0001370 secs] [1 CMS-remark:
14745539K(60529088K)] 16307210K(62676032K), 0.0513170 secs] [Times:
user=0.78 sys=0.00, real=0.05 secs]
34.177: [CMS-concurrent-sweep-start]
35.280: [GC35.280: [ParNew: 2146944K->238528K(2146944K), 0.5963010
secs] 16884983K->16853353K(62676032K), 0.5964590 secs] [Times:
user=5.68 sys=0.90, real=0.60 secs]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=1576M, runtime.usedMemory=59630M,
runTime.availableMemory=1576M, freeHeapPercentage=2.58
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=1576M, runtime.usedMemory=59630M,
runTime.availableMemory=1576M, freeHeapPercentage=2.58
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=1576M, runtime.usedMemory=59630M,
runTime.availableMemory=1576M, freeHeapPercentage=2.58
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=1576M, runtime.usedMemory=59630M,
runTime.availableMemory=1576M, freeHeapPercentage=2.58
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=1576M, runtime.usedMemory=59630M,
runTime.availableMemory=1576M, freeHeapPercentage=2.58
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=1576M, runtime.usedMemory=59630M,
runTime.availableMemory=1576M, freeHeapPercentage=2.58
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=1576M, runtime.usedMemory=59630M,
runTime.availableMemory=1576M, freeHeapPercentage=2.58
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=1576M, runtime.usedMemory=59630M,
runTime.availableMemory=1576M, freeHeapPercentage=2.58
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=1576M, runtime.usedMemory=59630M,
runTime.availableMemory=1576M, freeHeapPercentage=2.58
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=1576M, runtime.usedMemory=59630M,
runTime.availableMemory=1576M, freeHeapPercentage=2.58
36.472: [CMS-concurrent-sweep: 1.697/2.294 secs] [Times: user=13.86
sys=0.94, real=2.29 secs]
36.472: [CMS-concurrent-reset-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=1576M, runtime.usedMemory=59630M,
runTime.availableMemory=1576M, freeHeapPercentage=2.58
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=1576M, runtime.usedMemory=59630M,
runTime.availableMemory=1576M, freeHeapPercentage=2.58
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=1576M, runtime.usedMemory=59630M,
runTime.availableMemory=1576M, freeHeapPercentage=2.58
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=1576M, runtime.usedMemory=59630M,
runTime.availableMemory=1576M, freeHeapPercentage=2.58
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=1576M, runtime.usedMemory=59630M,
runTime.availableMemory=1576M, freeHeapPercentage=2.58
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=1576M, runtime.usedMemory=59630M,
runTime.availableMemory=1576M, freeHeapPercentage=2.58
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=1576M, runtime.usedMemory=59630M,
runTime.availableMemory=1576M, freeHeapPercentage=2.58
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=1576M, runtime.usedMemory=59630M,
runTime.availableMemory=1576M, freeHeapPercentage=2.58
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=1576M, runtime.usedMemory=59630M,
runTime.availableMemory=1576M, freeHeapPercentage=2.58
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=1576M, runtime.usedMemory=59630M,
runTime.availableMemory=1576M, freeHeapPercentage=2.58
36.594: [CMS-concurrent-reset: 0.122/0.122 secs] [Times: user=0.56
sys=0.01, real=0.12 secs]
38.594: [GC [1 CMS-initial-mark: 16614437K(60529088K)]
18658849K(62676032K), 0.3918420 secs] [Times: user=0.40 sys=0.00,
real=0.40 secs]
38.986: [CMS-concurrent-mark-start]
39.170: [GC39.170: [ParNew: 2146944K->238528K(2146944K), 0.6542340
secs] 18761381K->18734221K(62676032K), 0.6543650 secs] [Times:
user=9.06 sys=1.06, real=0.66 secs]
41.592: [CMS-concurrent-mark: 1.952/2.606 secs] [Times: user=27.04
sys=1.44, real=2.60 secs]
41.592: [CMS-concurrent-preclean-start]
42.630: [GC42.630: [ParNew: 2146944K->238528K(2146944K), 0.6582430
secs] 20642637K->20619236K(62676032K), 0.6583630 secs] [Times:
user=7.10 sys=0.96, real=0.66 secs]
45.295: [CMS-concurrent-preclean: 2.545/3.703 secs] [Times: user=20.74
sys=1.03, real=3.71 secs]
45.295: [CMS-concurrent-abortable-preclean-start]
45.754: [CMS-concurrent-abortable-preclean: 0.440/0.459 secs] [Times:
user=1.97 sys=0.01, real=0.45 secs]
45.754: [GC[YG occupancy: 1972273 K (2146944 K)]45.754: [Rescan
(parallel) , 0.0567050 secs]45.811: [weak refs processing, 0.0000290
secs]45.811: [scrub string table, 0.0001650 secs] [1 CMS-remark:
20380708K(60529088K)] 22352981K(62676032K), 0.0570420 secs] [Times:
user=0.99 sys=0.00, real=0.06 secs]
45.811: [CMS-concurrent-sweep-start]
46.057: [GC46.057: [ParNew: 2146944K->238528K(2146944K), 0.6509200
secs] 22520760K->22498628K(62676032K), 0.6510540 secs] [Times:
user=5.80 sys=0.90, real=0.65 secs]
48.782: [CMS-concurrent-sweep: 2.320/2.971 secs] [Times: user=15.44
sys=0.94, real=2.97 secs]
48.782: [CMS-concurrent-reset-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=798M, runtime.usedMemory=60409M,
runTime.availableMemory=798M, freeHeapPercentage=1.30
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=798M, runtime.usedMemory=60409M,
runTime.availableMemory=798M, freeHeapPercentage=1.30
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=798M, runtime.usedMemory=60409M,
runTime.availableMemory=798M, freeHeapPercentage=1.30
48.905: [CMS-concurrent-reset: 0.123/0.123 secs] [Times: user=0.54
sys=0.00, real=0.13 secs]
49.576: [GC49.576: [ParNew: 2146944K->238528K(2146944K), 0.9098200
secs] 24168579K->24146272K(62676032K), 0.9099430 secs] [Times:
user=5.52 sys=0.76, real=0.91 secs]
50.495: [GC [1 CMS-initial-mark: 23907744K(60529088K)]
24183040K(62676032K), 0.0441810 secs] [Times: user=0.04 sys=0.00,
real=0.04 secs]
50.539: [CMS-concurrent-mark-start]
52.849: [CMS-concurrent-mark: 2.310/2.310 secs] [Times: user=21.75
sys=0.37, real=2.31 secs]
52.849: [CMS-concurrent-preclean-start]
53.232: [CMS-concurrent-preclean: 0.378/0.383 secs] [Times: user=1.86
sys=0.01, real=0.38 secs]
53.232: [CMS-concurrent-abortable-preclean-start]
53.262: [GC53.262: [ParNew: 2146944K->238528K(2146944K), 0.6388870
secs] 26054688K->26033598K(62676032K), 0.6390090 secs] [Times:
user=5.77 sys=0.87, real=0.64 secs]
55.790: [CMS-concurrent-abortable-preclean: 1.657/2.558 secs] [Times:
user=13.95 sys=0.91, real=2.56 secs]
55.790: [GC[YG occupancy: 1519225 K (2146944 K)]55.790: [Rescan
(parallel) , 0.0415720 secs]55.832: [weak refs processing, 0.0000290
secs]55.832: [scrub string table, 0.0001280 secs] [1 CMS-remark:
25795070K(60529088K)] 27314296K(62676032K), 0.0418560 secs] [Times:
user=0.73 sys=0.00, real=0.04 secs]
55.832: [CMS-concurrent-sweep-start]
56.712: [GC56.712: [ParNew: 2146944K->238528K(2146944K), 0.6404990
secs] 27932356K->27910577K(62676032K), 0.6406280 secs] [Times:
user=6.26 sys=0.94, real=0.64 secs]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=483M, runtime.usedMemory=60723M,
runTime.availableMemory=483M, freeHeapPercentage=0.79
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=483M, runtime.usedMemory=60723M,
runTime.availableMemory=483M, freeHeapPercentage=0.79
59.273: [CMS-concurrent-sweep: 2.799/3.440
secs]runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=483M, runtime.usedMemory=60723M,
runTime.availableMemory=483M, freeHeapPercentage=0.79
[Times: user=17.00 sys=0.99, real=3.44 secs]
59.273: [CMS-concurrent-reset-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=483M, runtime.usedMemory=60723M,
runTime.availableMemory=483M, freeHeapPercentage=0.79
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=483M, runtime.usedMemory=60723M,
runTime.availableMemory=483M, freeHeapPercentage=0.79
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=483M, runtime.usedMemory=60723M,
runTime.availableMemory=483M, freeHeapPercentage=0.79
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=483M, runtime.usedMemory=60723M,
runTime.availableMemory=483M, freeHeapPercentage=0.79
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=483M, runtime.usedMemory=60723M,
runTime.availableMemory=483M, freeHeapPercentage=0.79
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=483M, runtime.usedMemory=60723M,
runTime.availableMemory=483M, freeHeapPercentage=0.79
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=483M, runtime.usedMemory=60723M,
runTime.availableMemory=483M, freeHeapPercentage=0.79
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=483M, runtime.usedMemory=60723M,
runTime.availableMemory=483M, freeHeapPercentage=0.79
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=483M, runtime.usedMemory=60723M,
runTime.availableMemory=483M, freeHeapPercentage=0.79
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=483M, runtime.usedMemory=60723M,
runTime.availableMemory=483M, freeHeapPercentage=0.79
59.393: [CMS-concurrent-reset: 0.121/0.121 secs] [Times: user=0.60
sys=0.00, real=0.12 secs]
59.902: [GC59.902: [ParNew: 2146944K->238528K(2146944K), 0.7065190
secs] 29803757K->29797857K(62676032K), 0.7066380 secs] [Times:
user=6.42 sys=0.96, real=0.71 secs]
60.622: [GC [1 CMS-initial-mark: 29559329K(60529088K)]
29822295K(62676032K), 0.1058490 secs] [Times: user=0.11 sys=0.00,
real=0.11 secs]
60.728: [CMS-concurrent-mark-start]
63.586: [GC63.586: [ParNew: 2146944K->238528K(2146944K), 0.6232010
secs] 31706273K->31683761K(62676032K), 0.6233350 secs] [Times:
user=5.46 sys=0.91, real=0.62 secs]
64.440: [CMS-concurrent-mark: 3.088/3.712 secs] [Times: user=35.70
sys=1.46, real=3.71 secs]
64.440: [CMS-concurrent-preclean-start]
66.715: [CMS-concurrent-preclean: 1.982/2.275 secs] [Times: user=10.21
sys=0.04, real=2.28 secs]
66.716: [CMS-concurrent-abortable-preclean-start]
66.880: [GC66.880: [ParNew: 2146944K->238528K(2146944K), 0.6119610
secs] 33592177K->33573043K(62676032K), 0.6120760 secs] [Times:
user=6.49 sys=0.93, real=0.61 secs]
69.702: [GC69.702: [ParNew: 2146944K->238528K(2146944K), 0.5955690
secs] 35481459K->35461194K(62676032K), 0.5956870 secs] [Times:
user=6.46 sys=0.93, real=0.60 secs]
70.329: [CMS-concurrent-abortable-preclean: 2.099/3.614 secs] [Times:
user=25.75 sys=1.92, real=3.61 secs]
70.329: [GC[YG occupancy: 293691 K (2146944 K)]70.329: [Rescan
(parallel) , 0.0635560 secs]70.393: [weak refs processing, 0.0000230
secs]70.393: [scrub string table, 0.0001290 secs] [1 CMS-remark:
35222666K(60529088K)] 35516357K(62676032K), 0.0638250 secs] [Times:
user=1.42 sys=0.02, real=0.06 secs]
70.393: [CMS-concurrent-sweep-start]
72.646: [GC72.646: [ParNew: 2146944K->238528K(2146944K), 0.9451240
secs] 36951043K->36929589K(62676032K), 0.9452550 secs] [Times:
user=5.85 sys=0.71, real=0.94 secs]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
75.105: [CMS-concurrent-sweep: 3.767/4.712 secs] [Times: user=24.29
sys=0.80, real=4.72 secs]
75.106: [CMS-concurrent-reset-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=936M, runtime.usedMemory=60270M,
runTime.availableMemory=936M, freeHeapPercentage=1.53
75.228: [CMS-concurrent-reset: 0.122/0.122 secs] [Times: user=0.53
sys=0.01, real=0.12 secs]
75.598: [GC [1 CMS-initial-mark: 36625076K(60529088K)]
38254679K(62676032K), 0.3188370 secs] [Times: user=0.32 sys=0.00,
real=0.32 secs]
75.917: [CMS-concurrent-mark-start]
76.659: [GC76.659: [ParNew: 2146944K->238528K(2146944K), 0.8054530
secs] 38772020K->38749651K(62676032K), 0.8055600 secs] [Times:
user=5.93 sys=0.84, real=0.81 secs]
80.291: [GC80.291: [ParNew: 2146944K->238528K(2146944K), 0.6266540
secs] 40658067K->40641414K(62676032K), 0.6267580 secs] [Times:
user=6.63 sys=1.02, real=0.63 secs]
81.322: [CMS-concurrent-mark: 3.972/5.405 secs] [Times: user=50.57
sys=2.50, real=5.40 secs]
81.322: [CMS-concurrent-preclean-start]
83.503: [GC83.503: [ParNew: 2146944K->238528K(2146944K), 0.6219820
secs] 42549830K->42530440K(62676032K), 0.6220780 secs] [Times:
user=6.70 sys=0.96, real=0.63 secs]
86.711: [GC86.711: [ParNew: 2146944K->238528K(2146944K), 0.6295710
secs] 44438856K->44419255K(62676032K), 0.6296720 secs] [Times:
user=5.84 sys=0.92, real=0.63 secs]
89.829: [GC89.829: [ParNew: 2146944K->238528K(2146944K), 0.6297130
secs] 46327671K->46307853K(62676032K), 0.6298170 secs] [Times:
user=7.59 sys=1.09, real=0.63 secs]
90.459: [CMS-concurrent-preclean: 6.186/9.137 secs] [Times: user=54.90
sys=3.11, real=9.14 secs]
90.459: [CMS-concurrent-abortable-preclean-start]
93.106: [GC93.106: [ParNew: 2146944K->238528K(2146944K), 0.6533050
secs] 48216269K->48193771K(62676032K), 0.6534110 secs] [Times:
user=10.04 sys=1.22, real=0.65 secs]
93.797: [CMS-concurrent-abortable-preclean: 2.383/3.338 secs] [Times:
user=22.51 sys=1.27, real=3.34 secs]
93.797: [GC[YG occupancy: 291838 K (2146944 K)]93.797: [Rescan
(parallel) , 0.0816650 secs]93.879: [weak refs processing, 0.0000220
secs]93.879: [scrub string table, 0.0001220 secs] [1 CMS-remark:
47955243K(60529088K)] 48247082K(62676032K), 0.0819420 secs] [Times:
user=1.61 sys=0.01, real=0.08 secs]
93.879: [CMS-concurrent-sweep-start]
96.615: [GC96.615: [ParNew: 2146944K->238528K(2146944K), 0.6331560
secs] 50053061K->50034231K(62676032K), 0.6332520 secs] [Times:
user=7.67 sys=1.03, real=0.63 secs]
99.520: [CMS-concurrent-sweep: 5.007/5.640 secs] [Times: user=30.41
sys=1.15, real=5.64 secs]
99.520: [CMS-concurrent-reset-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=319M, runtime.usedMemory=60887M,
runTime.availableMemory=319M, freeHeapPercentage=0.52
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=319M, runtime.usedMemory=60887M,
runTime.availableMemory=319M, freeHeapPercentage=0.52
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=319M, runtime.usedMemory=60887M,
runTime.availableMemory=319M, freeHeapPercentage=0.52
99.641: [CMS-concurrent-reset: 0.122/0.122 secs] [Times: user=0.67
sys=0.01, real=0.12 secs]
99.896: [GC99.896: [ParNew: 2146944K->238528K(2146944K), 0.5846780
secs] 51929136K->51910762K(62676032K), 0.5847860 secs] [Times:
user=5.33 sys=0.92, real=0.58 secs]
100.484: [GC [1 CMS-initial-mark: 51672234K(60529088K)]
51925538K(62676032K), 0.0461750 secs] [Times: user=0.05 sys=0.00,
real=0.05 secs]
100.530: [CMS-concurrent-mark-start]
102.959: [GC102.959: [ParNew: 2146944K->238528K(2146944K), 0.5868320
secs] 53819178K->53798644K(62676032K), 0.5869410 secs] [Times:
user=6.25 sys=0.88, real=0.59 secs]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7343M, runtime.usedMemory=53863M,
runTime.availableMemory=7343M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7343M, runtime.usedMemory=53863M,
runTime.availableMemory=7343M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7343M, runtime.usedMemory=53863M,
runTime.availableMemory=7343M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7343M, runtime.usedMemory=53863M,
runTime.availableMemory=7343M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7343M, runtime.usedMemory=53863M,
runTime.availableMemory=7343M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7343M, runtime.usedMemory=53863M,
runTime.availableMemory=7343M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7343M, runtime.usedMemory=53863M,
runTime.availableMemory=7343M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7343M, runtime.usedMemory=53863M,
runTime.availableMemory=7343M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7343M, runtime.usedMemory=53863M,
runTime.availableMemory=7343M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7343M, runtime.usedMemory=53863M,
runTime.availableMemory=7343M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7343M, runtime.usedMemory=53863M,
runTime.availableMemory=7343M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7343M, runtime.usedMemory=53863M,
runTime.availableMemory=7343M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7343M, runtime.usedMemory=53863M,
runTime.availableMemory=7343M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7343M, runtime.usedMemory=53863M,
runTime.availableMemory=7343M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7343M, runtime.usedMemory=53863M,
runTime.availableMemory=7343M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7343M, runtime.usedMemory=53863M,
runTime.availableMemory=7343M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7343M, runtime.usedMemory=53863M,
runTime.availableMemory=7343M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7344M, runtime.usedMemory=53862M,
runTime.availableMemory=7344M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7343M, runtime.usedMemory=53863M,
runTime.availableMemory=7343M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7342M, runtime.usedMemory=53864M,
runTime.availableMemory=7342M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7342M, runtime.usedMemory=53864M,
runTime.availableMemory=7342M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7342M, runtime.usedMemory=53864M,
runTime.availableMemory=7342M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7342M, runtime.usedMemory=53864M,
runTime.availableMemory=7342M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7342M, runtime.usedMemory=53864M,
runTime.availableMemory=7342M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7342M, runtime.usedMemory=53864M,
runTime.availableMemory=7342M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7342M, runtime.usedMemory=53864M,
runTime.availableMemory=7342M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7342M, runtime.usedMemory=53864M,
runTime.availableMemory=7342M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7342M, runtime.usedMemory=53864M,
runTime.availableMemory=7342M, freeHeapPercentage=12.00
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7342M, runtime.usedMemory=53864M,
runTime.availableMemory=7342M, freeHeapPercentage=12.00
End of run...now we expect to see actual used-memory value
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7342M, runtime.usedMemory=53865M,
runTime.availableMemory=7342M, freeHeapPercentage=12.00
108.307: [CMS-concurrent-mark: 7.187/7.777 secs] [Times: user=68.29
sys=1.90, real=7.78 secs]
108.307: [CMS-concurrent-preclean-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7329M, runtime.usedMemory=53877M,
runTime.availableMemory=7329M, freeHeapPercentage=11.98
110.690: [CMS-concurrent-preclean: 2.088/2.383 secs] [Times: user=2.39
sys=0.00, real=2.38 secs]
110.690: [CMS-concurrent-abortable-preclean-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7329M, runtime.usedMemory=53877M,
runTime.availableMemory=7329M, freeHeapPercentage=11.98
CMS: abort preclean due to time 115.797:
[CMS-concurrent-abortable-preclean: 3.706/5.107 secs] [Times:
user=3.71 sys=0.00, real=5.11 secs]
115.797: [GC[YG occupancy: 1610438 K (2146944 K)]115.797: [Rescan
(parallel) , 0.3345390 secs]116.132: [weak refs processing, 0.0000200
secs]116.132: [scrub string table, 0.0001210 secs] [1 CMS-remark:
53560116K(60529088K)] 55170554K(62676032K), 0.3347610 secs] [Times:
user=6.36 sys=0.02, real=0.33 secs]
116.132: [CMS-concurrent-sweep-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7444M, runtime.usedMemory=53762M,
runTime.availableMemory=7444M, freeHeapPercentage=12.16
121.468: [CMS-concurrent-sweep: 5.336/5.336 secs] [Times: user=5.35
sys=0.00, real=5.34 secs]
121.469: [CMS-concurrent-reset-start]
121.593: [CMS-concurrent-reset: 0.125/0.125 secs] [Times: user=0.13
sys=0.00, real=0.12 secs]
123.593: [GC [1 CMS-initial-mark: 53426011K(60529088K)]
55036449K(62676032K), 0.3241770 secs] [Times: user=0.32 sys=0.00,
real=0.33 secs]
123.918: [CMS-concurrent-mark-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7460M, runtime.usedMemory=53746M,
runTime.availableMemory=7460M, freeHeapPercentage=12.19
128.910: [CMS-concurrent-mark: 4.993/4.993 secs] [Times: user=32.81
sys=0.80, real=4.99 secs]
128.910: [CMS-concurrent-preclean-start]
128.969: [CMS-concurrent-preclean: 0.058/0.058 secs] [Times: user=0.06
sys=0.00, real=0.06 secs]
128.969: [CMS-concurrent-abortable-preclean-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7460M, runtime.usedMemory=53746M,
runTime.availableMemory=7460M, freeHeapPercentage=12.19
CMS: abort preclean due to time 134.096:
[CMS-concurrent-abortable-preclean: 3.726/5.127 secs] [Times:
user=3.74 sys=0.00, real=5.13 secs]
134.096: [GC[YG occupancy: 1610438 K (2146944 K)]134.096: [Rescan
(parallel) , 0.3166330 secs]134.413: [weak refs processing, 0.0000220
secs]134.413: [scrub string table, 0.0001220 secs] [1 CMS-remark:
53426011K(60529088K)] 55036449K(62676032K), 0.3168870 secs] [Times:
user=6.06 sys=0.05, real=0.31 secs]
134.413: [CMS-concurrent-sweep-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7461M, runtime.usedMemory=53745M,
runTime.availableMemory=7461M, freeHeapPercentage=12.19
139.841: [CMS-concurrent-sweep: 5.428/5.428 secs] [Times: user=5.44
sys=0.00, real=5.43 secs]
139.841: [CMS-concurrent-reset-start]
139.965: [CMS-concurrent-reset: 0.124/0.124 secs] [Times: user=0.13
sys=0.00, real=0.13 secs]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
141.965: [GC [1 CMS-initial-mark: 53419286K(60529088K)]
55029724K(62676032K), 0.3267790 secs] [Times: user=0.33 sys=0.00,
real=0.32 secs]
142.292: [CMS-concurrent-mark-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
146.897: [CMS-concurrent-mark: 4.605/4.605 secs] [Times: user=30.89
sys=0.48, real=4.61 secs]
146.898: [CMS-concurrent-preclean-start]
146.955: [CMS-concurrent-preclean: 0.058/0.058 secs] [Times: user=0.06
sys=0.00, real=0.06 secs]
146.955: [CMS-concurrent-abortable-preclean-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
CMS: abort preclean due to time 152.087:
[CMS-concurrent-abortable-preclean: 3.731/5.132 secs] [Times:
user=3.74 sys=0.00, real=5.13 secs]
152.088: [GC[YG occupancy: 1610438 K (2146944 K)]152.088: [Rescan
(parallel) , 0.5756110 secs]152.663: [weak refs processing, 0.0000230
secs]152.663: [scrub string table, 0.0001300 secs] [1 CMS-remark:
53419286K(60529088K)] 55029724K(62676032K), 0.5758770 secs] [Times:
user=11.00 sys=0.08, real=0.57 secs]
152.664: [CMS-concurrent-sweep-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
158.034: [CMS-concurrent-sweep: 5.371/5.371 secs] [Times: user=5.38
sys=0.00, real=5.37 secs]
158.034: [CMS-concurrent-reset-start]
158.158: [CMS-concurrent-reset: 0.124/0.124 secs] [Times: user=0.13
sys=0.00, real=0.12 secs]
160.158: [GC [1 CMS-initial-mark: 53419286K(60529088K)]
55029724K(62676032K), 0.3387750 secs] [Times: user=0.34 sys=0.00,
real=0.34 secs]
160.497: [CMS-concurrent-mark-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
165.390: [CMS-concurrent-mark: 4.892/4.893 secs] [Times: user=32.05
sys=0.66, real=4.89 secs]
165.390: [CMS-concurrent-preclean-start]
165.449: [CMS-concurrent-preclean: 0.059/0.059 secs] [Times: user=0.06
sys=0.00, real=0.06 secs]
165.449: [CMS-concurrent-abortable-preclean-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
CMS: abort preclean due to time 170.580:
[CMS-concurrent-abortable-preclean: 3.730/5.131 secs] [Times:
user=3.74 sys=0.00, real=5.13 secs]
170.580: [GC[YG occupancy: 1610438 K (2146944 K)]170.580: [Rescan
(parallel) , 0.3244620 secs]170.905: [weak refs processing, 0.0000200
secs]170.905: [scrub string table, 0.0001360 secs] [1 CMS-remark:
53419286K(60529088K)] 55029724K(62676032K), 0.3247170 secs] [Times:
user=5.98 sys=0.05, real=0.33 secs]
170.905: [CMS-concurrent-sweep-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
176.327: [CMS-concurrent-sweep: 5.422/5.422 secs] [Times: user=5.43
sys=0.00, real=5.42 secs]
176.327: [CMS-concurrent-reset-start]
176.451: [CMS-concurrent-reset: 0.124/0.124 secs] [Times: user=0.12
sys=0.00, real=0.12 secs]
178.452: [GC [1 CMS-initial-mark: 53419286K(60529088K)]
55029724K(62676032K), 0.3595980 secs] [Times: user=0.36 sys=0.00,
real=0.36 secs]
178.811: [CMS-concurrent-mark-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
183.353: [CMS-concurrent-mark: 4.541/4.541 secs] [Times: user=30.41
sys=0.51, real=4.54 secs]
183.353: [CMS-concurrent-preclean-start]
183.416: [CMS-concurrent-preclean: 0.063/0.063 secs] [Times: user=0.06
sys=0.00, real=0.07 secs]
183.416: [CMS-concurrent-abortable-preclean-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
CMS: abort preclean due to time 188.572:
[CMS-concurrent-abortable-preclean: 3.755/5.156 secs] [Times:
user=3.76 sys=0.00, real=5.15 secs]
188.572: [GC[YG occupancy: 1610438 K (2146944 K)]188.572: [Rescan
(parallel) , 0.3576490 secs]188.929: [weak refs processing, 0.0000250
secs]188.929: [scrub string table, 0.0001260 secs] [1 CMS-remark:
53419286K(60529088K)] 55029724K(62676032K), 0.3579100 secs] [Times:
user=6.56 sys=0.07, real=0.36 secs]
188.930: [CMS-concurrent-sweep-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
194.404: [CMS-concurrent-sweep: 5.474/5.474 secs] [Times: user=5.49
sys=0.00, real=5.47 secs]
194.404: [CMS-concurrent-reset-start]
194.527: [CMS-concurrent-reset: 0.124/0.124 secs] [Times: user=0.12
sys=0.00, real=0.13 secs]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
196.528: [GC [1 CMS-initial-mark: 53419286K(60529088K)]
55029724K(62676032K), 0.3428100 secs] [Times: user=0.35 sys=0.00,
real=0.34 secs]
196.871: [CMS-concurrent-mark-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
201.918: [CMS-concurrent-mark: 5.047/5.047 secs] [Times: user=33.24
sys=0.83, real=5.05 secs]
201.918: [CMS-concurrent-preclean-start]
201.976: [CMS-concurrent-preclean: 0.058/0.058 secs] [Times: user=0.05
sys=0.00, real=0.06 secs]
201.976: [CMS-concurrent-abortable-preclean-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
CMS: abort preclean due to time 207.071:
[CMS-concurrent-abortable-preclean: 3.694/5.095 secs] [Times:
user=3.71 sys=0.00, real=5.09 secs]
207.071: [GC[YG occupancy: 1610438 K (2146944 K)]207.071: [Rescan
(parallel) , 0.3230240 secs]207.394: [weak refs processing, 0.0000250
secs]207.394: [scrub string table, 0.0001370 secs] [1 CMS-remark:
53419286K(60529088K)] 55029724K(62676032K), 0.3232880 secs] [Times:
user=5.73 sys=0.03, real=0.33 secs]
207.395: [CMS-concurrent-sweep-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
212.728: [CMS-concurrent-sweep: 5.333/5.333 secs] [Times: user=5.35
sys=0.00, real=5.33 secs]
212.728: [CMS-concurrent-reset-start]
212.852: [CMS-concurrent-reset: 0.124/0.124 secs] [Times: user=0.12
sys=0.00, real=0.12 secs]
214.852: [GC [1 CMS-initial-mark: 53419286K(60529088K)]
55029724K(62676032K), 0.3493740 secs] [Times: user=0.35 sys=0.00,
real=0.35 secs]
215.202: [CMS-concurrent-mark-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
220.095: [CMS-concurrent-mark: 4.893/4.893 secs] [Times: user=32.33
sys=0.76, real=4.90 secs]
220.095: [CMS-concurrent-preclean-start]
220.154: [CMS-concurrent-preclean: 0.059/0.059 secs] [Times: user=0.06
sys=0.00, real=0.05 secs]
220.154: [CMS-concurrent-abortable-preclean-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
CMS: abort preclean due to time 225.272:
[CMS-concurrent-abortable-preclean: 3.718/5.119 secs] [Times:
user=3.73 sys=0.00, real=5.12 secs]
225.272: [GC[YG occupancy: 1610438 K (2146944 K)]225.272: [Rescan
(parallel) , 0.3205500 secs]225.593: [weak refs processing, 0.0000220
secs]225.593: [scrub string table, 0.0001240 secs] [1 CMS-remark:
53419286K(60529088K)] 55029724K(62676032K), 0.3208060 secs] [Times:
user=5.53 sys=0.07, real=0.32 secs]
225.593: [CMS-concurrent-sweep-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
230.979: [CMS-concurrent-sweep: 5.386/5.386 secs] [Times: user=5.40
sys=0.00, real=5.39 secs]
230.979: [CMS-concurrent-reset-start]
231.103: [CMS-concurrent-reset: 0.124/0.124 secs] [Times: user=0.13
sys=0.00, real=0.12 secs]
233.104: [GC [1 CMS-initial-mark: 53419286K(60529088K)]
55029724K(62676032K), 0.3235480 secs] [Times: user=0.32 sys=0.00,
real=0.33 secs]
233.427: [CMS-concurrent-mark-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
238.241: [CMS-concurrent-mark: 4.814/4.814 secs] [Times: user=31.71
sys=0.70, real=4.81 secs]
238.241: [CMS-concurrent-preclean-start]
238.299: [CMS-concurrent-preclean: 0.058/0.058 secs] [Times: user=0.05
sys=0.00, real=0.06 secs]
238.299: [CMS-concurrent-abortable-preclean-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
CMS: abort preclean due to time 243.393:
[CMS-concurrent-abortable-preclean: 3.692/5.093 secs] [Times:
user=3.70 sys=0.00, real=5.09 secs]
243.393: [GC[YG occupancy: 1610438 K (2146944 K)]243.393: [Rescan
(parallel) , 0.4171870 secs]243.810: [weak refs processing, 0.0000220
secs]243.810: [scrub string table, 0.0001300 secs] [1 CMS-remark:
53419286K(60529088K)] 55029724K(62676032K), 0.4174430 secs] [Times:
user=7.59 sys=0.04, real=0.42 secs]
243.810: [CMS-concurrent-sweep-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
249.138: [CMS-concurrent-sweep: 5.328/5.328 secs] [Times: user=5.34
sys=0.00, real=5.33 secs]
249.138: [CMS-concurrent-reset-start]
249.262: [CMS-concurrent-reset: 0.123/0.123 secs] [Times: user=0.13
sys=0.00, real=0.12 secs]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
251.262: [GC [1 CMS-initial-mark: 53419286K(60529088K)]
55029724K(62676032K), 0.3307570 secs] [Times: user=0.33 sys=0.00,
real=0.33 secs]
251.593: [CMS-concurrent-mark-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
256.226: [CMS-concurrent-mark: 4.633/4.633 secs] [Times: user=30.73
sys=0.69, real=4.64 secs]
256.226: [CMS-concurrent-preclean-start]
256.284: [CMS-concurrent-preclean: 0.058/0.058 secs] [Times: user=0.05
sys=0.00, real=0.05 secs]
256.284: [CMS-concurrent-abortable-preclean-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
CMS: abort preclean due to time 261.444:
[CMS-concurrent-abortable-preclean: 3.759/5.160 secs] [Times:
user=3.77 sys=0.00, real=5.16 secs]
261.444: [GC[YG occupancy: 1610438 K (2146944 K)]261.444: [Rescan
(parallel) , 0.3162650 secs]261.760: [weak refs processing, 0.0000230
secs]261.760: [scrub string table, 0.0001400 secs] [1 CMS-remark:
53419286K(60529088K)] 55029724K(62676032K), 0.3165290 secs] [Times:
user=5.42 sys=0.02, real=0.32 secs]
261.761: [CMS-concurrent-sweep-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
267.124: [CMS-concurrent-sweep: 5.364/5.364 secs] [Times: user=5.37
sys=0.00, real=5.36 secs]
267.124: [CMS-concurrent-reset-start]
267.248: [CMS-concurrent-reset: 0.124/0.124 secs] [Times: user=0.13
sys=0.00, real=0.13 secs]
269.249: [GC [1 CMS-initial-mark: 53419286K(60529088K)]
55029724K(62676032K), 0.3293280 secs] [Times: user=0.33 sys=0.00,
real=0.33 secs]
269.578: [CMS-concurrent-mark-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
274.842: [CMS-concurrent-mark: 5.264/5.264 secs] [Times: user=33.32
sys=0.61, real=5.26 secs]
274.842: [CMS-concurrent-preclean-start]
274.900: [CMS-concurrent-preclean: 0.058/0.058 secs] [Times: user=0.05
sys=0.00, real=0.06 secs]
274.900: [CMS-concurrent-abortable-preclean-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
CMS: abort preclean due to time 279.951:
[CMS-concurrent-abortable-preclean: 3.649/5.050 secs] [Times:
user=3.66 sys=0.00, real=5.05 secs]
279.951: [GC[YG occupancy: 1610438 K (2146944 K)]279.951: [Rescan
(parallel) , 0.3062610 secs]280.257: [weak refs processing, 0.0000230
secs]280.257: [scrub string table, 0.0001380 secs] [1 CMS-remark:
53419286K(60529088K)] 55029724K(62676032K), 0.3065390 secs] [Times:
user=5.49 sys=0.04, real=0.31 secs]
280.258: [CMS-concurrent-sweep-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
285.596: [CMS-concurrent-sweep: 5.338/5.338 secs] [Times: user=5.35
sys=0.00, real=5.34 secs]
285.596: [CMS-concurrent-reset-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
285.720: [CMS-concurrent-reset: 0.123/0.123 secs] [Times: user=0.13
sys=0.00, real=0.12 secs]
287.720: [GC [1 CMS-initial-mark: 53419286K(60529088K)]
55029724K(62676032K), 0.3431370 secs] [Times: user=0.34 sys=0.00,
real=0.34 secs]
288.063: [CMS-concurrent-mark-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
293.197: [CMS-concurrent-mark: 5.134/5.134 secs] [Times: user=31.78
sys=0.77, real=5.14 secs]
293.197: [CMS-concurrent-preclean-start]
293.255: [CMS-concurrent-preclean: 0.058/0.058 secs] [Times: user=0.06
sys=0.00, real=0.06 secs]
293.255: [CMS-concurrent-abortable-preclean-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
CMS: abort preclean due to time 298.361:
[CMS-concurrent-abortable-preclean: 3.705/5.106 secs] [Times:
user=3.71 sys=0.00, real=5.10 secs]
298.361: [GC[YG occupancy: 1610438 K (2146944 K)]298.361: [Rescan
(parallel) , 0.3069420 secs]298.668: [weak refs processing, 0.0000220
secs]298.668: [scrub string table, 0.0001220 secs] [1 CMS-remark:
53419286K(60529088K)] 55029724K(62676032K), 0.3071670 secs] [Times:
user=5.53 sys=0.08, real=0.31 secs]
298.668: [CMS-concurrent-sweep-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
304.039: [CMS-concurrent-sweep: 5.370/5.370 secs] [Times: user=5.38
sys=0.00, real=5.37 secs]
304.039: [CMS-concurrent-reset-start]
304.162: [CMS-concurrent-reset: 0.124/0.124 secs] [Times: user=0.12
sys=0.00, real=0.12 secs]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
306.163: [GC [1 CMS-initial-mark: 53419286K(60529088K)]
55029724K(62676032K), 0.3258150 secs] [Times: user=0.33 sys=0.00,
real=0.33 secs]
306.488: [CMS-concurrent-mark-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
311.716: [CMS-concurrent-mark: 5.228/5.228 secs] [Times: user=33.89
sys=0.97, real=5.23 secs]
311.716: [CMS-concurrent-preclean-start]
311.777: [CMS-concurrent-preclean: 0.060/0.060 secs] [Times: user=0.06
sys=0.00, real=0.06 secs]
311.777: [CMS-concurrent-abortable-preclean-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
CMS: abort preclean due to time 316.855:
[CMS-concurrent-abortable-preclean: 3.677/5.078 secs] [Times:
user=3.69 sys=0.00, real=5.08 secs]
316.855: [GC[YG occupancy: 1610438 K (2146944 K)]316.855: [Rescan
(parallel) , 0.3299850 secs]317.185: [weak refs processing, 0.0000220
secs]317.185: [scrub string table, 0.0001320 secs] [1 CMS-remark:
53419286K(60529088K)] 55029724K(62676032K), 0.3302460 secs] [Times:
user=6.28 sys=0.08, real=0.33 secs]
317.185: [CMS-concurrent-sweep-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
322.600: [CMS-concurrent-sweep: 5.415/5.415 secs] [Times: user=5.43
sys=0.00, real=5.41 secs]
322.600: [CMS-concurrent-reset-start]
322.724: [CMS-concurrent-reset: 0.123/0.123 secs] [Times: user=0.12
sys=0.00, real=0.12 secs]
324.724: [GC [1 CMS-initial-mark: 53419286K(60529088K)]
55029724K(62676032K), 0.3439200 secs] [Times: user=0.35 sys=0.00,
real=0.35 secs]
325.068: [CMS-concurrent-mark-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
330.097: [CMS-concurrent-mark: 5.029/5.029 secs] [Times: user=33.20
sys=0.74, real=5.03 secs]
330.097: [CMS-concurrent-preclean-start]
330.158: [CMS-concurrent-preclean: 0.061/0.061 secs] [Times: user=0.06
sys=0.00, real=0.06 secs]
330.158: [CMS-concurrent-abortable-preclean-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
CMS: abort preclean due to time 335.261:
[CMS-concurrent-abortable-preclean: 3.702/5.103 secs] [Times:
user=3.71 sys=0.00, real=5.10 secs]
335.261: [GC[YG occupancy: 1610438 K (2146944 K)]335.261: [Rescan
(parallel) , 0.4076950 secs]335.669: [weak refs processing, 0.0000200
secs]335.669: [scrub string table, 0.0001280 secs] [1 CMS-remark:
53419286K(60529088K)] 55029724K(62676032K), 0.4079360 secs] [Times:
user=7.02 sys=0.02, real=0.41 secs]
335.669: [CMS-concurrent-sweep-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
341.024: [CMS-concurrent-sweep: 5.355/5.355 secs] [Times: user=5.36
sys=0.00, real=5.36 secs]
341.025: [CMS-concurrent-reset-start]
341.148: [CMS-concurrent-reset: 0.123/0.123 secs] [Times: user=0.13
sys=0.00, real=0.12 secs]
343.148: [GC [1 CMS-initial-mark: 53419286K(60529088K)]
55029724K(62676032K), 0.3265310 secs] [Times: user=0.32 sys=0.00,
real=0.33 secs]
343.475: [CMS-concurrent-mark-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
348.373: [CMS-concurrent-mark: 4.898/4.899 secs] [Times: user=32.31
sys=0.81, real=4.89 secs]
348.373: [CMS-concurrent-preclean-start]
348.431: [CMS-concurrent-preclean: 0.058/0.058 secs] [Times: user=0.06
sys=0.00, real=0.06 secs]
348.431: [CMS-concurrent-abortable-preclean-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
CMS: abort preclean due to time 353.490:
[CMS-concurrent-abortable-preclean: 3.658/5.059 secs] [Times:
user=3.67 sys=0.00, real=5.06 secs]
353.490: [GC[YG occupancy: 1610438 K (2146944 K)]353.490: [Rescan
(parallel) , 0.5716350 secs]354.062: [weak refs processing, 0.0000230
secs]354.062: [scrub string table, 0.0001300 secs] [1 CMS-remark:
53419286K(60529088K)] 55029724K(62676032K), 0.5718720 secs] [Times:
user=10.28 sys=0.09, real=0.57 secs]
354.062: [CMS-concurrent-sweep-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
359.432: [CMS-concurrent-sweep: 5.370/5.370 secs] [Times: user=5.38
sys=0.00, real=5.37 secs]
359.432: [CMS-concurrent-reset-start]
359.556: [CMS-concurrent-reset: 0.123/0.123 secs] [Times: user=0.12
sys=0.00, real=0.13 secs]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
361.556: [GC [1 CMS-initial-mark: 53419286K(60529088K)]
55029724K(62676032K), 0.3277380 secs] [Times: user=0.33 sys=0.00,
real=0.32 secs]
361.884: [CMS-concurrent-mark-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
366.817: [CMS-concurrent-mark: 4.933/4.933 secs] [Times: user=32.78
sys=0.77, real=4.94 secs]
366.817: [CMS-concurrent-preclean-start]
366.875: [CMS-concurrent-preclean: 0.058/0.058 secs] [Times: user=0.06
sys=0.00, real=0.06 secs]
366.875: [CMS-concurrent-abortable-preclean-start]
runtime.maxMemory=61207M, runtime.totalMemory=61207M,
runtime.freeMemory=7467M, runtime.usedMemory=53739M,
runTime.availableMemory=7467M, freeHeapPercentage=12.20
Heap
par new generation total 2146944K, used 1649288K
[0x00007f2d45a00000, 0x00007f2dd7390000, 0x00007f2dd7390000)
eden space 1908416K, 73% used [0x00007f2d45a00000,
0x00007f2d9bbb21a8, 0x00007f2dba1b0000)
from space 238528K, 100% used [0x00007f2dc8aa0000,
0x00007f2dd7390000, 0x00007f2dd7390000)
to space 238528K, 0% used [0x00007f2dba1b0000,
0x00007f2dba1b0000, 0x00007f2dc8aa0000)
concurrent mark-sweep generation total 60529088K, used 53419286K
[0x00007f2dd7390000, 0x00007f3c45a00000, 0x00007f3c45a00000)
concurrent-mark-sweep perm gen total 21248K, used 3240K
[0x00007f3c45a00000, 0x00007f3c46ec0000, 0x00007f3c50000000)
19 Haz 2016 Paz, 01:56 tarihinde, ahmet mırçık <ahmetmircik at gmail.com> şunu
yazdı:
> Adding all logs from start of run:
>
> java -verbose:gc -Xms60G -Xmx60G -XX:CMSInitiatingOccupancyFraction=2 -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -cp target/free-memory-issue-1.0-
>
> SNAPSHOT.jar FreeMemory
>
> [GC (Allocation Failure) 886080K->21645K(62803840K), 0.0743103 secs]
> [GC (Allocation Failure) 907725K->568287K(62803840K), 0.4186990 secs]
> [GC (Allocation Failure) 1454367K->1232520K(62803840K), 0.2885866 secs]
> [GC (Allocation Failure) 2118600K->1985828K(62803840K), 0.3087718 secs]
> [GC (CMS Initial Mark) 2042073K(62803840K), 0.0037783 secs]
> [GC (Allocation Failure) 2871908K->2786446K(62803840K), 0.3650447 secs]
> [GC (Allocation Failure) 3672526K->3670514K(62803840K), 0.3675287 secs]
> [GC (Allocation Failure) 4556594K->4445914K(62803840K), 0.3455842 secs]
> [GC (Allocation Failure) 5331994K->5302365K(62803840K), 0.3627719 secs]
> [GC (CMS Final Remark) 5304053K(62803840K), 0.0586894 secs]
> runtime.maxMemory=61331M, runtime.totalMemory=61331M, runtime.freeMemory=509M, runtime.usedMemory=60822M, runTime.availableMemory=509M, freeHeapPercentage=0.83
> runtime.maxMemory=61331M, runtime.totalMemory=61331M, runtime.freeMemory=509M, runtime.usedMemory=60822M, runTime.availableMemory=509M, freeHeapPercentage=0.83
>
> End of run and free-memory returned expected values: (55734M instead of
> 509M)
>
> runtime.maxMemory=61331M, runtime.totalMemory=61331M, runtime.freeMemory=55734M, runtime.usedMemory=5597M, runTime.availableMemory=55734M, freeHeapPercentage=90.87
>
>
>
>
>
> 19 Haz 2016 Paz, 01:44 tarihinde <ecki at zusammenkunft.net> şunu yazdı:
>
>> Hello,
>>
>> Maybe you should show output and gclog as well.
>>
>> However I would argue that logging and alerting memory usage numbers is
>> next to useless in most situations. If you want to have some usefull
>> numbers I would restrict myself to log free memory for the various pools
>> after related GC runs. The JMX beans have a metric for that.
>>
>> Gruss
>> Bernd
>>
>> --
>> http://bernd.eckenfels.net
>>
>> -----Original Message-----
>> From: "ahmet mırçık" <ahmetmircik at gmail.com>
>> To: hotspot-gc-dev at openjdk.java.net
>> Sent: So., 19 Juni 2016 0:31
>> Subject: Runtime.getRuntime().freeMemory() can report wrong values when
>> collector is CMS?
>>
>> Hi,
>>
>> I am running a test which is trying to log memory info. when
>> free-heap-percentage is under a certain threshold. But noticed that when
>> heap is around `-XX:CMSInitiatingOccupancyFraction`,
>> Runtime.getRuntime().freeMemory() can report wrong values when compared to
>> memory info from GC logs. It reports as if whole heap is nearly occupied,
>> but actually there exists lots of free-memory. Issue is observable for a
>> short-time period. Later it starts to report expected values. (Also tried
>> my test with G1 defaults and Runtime.getRuntime().freeMemory() reported as
>> expected)
>>
>> Issue is easily visible on large heaps.
>>
>> Is my assumption correct? Can Runtime.getRuntime().freeMemory() report
>> wrong free-memory info for a while? Or how can we explain this situation?
>>
>> Here is my test and how i run it from command line:
>>
>> [PROBLEMATIC RUN WITH CMS]--> java -verbose:gc -Xms60G -Xmx60G
>> -XX:CMSInitiatingOccupancyFraction=2 -XX:+UseConcMarkSweepGC
>> -XX:+UseParNewGC -cp target/free-memory-issue-1.0-SNAPSHOT.jar
>> FreeMemory
>>
>> [OK RUN WITH G1]--> java -verbose:gc -Xms60G -Xmx60G -XX:+UseG1GC -cp
>> target/free-memory-issue-1.0-SNAPSHOT.jar FreeMemory
>>
>> public class FreeMemory {
>>
>> static final int MB = 1024 * 1024;
>> static final String MESSAGE = "runtime.maxMemory=%d%s,
>> runtime.totalMemory=%d%s, runtime.freeMemory=%d%s," +
>> " runtime.usedMemory=%d%s, runTime.availableMemory=%d%s,
>> freeHeapPercentage=%.2f";
>>
>> public static void main(String[] args) throws InterruptedException {
>> final ConcurrentHashMap map = new ConcurrentHashMap();
>>
>> Runtime runtime = Runtime.getRuntime();
>> int availableProcessors = runtime.availableProcessors();
>> int threadCount = availableProcessors * 4;
>>
>> ArrayList<Thread> threads = new ArrayList<Thread>();
>>
>> for (int i = 0; i < threadCount; i++) {
>> threads.add(new Thread(new Runnable() {
>>
>> @Override
>> public void run() {
>> Random random = new Random();
>> while (true) {
>> byte[] value = new byte[1024];
>> random.nextBytes(value);
>>
>> map.put(random.nextInt(), value);
>>
>> if (hasReachedMinFreeHeapPercentage(12)) {
>> break;
>> }
>> }
>> }
>> }));
>> }
>>
>> for (Thread thread : threads) {
>> thread.start();
>> }
>>
>> for (Thread thread : threads) {
>> thread.join();
>> }
>>
>> out.print("\n\n\nEnd of run...now we expect to see actual
>> used-memory value\n");
>>
>> while (true) {
>> printCurrentMemoryInfo();
>> parkNanos(SECONDS.toNanos(5));
>> }
>> }
>>
>> static boolean hasReachedMinFreeHeapPercentage(int
>> minFreeHeapPercentage) {
>> Runtime runtime = Runtime.getRuntime();
>>
>> long maxMemory = runtime.maxMemory();
>> long totalMemory = runtime.totalMemory();
>> long freeMemory = runtime.freeMemory();
>> long availableMemory = freeMemory + (maxMemory - totalMemory);
>> double freeHeapPercentage = 100D * availableMemory / maxMemory;
>>
>> if (freeHeapPercentage < minFreeHeapPercentage) {
>> String unit = "M";
>> out.println(format(MESSAGE, toMB(maxMemory), unit,
>> toMB(totalMemory), unit, toMB(freeMemory), unit,
>> toMB(totalMemory - freeMemory), unit,
>> toMB(availableMemory), unit, freeHeapPercentage));
>> return true;
>> }
>>
>> return false;
>> }
>>
>> static void printCurrentMemoryInfo() {
>> Runtime runtime = Runtime.getRuntime();
>>
>> long maxMemory = runtime.maxMemory();
>> long totalMemory = runtime.totalMemory();
>> long freeMemory = runtime.freeMemory();
>> long availableMemory = freeMemory + (maxMemory - totalMemory);
>> double freeHeapPercentage = 100D * availableMemory / maxMemory;
>>
>> String unit = "M";
>> out.println(format(MESSAGE, toMB(maxMemory), unit,
>> toMB(totalMemory), unit, toMB(freeMemory), unit,
>> toMB(totalMemory - freeMemory), unit,
>> toMB(availableMemory), unit, freeHeapPercentage));
>> }
>>
>> static int toMB(long bytes) {
>> return (int) Math.rint(bytes / MB);
>> }
>> }
>>
>> Java version:
>>
>> openjdk version "1.8.0_91"
>>
>> OpenJDK Runtime Environment (build 1.8.0_91-8u91-b14-0ubuntu4~14.04-b14)
>>
>> OpenJDK 64-Bit Server VM (build 25.91-b14, mixed mode)
>>
>> OS info:
>>
>> Linux version 3.13.0-74-generic (buildd at lcy01-07) (gcc version 4.8.2
>> (Ubuntu 4.8.2-19ubuntu1) ) #118-Ubuntu SMP Thu Dec 17 22:52:10 UTC 2015
>>
>> Distributor ID: Ubuntu
>>
>> Description: Ubuntu 14.04.3 LTS
>>
>> Release: 14.04
>>
>>
>> Thanks in advance,
>>
> --
> ahmet
>
--
ahmet
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/hotspot-gc-dev/attachments/20160622/33ed5f23/attachment.htm>
More information about the hotspot-gc-dev
mailing list