« Return to Thread: CMS collection keep working during holiday

CMS collection keep working during holiday

by Ken--@newsgroupstats.hk :: Rate this Message:

| View in Thread

01/10 is our holiday and my stock quote application was in leisure time on 01/10.

I am surprised that during non-busy hours, my application keep draw around 15-20% cpu loading due to continueously CMS collections.

It seems that -XX:CMSInitiatingOccupancyFraction=70 will not take effect during non-busy hours. Please find the attached memory chart from jconsole and gc log.

jvm options:
%JAVA_HOME%\jre\bin\java -server -verbose:gc -XX:+PrintGCDetails -Xloggc:powerserver_gc.log -showversion -Djava.security.policy=.\java.policy -Xms4G -Xmx4G -XX:NewSize=1G -XX:+DisableExplicitGC -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:SurvivorRatio=4 -XX:CMSInitiatingOccupancyFraction=70 -XX:TargetSurvivorRatio=90 -Dcom.sun.management.jmxremote.port=18002 -Dcom.sun.management.jmxremote.authenticate=false -Dcom.sun.management.jmxremote.ssl=false

Any idea? Please advise.






62446.219: [GC 62446.219: [ParNew: 873856K->174720K(873856K), 0.2927771 secs] 2109161K->1491505K(4019584K), 0.2928679 secs] [Times: user=1.64 sys=0.02, real=0.30 secs]
63537.932: [GC 63537.932: [ParNew: 873856K->174720K(873856K), 0.2936245 secs] 2190641K->1573411K(4019584K), 0.2937111 secs] [Times: user=1.66 sys=0.03, real=0.31 secs]
64576.245: [GC 64576.245: [ParNew: 873856K->174720K(873856K), 0.2805543 secs] 2272547K->1652492K(4019584K), 0.2806343 secs] [Times: user=1.52 sys=0.05, real=0.28 secs]
65665.444: [GC 65665.444: [ParNew: 873856K->174720K(873856K), 0.3126828 secs] 2351628K->1733865K(4019584K), 0.3127696 secs] [Times: user=1.61 sys=0.08, real=0.31 secs]
66761.009: [GC 66761.009: [ParNew: 873856K->174720K(873856K), 0.3386468 secs] 2433001K->1815987K(4019584K), 0.3387269 secs] [Times: user=1.64 sys=0.17, real=0.36 secs]
67839.979: [GC 67839.979: [ParNew: 873856K->174720K(873856K), 0.3359659 secs] 2515123K->1897775K(4019584K), 0.3360704 secs] [Times: user=1.72 sys=0.09, real=0.34 secs]
68936.295: [GC 68936.295: [ParNew: 873856K->174720K(873856K), 0.3439460 secs] 2596911K->1979557K(4019584K), 0.3440326 secs] [Times: user=1.58 sys=0.19, real=0.34 secs]
70019.873: [GC 70019.873: [ParNew: 873856K->174720K(873856K), 0.3758143 secs] 2678693K->2065201K(4019584K), 0.3759026 secs] [Times: user=1.81 sys=0.13, real=0.38 secs]
71123.565: [GC 71123.566: [ParNew: 873856K->174719K(873856K), 0.3515356 secs] 2764337K->2147170K(4019584K), 0.3516129 secs] [Times: user=1.47 sys=0.11, real=0.34 secs]
72227.180: [GC 72227.180: [ParNew: 873855K->174720K(873856K), 0.3775019 secs] 2846306K->2230692K(4019584K), 0.3775869 secs] [Times: user=1.64 sys=0.19, real=0.38 secs]
73334.657: [GC 73334.657: [ParNew: 873856K->174719K(873856K), 0.3546221 secs] 2929828K->2313182K(4019584K), 0.3547042 secs] [Times: user=1.61 sys=0.27, real=0.36 secs]
74434.184: [GC 74434.184: [ParNew: 873855K->174720K(873856K), 0.3884261 secs] 3012318K->2395247K(4019584K), 0.3885106 secs] [Times: user=1.63 sys=0.20, real=0.39 secs]
74434.573: [GC [1 CMS-initial-mark: 2220527K(3145728K)] 2396315K(4019584K), 0.2436187 secs] [Times: user=0.25 sys=0.00, real=0.23 secs]
74434.817: [CMS-concurrent-mark-start]
74437.338: [CMS-concurrent-mark: 2.521/2.521 secs] [Times: user=5.06 sys=0.16, real=2.53 secs]
74437.338: [CMS-concurrent-preclean-start]
74437.369: [CMS-concurrent-preclean: 0.031/0.031 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
74437.374: [GC[YG occupancy: 176540 K (873856 K)]74437.374: [Rescan (parallel) , 0.1324063 secs]74437.507: [weak refs processing, 0.1494715 secs] [1 CMS-remark: 2220527K(3145728K)] 2397068K(4019584K), 0.3048030 secs] [Times: user=0.42 sys=0.00, real=0.31 secs]
74437.694: [CMS-concurrent-sweep-start]
74438.946: [CMS-concurrent-sweep: 1.248/1.252 secs] [Times: user=2.19 sys=0.05, real=1.25 secs]
74438.946: [CMS-concurrent-reset-start]
74438.961: [CMS-concurrent-reset: 0.015/0.015 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
75525.633: [GC 75525.633: [ParNew: 873856K->174719K(873856K), 0.3452037 secs] 2940674K->2323239K(4019584K), 0.3453060 secs] [Times: user=1.73 sys=0.11, real=0.34 secs]
76628.997: [GC 76628.997: [ParNew: 873855K->174720K(873856K), 0.3680628 secs] 3022375K->2405373K(4019584K), 0.3681462 secs] [Times: user=1.88 sys=0.13, real=0.38 secs]
76629.366: [GC [1 CMS-initial-mark: 2230653K(3145728K)] 2407331K(4019584K), 0.2614019 secs] [Times: user=0.27 sys=0.00, real=0.27 secs]
76629.627: [CMS-concurrent-mark-start]
76632.373: [CMS-concurrent-mark: 2.746/2.746 secs] [Times: user=5.22 sys=0.34, real=2.75 secs]
76632.373: [CMS-concurrent-preclean-start]
76632.383: [CMS-concurrent-preclean: 0.010/0.010 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
76632.391: [GC[YG occupancy: 176683 K (873856 K)]76632.391: [Rescan (parallel) , 0.1555281 secs]76632.546: [weak refs processing, 0.0003456 secs] [1 CMS-remark: 2230653K(3145728K)] 2407337K(4019584K), 0.1559517 secs] [Times: user=0.36 sys=0.00, real=0.16 secs]
76632.562: [CMS-concurrent-sweep-start]
76633.784: [CMS-concurrent-sweep: 1.222/1.222 secs] [Times: user=1.31 sys=0.00, real=1.22 secs]
76633.784: [CMS-concurrent-reset-start]
76633.799: [CMS-concurrent-reset: 0.015/0.015 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
77722.107: [GC 77722.107: [ParNew: 873856K->174719K(873856K), 0.3346014 secs] 3005732K->2390264K(4019584K), 0.3346905 secs] [Times: user=1.61 sys=0.13, real=0.33 secs]
77722.442: [GC [1 CMS-initial-mark: 2215544K(3145728K)] 2391202K(4019584K), 0.2670180 secs] [Times: user=0.28 sys=0.00, real=0.28 secs]
77722.710: [CMS-concurrent-mark-start]
77725.468: [CMS-concurrent-mark: 2.758/2.758 secs] [Times: user=5.66 sys=0.11, real=2.77 secs]
77725.468: [CMS-concurrent-preclean-start]
77725.478: [CMS-concurrent-preclean: 0.010/0.011 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
77725.478: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 77730.692: [CMS-concurrent-abortable-preclean: 0.340/5.213 secs] [Times: user=3.24 sys=0.00, real=5.22 secs]
77730.699: [GC[YG occupancy: 181794 K (873856 K)]77730.700: [Rescan (parallel) , 0.1554305 secs]77730.855: [weak refs processing, 0.0002146 secs] [1 CMS-remark: 2215544K(3145728K)] 2397339K(4019584K), 0.1557162 secs] [Times: user=0.27 sys=0.00, real=0.16 secs]
77730.870: [CMS-concurrent-sweep-start]
77732.117: [CMS-concurrent-sweep: 1.247/1.247 secs] [Times: user=1.26 sys=0.00, real=1.24 secs]
77732.117: [CMS-concurrent-reset-start]
77732.132: [CMS-concurrent-reset: 0.015/0.015 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
77734.136: [GC [1 CMS-initial-mark: 2208798K(3145728K)] 2392348K(4019584K), 0.2699426 secs] [Times: user=0.26 sys=0.00, real=0.27 secs]
77734.406: [CMS-concurrent-mark-start]
77737.261: [CMS-concurrent-mark: 2.851/2.856 secs] [Times: user=5.27 sys=0.34, real=2.86 secs]
77737.261: [CMS-concurrent-preclean-start]
77737.272: [CMS-concurrent-preclean: 0.010/0.010 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
77737.272: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 77742.481: [CMS-concurrent-abortable-preclean: 0.339/5.209 secs] [Times: user=3.30 sys=0.00, real=5.22 secs]
77742.487: [GC[YG occupancy: 191586 K (873856 K)]77742.487: [Rescan (parallel) , 0.1631453 secs]77742.651: [weak refs processing, 0.0001524 secs] [1 CMS-remark: 2208798K(3145728K)] 2400385K(4019584K), 0.1633895 secs] [Times: user=0.28 sys=0.00, real=0.17 secs]
77742.666: [CMS-concurrent-sweep-start]
77743.864: [CMS-concurrent-sweep: 1.198/1.198 secs] [Times: user=1.22 sys=0.00, real=1.20 secs]
77743.864: [CMS-concurrent-reset-start]
77743.879: [CMS-concurrent-reset: 0.015/0.015 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
77745.883: [GC [1 CMS-initial-mark: 2203641K(3145728K)] 2398172K(4019584K), 0.2750780 secs] [Times: user=0.25 sys=0.00, real=0.27 secs]
77746.159: [CMS-concurrent-mark-start]
77748.880: [CMS-concurrent-mark: 2.721/2.721 secs] [Times: user=5.36 sys=0.09, real=2.73 secs]
77748.880: [CMS-concurrent-preclean-start]
77748.890: [CMS-concurrent-preclean: 0.010/0.010 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
77748.890: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 77754.112: [CMS-concurrent-abortable-preclean: 0.467/5.222 secs] [Times: user=3.33 sys=0.00, real=5.23 secs]
77754.118: [GC[YG occupancy: 197250 K (873856 K)]77754.118: [Rescan (parallel) , 0.1562518 secs]77754.274: [weak refs processing, 0.0001109 secs] [1 CMS-remark: 2203641K(3145728K)] 2400891K(4019584K), 0.1564752 secs] [Times: user=0.36 sys=0.00, real=0.17 secs]
77754.290: [CMS-concurrent-sweep-start]
77755.425: [CMS-concurrent-sweep: 1.135/1.135 secs] [Times: user=1.14 sys=0.00, real=1.14 secs]
77755.425: [CMS-concurrent-reset-start]
77755.441: [CMS-concurrent-reset: 0.016/0.016 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
77757.445: [GC [1 CMS-initial-mark: 2203641K(3145728K)] 2405052K(4019584K), 0.2801865 secs] [Times: user=0.26 sys=0.00, real=0.28 secs]
77757.725: [CMS-concurrent-mark-start]
77760.493: [CMS-concurrent-mark: 2.768/2.768 secs] [Times: user=5.52 sys=0.11, real=2.80 secs]
77760.493: [CMS-concurrent-preclean-start]
77760.504: [CMS-concurrent-preclean: 0.010/0.010 secs] [Times: user=0.02 sys=0.00, real=0.00 secs]
77760.504: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 77765.719: [CMS-concurrent-abortable-preclean: 0.339/5.216 secs] [Times: user=3.23 sys=0.03, real=5.22 secs]
77765.725: [GC[YG occupancy: 203843 K (873856 K)]77765.725: [Rescan (parallel) , 0.1573253 secs]77765.883: [weak refs processing, 0.0000936 secs] [1 CMS-remark: 2203641K(3145728K)] 2407484K(4019584K), 0.1575000 secs] [Times: user=0.38 sys=0.00, real=0.17 secs]
77765.898: [CMS-concurrent-sweep-start]
77767.132: [CMS-concurrent-sweep: 1.234/1.234 secs] [Times: user=1.25 sys=0.00, real=1.23 secs]
77767.132: [CMS-concurrent-reset-start]
77767.147: [CMS-concurrent-reset: 0.015/0.015 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
77769.151: [GC [1 CMS-initial-mark: 2203641K(3145728K)] 2409821K(4019584K), 0.2889787 secs] [Times: user=0.26 sys=0.00, real=0.28 secs]
77769.440: [CMS-concurrent-mark-start]
77772.168: [CMS-concurrent-mark: 2.728/2.728 secs] [Times: user=5.36 sys=0.13, real=2.75 secs]
77772.168: [CMS-concurrent-preclean-start]
77772.178: [CMS-concurrent-preclean: 0.010/0.010 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
77772.178: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 77777.294: [CMS-concurrent-abortable-preclean: 0.344/5.116 secs] [Times: user=3.39 sys=0.00, real=5.13 secs]
77777.302: [GC[YG occupancy: 218737 K (873856 K)]77777.302: [Rescan (parallel) , 0.1573837 secs]77777.460: [weak refs processing, 0.0000945 secs] [1 CMS-remark: 2203641K(3145728K)] 2422379K(4019584K), 0.1575605 secs] [Times: user=0.39 sys=0.00, real=0.17 secs]
77777.475: [CMS-concurrent-sweep-start]
77778.609: [CMS-concurrent-sweep: 1.134/1.134 secs] [Times: user=1.14 sys=0.00, real=1.14 secs]
77778.609: [CMS-concurrent-reset-start]
77778.625: [CMS-concurrent-reset: 0.015/0.015 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
77780.628: [GC [1 CMS-initial-mark: 2203641K(3145728K)] 2424717K(4019584K), 0.2928494 secs] [Times: user=0.28 sys=0.00, real=0.30 secs]
77780.921: [CMS-concurrent-mark-start]
77783.638: [CMS-concurrent-mark: 2.717/2.717 secs] [Times: user=5.33 sys=0.13, real=2.73 secs]
77783.638: [CMS-concurrent-preclean-start]
77783.654: [CMS-concurrent-preclean: 0.016/0.016 secs] [Times: user=0.01 sys=0.00, real=0.02 secs]
77783.654: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 77788.832: [CMS-concurrent-abortable-preclean: 0.386/5.178 secs] [Times: user=3.36 sys=0.00, real=5.19 secs]
77788.840: [GC[YG occupancy: 226606 K (873856 K)]77788.840: [Rescan (parallel) , 0.1651500 secs]77789.005: [weak refs processing, 0.0000958 secs] [1 CMS-remark: 2203641K(3145728K)] 2430247K(4019584K), 0.1653619 secs] [Times: user=0.30 sys=0.00, real=0.17 secs]
77789.021: [CMS-concurrent-sweep-start]
77790.051: [CMS-concurrent-sweep: 1.031/1.031 secs] [Times: user=1.05 sys=0.00, real=1.03 secs]
77790.051: [CMS-concurrent-reset-start]
77790.067: [CMS-concurrent-reset: 0.015/0.015 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
77792.070: [GC [1 CMS-initial-mark: 2203641K(3145728K)] 2430289K(4019584K), 0.2979185 secs] [Times: user=0.28 sys=0.00, real=0.30 secs]
77792.368: [CMS-concurrent-mark-start]
77795.085: [CMS-concurrent-mark: 2.717/2.717 secs] [Times: user=5.34 sys=0.20, real=2.72 secs]
77795.085: [CMS-concurrent-preclean-start]
77795.095: [CMS-concurrent-preclean: 0.010/0.010 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
77795.095: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 77800.269: [CMS-concurrent-abortable-preclean: 0.484/5.174 secs] [Times: user=3.28 sys=0.00, real=5.17 secs]
77800.275: [GC[YG occupancy: 233897 K (873856 K)]77800.275: [Rescan (parallel) , 0.1660870 secs]77800.442: [weak refs processing, 0.0001040 secs] [1 CMS-remark: 2203641K(3145728K)] 2437538K(4019584K), 0.1662851 secs] [Times: user=0.31 sys=0.00, real=0.17 secs]
77800.457: [CMS-concurrent-sweep-start]
77801.459: [CMS-concurrent-sweep: 1.002/1.002 secs] [Times: user=1.06 sys=0.00, real=1.00 secs]
77801.459: [CMS-concurrent-reset-start]
77801.474: [CMS-concurrent-reset: 0.015/0.015 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
77803.477: [GC [1 CMS-initial-mark: 2203641K(3145728K)] 2438755K(4019584K), 0.3026378 secs] [Times: user=0.30 sys=0.00, real=0.30 secs]
77803.780: [CMS-concurrent-mark-start]
77806.515: [CMS-concurrent-mark: 2.735/2.735 secs] [Times: user=5.41 sys=0.11, real=2.73 secs]
77806.515: [CMS-concurrent-preclean-start]
77806.525: [CMS-concurrent-preclean: 0.010/0.010 secs] [Times: user=0.00 sys=0.00, real=0.02 secs]
77806.525: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 77811.723: [CMS-concurrent-abortable-preclean: 0.374/5.197 secs] [Times: user=3.33 sys=0.00, real=5.22 secs]
77811.726: [GC[YG occupancy: 237551 K (873856 K)]77811.726: [Rescan (parallel) , 0.1518526 secs]77811.878: [weak refs processing, 0.0000969 secs] [1 CMS-remark: 2203641K(3145728K)] 2441193K(4019584K), 0.1520584 secs] [Times: user=0.38 sys=0.00, real=0.16 secs]
77811.893: [CMS-concurrent-sweep-start]
77812.890: [CMS-concurrent-sweep: 0.997/0.997 secs] [Times: user=1.08 sys=0.00, real=1.00 secs]
77812.890: [CMS-concurrent-reset-start]
77812.905: [CMS-concurrent-reset: 0.015/0.015 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
77814.909: [GC [1 CMS-initial-mark: 2203641K(3145728K)] 2445359K(4019584K), 0.3071683 secs] [Times: user=0.28 sys=0.00, real=0.30 secs]
77815.216: [CMS-concurrent-mark-start]
77817.955: [CMS-concurrent-mark: 2.739/2.739 secs] [Times: user=5.33 sys=0.13, real=2.75 secs]
77817.955: [CMS-concurrent-preclean-start]
77817.965: [CMS-concurrent-preclean: 0.010/0.010 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]
77817.965: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 77823.178: [CMS-concurrent-abortable-preclean: 0.482/5.213 secs] [Times: user=3.27 sys=0.00, real=5.20 secs]
77823.184: [GC[YG occupancy: 243681 K (873856 K)]77823.184: [Rescan (parallel) , 0.1612718 secs]77823.345: [weak refs processing, 0.0001191 secs] [1 CMS-remark: 2203641K(3145728K)] 2447322K(4019584K), 0.1615056 secs] [Times: user=0.31 sys=0.00, real=0.17 secs]
77823.361: [CMS-concurrent-sweep-start]
77824.356: [CMS-concurrent-sweep: 0.995/0.995 secs] [Times: user=1.08 sys=0.00, real=1.00 secs]
77824.356: [CMS-concurrent-reset-start]
77824.371: [CMS-concurrent-reset: 0.015/0.015 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
77825.194: [GC [1 CMS-initial-mark: 2203641K(3145728K)] 2449146K(4019584K), 0.3122333 secs] [Times: user=0.30 sys=0.00, real=0.31 secs]
77825.506: [CMS-concurrent-mark-start]
77828.241: [CMS-concurrent-mark: 2.735/2.735 secs] [Times: user=5.31 sys=0.17, real=2.73 secs]
77828.241: [CMS-concurrent-preclean-start]
77828.252: [CMS-concurrent-preclean: 0.010/0.010 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
77828.252: [CMS-concurrent-abortable-preclean-start]

 « Return to Thread: CMS collection keep working during holiday