You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@cassandra.apache.org by Rene Kochen <re...@schange.com> on 2012/08/16 16:58:50 UTC
Many ParNew collections
Hi
I have a cluster of 7 nodes:
- Windows Server 2008
- Cassandra 0.7.10
- The nodes are identical (hardware, configuration and client request load)
- Standard batch file with 8GB heap
- I use disk_access_mode = standard
- Random partitioner
- TP stats shows no problems
- Ring command shows no problems (data is balanced)
However, there is one node with high read latency and far too many
ParNew collections (compared to other nodes). It also suffers from a
high CPU load (I guess due to the ParNew collections).
What can be the source of so many ParNew collections? The other
identical nodes do not have this behavior.
Logging:
2012-08-16 15:58:46,436906.072: [GC 906.072: [ParNew:
345022K->38336K(345024K), 0.2375976 secs]
3630599K->3516249K(8350272K), 0.2377296 secs] [Times: user=3.21
sys=0.00, real=0.23 secs]
2012-08-16 15:58:46,888906.517: [GC 906.517: [ParNew:
345024K->38336K(345024K), 0.2400594 secs]
3822937K->3743690K(8350272K), 0.2401802 secs] [Times: user=3.48
sys=0.03, real=0.25 secs]
2012-08-16 15:58:46,888 INFO 15:58:46,888 GC for ParNew: 478 ms for 2
collections, 3837792904 used; max is 8550678528
2012-08-16 15:58:47,372907.003: [GC 907.003: [ParNew:
345024K->38336K(345024K), 0.2405363 secs]
4050378K->3971544K(8350272K), 0.2406553 secs] [Times: user=3.34
sys=0.01, real=0.23 secs]
2012-08-16 15:58:47,918907.544: [GC 907.544: [ParNew:
345024K->38336K(345024K), 0.2404339 secs]
4278232K->4193789K(8350272K), 0.2405540 secs] [Times: user=3.31
sys=0.00, real=0.25 secs]
2012-08-16 15:58:47,918 INFO 15:58:47,918 GC for ParNew: 481 ms for 2
collections, 4300939752 used; max is 8550678528
2012-08-16 15:58:48,464908.079: [GC 908.079: [ParNew:
345024K->38336K(345024K), 0.2621174 secs]
4500477K->4434112K(8350272K), 0.2622375 secs] [Times: user=3.64
sys=0.00, real=0.25 secs]
2012-08-16 15:58:48,932 INFO 15:58:48,932 GC for ParNew: 262 ms for 1
collections, 4763583200 used; max is 8550678528
2012-08-16 15:58:49,384909.050: [GC 909.051: [ParNew:
344972K->38336K(345024K), 0.2033453 secs]
4740748K->4563252K(8350272K), 0.2034588 secs] [Times: user=2.89
sys=0.01, real=0.20 secs]
2012-08-16 15:58:49,946 INFO 15:58:49,946 GC for ParNew: 203 ms for 1
collections, 4885945792 used; max is 8550678528
2012-08-16 15:58:50,383909.998: [GC 909.998: [ParNew:
345024K->38336K(345024K), 0.2567542 secs]
4869940K->4740489K(8350272K), 0.2568804 secs] [Times: user=3.60
sys=0.00, real=0.25 secs]
2012-08-16 15:58:50,882910.474: [GC 910.474: [ParNew:
345024K->38336K(345024K), 0.2786205 secs]
5047177K->4962531K(8350272K), 0.2787668 secs] [Times: user=3.48
sys=0.00, real=0.28 secs]
2012-08-16 15:58:50,960 INFO 15:58:50,960 GC for ParNew: 536 ms for 2
collections, 5143423816 used; max is 8550678528
2012-08-16 15:58:51,584911.192: [GC 911.192: [ParNew:
344963K->38334K(345024K), 0.2664316 secs]
5269158K->5196444K(8350272K), 0.2665544 secs] [Times: user=3.74
sys=0.00, real=0.27 secs]
2012-08-16 15:58:52,130911.767: [GC 911.767: [ParNew:
345022K->38336K(345024K), 0.2327209 secs]
5503132K->5406771K(8350272K), 0.2328457 secs] [Times: user=3.35
sys=0.00, real=0.23 secs]
2012-08-16 15:58:52,130 INFO 15:58:52,130 GC for ParNew: 499 ms for 2
collections, 5541845264 used; max is 8550678528
2012-08-16 15:58:52,816912.460: [GC 912.460: [ParNew:
345024K->38334K(345024K), 0.2198399 secs]
5713459K->5605670K(8350272K), 0.2199669 secs] [Times: user=3.29
sys=0.00, real=0.23 secs]
2012-08-16 15:58:53,144 INFO 15:58:53,144 GC for ParNew: 220 ms for 1
collections, 5805870608 used; max is 8550678528
2012-08-16 15:58:55,546915.173: [GC 915.173: [ParNew:
345022K->38334K(345024K), 0.2369585 secs]
5912358K->5702871K(8350272K), 0.2371098 secs] [Times: user=3.18
sys=0.00, real=0.25 secs]
2012-08-16 15:58:56,186 INFO 15:58:56,186 GC for ParNew: 237 ms for 1
collections, 6089002480 used; max is 8550678528
2012-08-16 15:58:56,591916.232: [GC 916.232: [ParNew:
345022K->38336K(345024K), 0.2364850 secs]
6009559K->5914142K(8350272K), 0.2366075 secs] [Times: user=3.32
sys=0.00, real=0.23 secs]
2012-08-16 15:58:57,340916.989: [GC 916.989: [ParNew:
345024K->38334K(345024K), 0.2191751 secs]
6220830K->6107217K(8350272K), 0.2192894 secs] [Times: user=2.92
sys=0.00, real=0.22 secs]
2012-08-16 15:58:57,371917.209: [GC [1 CMS-initial-mark:
6068883K(8005248K)] 6108716K(8350272K), 0.0272472 secs] [Times:
user=0.03 sys=0.00, real=0.03 secs]
2012-08-16 15:58:57,371917.236: [CMS-concurrent-mark-start]
2012-08-16 15:58:57,371 INFO 15:58:57,371 GC for ParNew: 456 ms for 2
collections, 6255865264 used; max is 8550678528
2012-08-16 15:58:57,574917.444: [CMS-concurrent-mark: 0.208/0.208
secs] [Times: user=1.48 sys=0.06, real=0.20 secs]
2012-08-16 15:58:57,574917.444: [CMS-concurrent-preclean-start]
2012-08-16 15:58:57,637917.501: [CMS-concurrent-preclean: 0.057/0.057
secs] [Times: user=0.19 sys=0.00, real=0.06 secs]
2012-08-16 15:58:57,637917.501: [CMS-concurrent-abortable-preclean-start]
2012-08-16 15:58:58,775918.552: [GC 918.552: [ParNew:
345022K->38334K(345024K), 0.0948325 secs]
6413905K->6163063K(8350272K), 0.0949661 secs] [Times: user=1.22
sys=0.00, real=0.09 secs]
2012-08-16 15:58:59,025918.896: [CMS-concurrent-abortable-preclean:
1.198/1.395 secs] [Times: user=5.26 sys=0.17, real=1.39 secs]
2012-08-16 15:58:59,072918.896: [GC[YG occupancy: 274623 K (345024
K)]918.896: [Rescan (parallel) , 0.0427564 secs]918.939: [weak refs
processing, 0.0000096 secs] [1 CMS-remark: 6124729K(8005248K)]
6399352K(8350272K), 0.0428734 secs] [Times: user=0.62 sys=0.00,
real=0.05 secs]
2012-08-16 15:58:59,072918.939: [CMS-concurrent-sweep-start]
2012-08-16 15:58:59,368918.972: [GC 918.972: [ParNew:
345022K->38336K(345024K), 0.2652648 secs]
6465380K->6379989K(8350272K), 0.2654014 secs] [Times: user=3.71
sys=0.00, real=0.27 secs]
2012-08-16 15:58:59,930919.557: [GC 919.557: [ParNew:
345024K->38334K(345024K), 0.2417524 secs]
6433484K->6347081K(8350272K), 0.2418748 secs] [Times: user=3.40
sys=0.00, real=0.25 secs]
2012-08-16 15:59:00,507920.161: [GC 920.162: [ParNew:
345015K->38334K(345024K), 0.2142607 secs]
6191692K->6086072K(8350272K), 0.2143766 secs] [Times: user=3.09
sys=0.00, real=0.22 secs]
2012-08-16 15:59:00,507 INFO 15:59:00,507 GC for ParNew: 456 ms for 2
collections, 6233109512 used; max is 8550678528
2012-08-16 15:59:01,022920.633: [GC 920.633: [ParNew:
345022K->38336K(345024K), 0.2590327 secs]
6140813K->6065694K(8350272K), 0.2591528 secs] [Times: user=3.67
sys=0.00, real=0.27 secs]
2012-08-16 15:59:01,521 INFO 15:59:01,521 GC for ParNew: 259 ms for 1
collections, 5916301064 used; max is 8550678528
2012-08-16 15:59:01,942921.604: [GC 921.604: [ParNew:
345001K->38334K(345024K), 0.2059791 secs]
5576624K->5407950K(8350272K), 0.2060935 secs] [Times: user=3.07
sys=0.00, real=0.20 secs]
2012-08-16 15:59:02,535 INFO 15:59:02,535 GC for ParNew: 206 ms for 1
collections, 4951508912 used; max is 8550678528
2012-08-16 15:59:06,185925.865: [GC 925.865: [ParNew:
345022K->38334K(345024K), 0.1944824 secs]
2207361K->2034487K(8350272K), 0.1946014 secs] [Times: user=2.54
sys=0.00, real=0.19 secs]
2012-08-16 15:59:06,747926.624: [CMS-concurrent-sweep: 6.301/7.685
secs] [Times: user=36.33 sys=0.37, real=7.67 secs]
2012-08-16 15:59:06,747926.624: [CMS-concurrent-reset-start]
2012-08-16 15:59:06,778926.644: [CMS-concurrent-reset: 0.020/0.020
secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
2012-08-16 15:59:07,699927.442: [GC 927.442: [ParNew:
345022K->38336K(345024K), 0.1241401 secs]
2087777K->1881732K(8350272K), 0.1242536 secs] [Times: user=1.47
sys=0.00, real=0.13 secs]
2012-08-16 15:59:10,241929.912: [GC 929.912: [ParNew:
345024K->38334K(345024K), 0.1987855 secs]
2188420K->2049927K(8350272K), 0.1989237 secs] [Times: user=2.73
sys=0.00, real=0.20 secs]
2012-08-16 15:59:10,912930.557: [GC 930.558: [ParNew:
345022K->38336K(345024K), 0.2269435 secs]
2356615K->2253199K(8350272K), 0.2270702 secs] [Times: user=2.98
sys=0.00, real=0.22 secs]
2012-08-16 15:59:10,912 INFO 15:59:10,912 GC for ParNew: 426 ms for 2
collections, 2312471792 used; max is 8550678528
2012-08-16 15:59:11,521931.148: [GC 931.148: [ParNew:
345024K->38334K(345024K), 0.2371360 secs]
2559887K->2475870K(8350272K), 0.2372526 secs] [Times: user=3.10
sys=0.00, real=0.25 secs]
2012-08-16 15:59:11,926 INFO 15:59:11,926 GC for ParNew: 237 ms for 1
collections, 2763895872 used; max is 8550678528
2012-08-16 15:59:12,441932.137: [GC 932.137: [ParNew:
345022K->38336K(345024K), 0.1733826 secs]
2782558K->2622114K(8350272K), 0.1735015 secs] [Times: user=2.42
sys=0.02, real=0.17 secs]
2012-08-16 15:59:13,549933.155: [GC 933.155: [ParNew:
345024K->38334K(345024K), 0.2625127 secs]
2928802K->2829867K(8350272K), 0.2626344 secs] [Times: user=3.77
sys=0.00, real=0.27 secs]
2012-08-16 15:59:14,188933.808: [GC 933.808: [ParNew:
345022K->38334K(345024K), 0.2505625 secs]
3136555K->3054091K(8350272K), 0.2506795 secs] [Times: user=3.46
sys=0.00, real=0.25 secs]
2012-08-16 15:59:14,188 INFO 15:59:14,188 GC for ParNew: 513 ms for 2
collections, 3134992208 used; max is 8550678528
2012-08-16 15:59:14,890934.522: [GC 934.523: [ParNew:
345022K->38336K(345024K), 0.2316504 secs]
3360779K->3275423K(8350272K), 0.2317766 secs] [Times: user=3.13
sys=0.00, real=0.23 secs]
2012-08-16 15:59:15,202 INFO 15:59:15,202 GC for ParNew: 232 ms for 1
collections, 3536955232 used; max is 8550678528
2012-08-16 15:59:15,920935.625: [GC 935.625: [ParNew:
345024K->38334K(345024K), 0.1714062 secs]
3582111K->3415888K(8350272K), 0.1715367 secs] [Times: user=2.54
sys=0.00, real=0.17 secs]
2012-08-16 15:59:16,513936.119: [GC 936.119: [ParNew:
345022K->38334K(345024K), 0.2719661 secs]
3722576K->3649948K(8350272K), 0.2720966 secs] [Times: user=3.74
sys=0.00, real=0.27 secs]
2012-08-16 15:59:17,059936.685: [GC 936.685: [ParNew:
345022K->38336K(345024K), 0.2452667 secs]
3956636K->3871076K(8350272K), 0.2453914 secs] [Times: user=3.62
sys=0.00, real=0.25 secs]
2012-08-16 15:59:17,230 INFO 15:59:17,230 GC for ParNew: 517 ms for 2
collections, 4081462864 used; max is 8550678528
2012-08-16 15:59:17,651937.255: [GC 937.255: [ParNew:
345024K->38334K(345024K), 0.2594023 secs]
4177764K->4099640K(8350272K), 0.2595243 secs] [Times: user=3.49
sys=0.01, real=0.27 secs]
2012-08-16 15:59:18,213937.825: [GC 937.825: [ParNew:
345022K->38336K(345024K), 0.2584561 secs]
4406328K->4332694K(8350272K), 0.2585750 secs] [Times: user=3.74
sys=0.00, real=0.27 secs]
2012-08-16 15:59:18,244 INFO 15:59:18,244 GC for ParNew: 518 ms for 2
collections, 4451788480 used; max is 8550678528
2012-08-16 15:59:19,165938.841: [GC 938.841: [ParNew:
344991K->38334K(345024K), 0.1994641 secs]
4639350K->4482568K(8350272K), 0.1995789 secs] [Times: user=2.56
sys=0.01, real=0.19 secs]
2012-08-16 15:59:25,717945.440: [GC 945.440: [ParNew:
344963K->38334K(345024K), 0.1440731 secs]
4789197K->4538905K(8350272K), 0.1442125 secs] [Times: user=1.61
sys=0.00, real=0.14 secs]
2012-08-16 15:59:26,372945.966: [GC 945.966: [ParNew:
345022K->38336K(345024K), 0.2803466 secs]
4845593K->4785922K(8350272K), 0.2804798 secs] [Times: user=3.92
sys=0.00, real=0.28 secs]
2012-08-16 15:59:26,372 INFO 15:59:26,372 GC for ParNew: 425 ms for 2
collections, 4903116472 used; max is 8550678528
2012-08-16 15:59:26,965946.589: [GC 946.589: [ParNew:
345024K->38336K(345024K), 0.2496506 secs]
5092610K->5017752K(8350272K), 0.2497695 secs] [Times: user=3.60
sys=0.00, real=0.25 secs]
2012-08-16 15:59:27,526947.149: [GC 947.149: [ParNew:
345024K->38336K(345024K), 0.2427009 secs]
5324440K->5242855K(8350272K), 0.2428195 secs] [Times: user=3.21
sys=0.00, real=0.25 secs]
2012-08-16 15:59:27,526 INFO 15:59:27,526 GC for ParNew: 492 ms for 2
collections, 5374819504 used; max is 8550678528
2012-08-16 15:59:28,088947.717: [GC 947.717: [ParNew:
345024K->38336K(345024K), 0.2467160 secs]
5549543K->5469437K(8350272K), 0.2468315 secs] [Times: user=3.39
sys=0.00, real=0.23 secs]
2012-08-16 15:59:28,540 INFO 15:59:28,540 GC for ParNew: 247 ms for 1
collections, 5756868992 used; max is 8550678528
2012-08-16 15:59:29,195948.871: [GC 948.871: [ParNew:
345024K->38334K(345024K), 0.1934754 secs]
5776125K->5599289K(8350272K), 0.1935862 secs] [Times: user=2.70
sys=0.00, real=0.20 secs]
2012-08-16 15:59:29,710949.316: [GC 949.316: [ParNew:
345022K->38334K(345024K), 0.2601060 secs]
5905977K->5828882K(8350272K), 0.2602222 secs] [Times: user=3.46
sys=0.00, real=0.27 secs]
2012-08-16 15:59:29,710 INFO 15:59:29,710 GC for ParNew: 454 ms for 2
collections, 5975471248 used; max is 8550678528
2012-08-16 15:59:30,194949.830: [GC 949.830: [ParNew:
345022K->38336K(345024K), 0.2380811 secs]
6135570K->6042546K(8350272K), 0.2382000 secs] [Times: user=3.14
sys=0.00, real=0.23 secs]
2012-08-16 15:59:30,225950.069: [GC [1 CMS-initial-mark:
6004210K(8005248K)] 6042548K(8350272K), 0.0260419 secs] [Times:
user=0.03 sys=0.00, real=0.03 secs]
2012-08-16 15:59:30,225950.095: [CMS-concurrent-mark-start]
2012-08-16 15:59:30,443950.316: [CMS-concurrent-mark: 0.221/0.221
secs] [Times: user=2.06 sys=0.13, real=0.22 secs]
2012-08-16 15:59:30,443950.316: [CMS-concurrent-preclean-start]
2012-08-16 15:59:30,459950.336: [CMS-concurrent-preclean: 0.020/0.020
secs] [Times: user=0.06 sys=0.01, real=0.02 secs]
2012-08-16 15:59:30,459950.336: [CMS-concurrent-abortable-preclean-start]
2012-08-16 15:59:30,818950.463: [GC 950.463: [ParNew:
345024K->38336K(345024K), 0.2228510 secs]
6349234K->6252442K(8350272K), 0.2229688 secs] [Times: user=3.14
sys=0.00, real=0.22 secs]
2012-08-16 15:59:30,818 INFO 15:59:30,818 GC for ParNew: 461 ms for 2
collections, 6406860032 used; max is 8550678528
2012-08-16 15:59:31,395950.997: [GC 950.997: [ParNew:
345024K->38336K(345024K), 0.2692564 secs]
6559130K->6493591K(8350272K), 0.2693750 secs] [Times: user=3.81
sys=0.00, real=0.26 secs]
2012-08-16 15:59:31,707951.580: [CMS-concurrent-abortable-preclean:
0.750/1.245 secs] [Times: user=10.84 sys=0.13, real=1.25 secs]
2012-08-16 15:59:31,723951.581: [GC[YG occupancy: 190327 K (345024
K)]951.581: [Rescan (parallel) , 0.0126204 secs]951.593: [weak refs
processing, 0.0000085 secs] [1 CMS-remark: 6455255K(8005248K)]
6645582K(8350272K), 0.0127259 secs] [Times: user=0.28 sys=0.00,
real=0.02 secs]
2012-08-16 15:59:31,723951.593: [CMS-concurrent-sweep-start]
2012-08-16 15:59:31,832 INFO 15:59:31,832 GC for ParNew: 269 ms for 1
collections, 6764806360 used; max is 8550678528
2012-08-16 15:59:32,362952.030: [GC 952.030: [ParNew:
345024K->38334K(345024K), 0.1960234 secs]
6293501K->6126054K(8350272K), 0.1961435 secs] [Times: user=2.89
sys=0.02, real=0.20 secs]
2012-08-16 15:59:35,685955.406: [GC 955.406: [ParNew:
345006K->38336K(345024K), 0.1556453 secs]
2927846K->2691941K(8350272K), 0.1557619 secs] [Times: user=2.39
sys=0.02, real=0.16 secs]
2012-08-16 15:59:36,325955.902: [GC 955.902: [ParNew:
345024K->38334K(345024K), 0.2880415 secs]
2887108K->2831437K(8350272K), 0.2881643 secs] [Times: user=4.04
sys=0.00, real=0.30 secs]
2012-08-16 15:59:36,902956.561: [GC 956.561: [ParNew:
345022K->38334K(345024K), 0.2172772 secs]
2933661K->2836344K(8350272K), 0.2173954 secs] [Times: user=3.04
sys=0.00, real=0.22 secs]
2012-08-16 15:59:36,902 INFO 15:59:36,902 GC for ParNew: 505 ms for 2
collections, 2909226128 used; max is 8550678528
2012-08-16 15:59:37,573957.194: [GC 957.194: [ParNew:
345022K->38336K(345024K), 0.2457267 secs]
2835640K->2761950K(8350272K), 0.2458564 secs] [Times: user=3.43
sys=0.00, real=0.25 secs]
2012-08-16 15:59:38,087957.692: [GC 957.692: [ParNew:
345024K->38334K(345024K), 0.2580753 secs]
2883419K->2810105K(8350272K), 0.2581927 secs] [Times: user=3.43
sys=0.00, real=0.25 secs]
2012-08-16 15:59:38,087 INFO 15:59:38,087 GC for ParNew: 504 ms for 2
collections, 2883187080 used; max is 8550678528
2012-08-16 15:59:39,273958.942: [GC 958.942: [ParNew:
345022K->38336K(345024K), 0.1964326 secs]
2691229K->2515113K(8350272K), 0.1965519 secs] [Times: user=2.87
sys=0.00, real=0.20 secs]
2012-08-16 15:59:39,694959.568: [CMS-concurrent-sweep: 6.414/7.975
secs] [Times: user=44.04 sys=0.72, real=7.97 secs]
2012-08-16 15:59:39,694959.568: [CMS-concurrent-reset-start]
2012-08-16 15:59:39,725959.590: [CMS-concurrent-reset: 0.022/0.022
secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
2012-08-16 15:59:41,956961.725: [GC 961.725: [ParNew:
344994K->38334K(345024K), 0.0970048 secs]
2645182K->2381114K(8350272K), 0.0971442 secs] [Times: user=0.92
sys=0.00, real=0.09 secs]
2012-08-16 15:59:46,043965.815: [GC 965.816: [ParNew:
345022K->38336K(345024K), 0.0998408 secs]
2687802K->2449434K(8350272K), 0.0999933 secs] [Times: user=1.08
sys=0.02, real=0.09 secs]
2012-08-16 15:59:46,511966.115: [GC 966.115: [ParNew:
344629K->38336K(345024K), 0.2663284 secs]
2755727K->2687941K(8350272K), 0.2664512 secs] [Times: user=3.46
sys=0.00, real=0.26 secs]
2012-08-16 15:59:47,089966.709: [GC 966.709: [ParNew:
344990K->38336K(345024K), 0.2430397 secs]
2994595K->2921799K(8350272K), 0.2431602 secs] [Times: user=3.40
sys=0.02, real=0.25 secs]
2012-08-16 15:59:47,681967.293: [GC 967.293: [ParNew:
345024K->38336K(345024K), 0.2527240 secs]
3228487K->3156972K(8350272K), 0.2528499 secs] [Times: user=3.45
sys=0.00, real=0.27 secs]
2012-08-16 15:59:47,681 INFO 15:59:47,681 GC for ParNew: 496 ms for 2
collections, 3235405952 used; max is 8550678528
2012-08-16 15:59:48,415968.061: [GC 968.061: [ParNew:
345024K->38336K(345024K), 0.2184791 secs]
3463660K->3348605K(8350272K), 0.2185973 secs] [Times: user=2.87
sys=0.00, real=0.22 secs]
2012-08-16 15:59:48,695 INFO 15:59:48,695 GC for ParNew: 219 ms for 1
collections, 3493343744 used; max is 8550678528
2012-08-16 15:59:49,631969.245: [GC 969.245: [ParNew:
345024K->38336K(345024K), 0.2571372 secs]
3655293K->3536159K(8350272K), 0.2572561 secs] [Times: user=3.67
sys=0.00, real=0.25 secs]
2012-08-16 15:59:49,709 INFO 15:59:49,709 GC for ParNew: 257 ms for 1
collections, 3726925432 used; max is 8550678528
2012-08-16 15:59:50,162969.766: [GC 969.766: [ParNew:
345024K->38334K(345024K), 0.2653560 secs]
3842847K->3774598K(8350272K), 0.2654692 secs] [Times: user=3.90
sys=0.00, real=0.26 secs]
2012-08-16 15:59:50,723970.347: [GC 970.347: [ParNew:
345022K->38336K(345024K), 0.2484206 secs]
4081286K->4008970K(8350272K), 0.2485346 secs] [Times: user=3.56
sys=0.00, real=0.25 secs]
2012-08-16 15:59:50,723 INFO 15:59:50,723 GC for ParNew: 514 ms for 2
collections, 4110795240 used; max is 8550678528
2012-08-16 15:59:51,363970.965: [GC 970.965: [ParNew:
345024K->38334K(345024K), 0.2646304 secs]
4315658K->4258131K(8350272K), 0.2647516 secs] [Times: user=3.67
sys=0.00, real=0.26 secs]
2012-08-16 15:59:51,737 INFO 15:59:51,737 GC for ParNew: 264 ms for 1
collections, 4581460088 used; max is 8550678528
2012-08-16 15:59:52,299971.961: [GC 971.961: [ParNew:
345022K->38334K(345024K), 0.2041610 secs]
4564819K->4427702K(8350272K), 0.2042765 secs] [Times: user=2.62
sys=0.00, real=0.20 secs]
2012-08-16 15:59:52,751 INFO 15:59:52,751 GC for ParNew: 205 ms for 1
collections, 4640258968 used; max is 8550678528
2012-08-16 15:59:55,669975.335: [GC 975.335: [ParNew:
345022K->38336K(345024K), 0.2031359 secs]
4734390K->4513398K(8350272K), 0.2032737 secs] [Times: user=2.67
sys=0.00, real=0.20 secs]
2012-08-16 15:59:55,793 INFO 15:59:55,793 GC for ParNew: 203 ms for 1
collections, 4637851352 used; max is 8550678528
2012-08-16 15:59:56,495976.118: [GC 976.118: [ParNew:
345024K->38334K(345024K), 0.2428765 secs]
4820086K->4719356K(8350272K), 0.2430081 secs] [Times: user=3.40
sys=0.00, real=0.25 secs]
2012-08-16 15:59:56,963976.598: [GC 976.598: [ParNew:
345022K->38336K(345024K), 0.2291020 secs]
5026044K->4940991K(8350272K), 0.2292186 secs] [Times: user=3.35
sys=0.02, real=0.23 secs]
2012-08-16 15:59:56,963 INFO 15:59:56,963 GC for ParNew: 472 ms for 2
collections, 5061091520 used; max is 8550678528
2012-08-16 15:59:57,478977.138: [GC 977.138: [ParNew:
345024K->38334K(345024K), 0.2138650 secs]
5247679K->5145409K(8350272K), 0.2139793 secs] [Times: user=2.79
sys=0.00, real=0.20 secs]
2012-08-16 15:59:58,024977.628: [GC 977.628: [ParNew:
345022K->38334K(345024K), 0.2597949 secs]
5452097K->5382216K(8350272K), 0.2599123 secs] [Times: user=3.49
sys=0.00, real=0.26 secs]
2012-08-16 15:59:58,024 INFO 15:59:58,024 GC for ParNew: 474 ms for 2
collections, 5520513520 used; max is 8550678528
2012-08-16 15:59:58,913978.616: [GC 978.616: [ParNew:
345022K->38336K(345024K), 0.1699849 secs]
5688904K->5512877K(8350272K), 0.1700962 secs] [Times: user=2.50
sys=0.00, real=0.17 secs]
2012-08-16 16:00:00,271979.992: [GC 979.992: [ParNew:
344994K->38334K(345024K), 0.1453127 secs]
5819535K->5572894K(8350272K), 0.1454497 secs] [Times: user=1.70
sys=0.02, real=0.16 secs]
2012-08-16 16:00:04,545984.343: [GC 984.343: [ParNew:
344994K->37933K(345024K), 0.0741034 secs]
5879554K->5610224K(8350272K), 0.0742458 secs] [Times: user=0.30
sys=0.00, real=0.08 secs]
2012-08-16 16:00:07,119986.764: [GC 986.764: [ParNew:
344621K->38336K(345024K), 0.2181230 secs]
5916912K->5759381K(8350272K), 0.2182593 secs] [Times: user=2.67
sys=0.03, real=0.22 secs]
2012-08-16 16:00:07,150 INFO 16:00:07,150 GC for ParNew: 218 ms for 1
collections, 5930704288 used; max is 8550678528
2012-08-16 16:00:08,164987.810: [GC 987.810: [ParNew:
345024K->38336K(345024K), 0.2296247 secs]
6066069K->5950068K(8350272K), 0.2297637 secs] [Times: user=2.87
sys=0.00, real=0.22 secs]
2012-08-16 16:00:08,164 INFO 16:00:08,164 GC for ParNew: 230 ms for 1
collections, 6098706784 used; max is 8550678528
2012-08-16 16:00:08,819988.430: [GC 988.430: [ParNew:
345024K->38336K(345024K), 0.2652883 secs]
6256756K->6190892K(8350272K), 0.2654107 secs] [Times: user=3.90
sys=0.00, real=0.27 secs]
2012-08-16 16:00:08,851988.695: [GC [1 CMS-initial-mark:
6152556K(8005248K)] 6191809K(8350272K), 0.0267734 secs] [Times:
user=0.03 sys=0.00, real=0.03 secs]
2012-08-16 16:00:08,851988.722: [CMS-concurrent-mark-start]
2012-08-16 16:00:09,100988.973: [CMS-concurrent-mark: 0.250/0.250
secs] [Times: user=2.29 sys=0.06, real=0.25 secs]
2012-08-16 16:00:09,100988.973: [CMS-concurrent-preclean-start]
2012-08-16 16:00:09,131989.005: [CMS-concurrent-preclean: 0.032/0.033
secs] [Times: user=0.14 sys=0.02, real=0.03 secs]
2012-08-16 16:00:09,131989.005: [CMS-concurrent-abortable-preclean-start]
2012-08-16 16:00:09,194 INFO 16:00:09,194 GC for ParNew: 265 ms for 1
collections, 6523586752 used; max is 8550678528
2012-08-16 16:00:09,537989.149: [GC 989.150: [ParNew:
345024K->38336K(345024K), 0.2521832 secs]
6497580K->6413622K(8350272K), 0.2523014 secs] [Times: user=3.65
sys=0.00, real=0.26 secs]
2012-08-16 16:00:09,896989.760: [CMS-concurrent-abortable-preclean:
0.499/0.755 secs] [Times: user=5.90 sys=0.05, real=0.76 secs]
2012-08-16 16:00:09,911989.760: [GC[YG occupancy: 215512 K (345024
K)]989.760: [Rescan (parallel) , 0.0248524 secs]989.785: [weak refs
processing, 0.0000169 secs] [1 CMS-remark: 6375286K(8005248K)]
6590799K(8350272K), 0.0249718 secs] [Times: user=0.19 sys=0.00,
real=0.02 secs]
2012-08-16 16:00:09,911989.785: [CMS-concurrent-sweep-start]
2012-08-16 16:00:10,208 INFO 16:00:10,208 GC for ParNew: 253 ms for 1
collections, 6481264200 used; max is 8550678528
2012-08-16 16:00:10,816990.457: [GC 990.457: [ParNew:
345024K->38336K(345024K), 0.2229088 secs]
5892628K->5747038K(8350272K), 0.2230343 secs] [Times: user=3.14
sys=0.00, real=0.23 secs]
2012-08-16 16:00:11,222 INFO 16:00:11,222 GC for ParNew: 222 ms for 1
collections, 5618012152 used; max is 8550678528
2012-08-16 16:00:16,167995.849: [GC 995.849: [ParNew:
345024K->38336K(345024K), 0.1941598 secs]
3109823K->2945213K(8350272K), 0.1943046 secs] [Times: user=2.62
sys=0.00, real=0.19 secs]
2012-08-16 16:00:17,072996.699: [GC 996.699: [ParNew:
345024K->38336K(345024K), 0.2477104 secs]
3005684K->2909884K(8350272K), 0.2478259 secs] [Times: user=3.45
sys=0.00, real=0.25 secs]
2012-08-16 16:00:17,306 INFO 16:00:17,306 GC for ParNew: 247 ms for 1
collections, 2907671688 used; max is 8550678528
2012-08-16 16:00:18,570998.243: [GC 998.243: [ParNew:
345024K->38336K(345024K), 0.1898907 secs]
2788564K->2632153K(8350272K), 0.1900108 secs] [Times: user=2.64
sys=0.00, real=0.20 secs]
2012-08-16 16:00:19,443999.086: [GC 999.086: [ParNew:
345024K->38336K(345024K), 0.2223548 secs]
2719738K->2599595K(8350272K), 0.2224745 secs] [Times: user=3.15
sys=0.00, real=0.23 secs]
2012-08-16 16:00:19,443 INFO 16:00:19,443 GC for ParNew: 413 ms for 2
collections, 2664222584 used; max is 8550678528
2012-08-16 16:00:19,911999.515: [GC 999.515: [ParNew:
345024K->38334K(345024K), 0.2598227 secs]
2719357K->2655204K(8350272K), 0.2599416 secs] [Times: user=3.62
sys=0.00, real=0.27 secs]
2012-08-16 16:00:20,5821000.185: [GC 1000.185: [ParNew:
345022K->38336K(345024K), 0.2591240 secs]
2761843K->2686494K(8350272K), 0.2592448 secs] [Times: user=3.46
sys=0.00, real=0.27 secs]
2012-08-16 16:00:20,582 INFO 16:00:20,582 GC for ParNew: 519 ms for 2
collections, 2756113024 used; max is 8550678528
2012-08-16 16:00:21,1901000.808: [GC 1000.808: [ParNew:
344971K->38334K(345024K), 0.2520519 secs]
2760422K->2688079K(8350272K), 0.2521670 secs] [Times: user=3.65
sys=0.02, real=0.25 secs]
2012-08-16 16:00:21,5021001.375: [CMS-concurrent-sweep: 9.737/11.590
secs] [Times: user=49.31 sys=0.78, real=11.59 secs]
2012-08-16 16:00:21,5021001.375: [CMS-concurrent-reset-start]
2012-08-16 16:00:21,5341001.403: [CMS-concurrent-reset: 0.028/0.028
secs] [Times: user=0.16 sys=0.00, real=0.03 secs]
2012-08-16 16:00:21,596 INFO 16:00:21,596 GC for ParNew: 252 ms for 1
collections, 2680484480 used; max is 8550678528
Re: Many ParNew collections
Posted by Rene Kochen <re...@emea.schange.com>.
Thanks Aaron,
I found the problem. It's in this thread: "minor compaction and delete
expired column-tombstones".
The problem was that I have one big row called "Index" which contains
many tombstones. Reading all these tombstones caused the memory
issues.
I think node 1 and 3 have had enough minor compactions so that the
tombstones were removed. The second node still contains several old
SSTables and it takes some time before the whole thing is compacted
again.
Thanks,
Rene
2012/9/17 aaron morton <aa...@thelastpickle.com>:
> The second node (the one suffering from many GC) has a high read
> latency compared to the others. Another thing is that the compacted
> row maximum size is bigger than on the other nodes.
>
> Node 2 also:
> * has about 220MB of data, while the others have about 45MB
> * has about 1 Million keys while the others have about 0.3 Million
>
> - Should the other nodes also have that wide row,
>
> yes. Are you running repair ? What CL are you using ?
>
> - Could repeatedly reading a wide row cause parnew problems?
>
> Maybe. Are you reading the whole thing ?
> It's only 22MB, it's big but not huge.
>
> I would:
>
> * ensure repair is running and completing, this may even out the data load.
> * determine if GC is associate with compactions, repair or general activity.
> * if Gc is associated with compactions the simple thing is to reduce
> concurrent_compactions and in_memory_compaction_limit in the yaml. Note this
> is often a simple / quick fix that can increase IO load and slow down
> compaction. The harder thing is to tune the JVM memory settings (the
> defaults often do a good job).
>
> Hope that helps.
>
> -----------------
> Aaron Morton
> Freelance Developer
> @aaronmorton
> http://www.thelastpickle.com
>
> On 14/09/2012, at 10:41 PM, Rene Kochen <re...@schange.com> wrote:
>
> Thanks Aaron,
>
> At another production site the exact same problems occur (also after
> ~6 months). Here I have a very small cluster of three nodes with
> replication factor = 3.
> One of the three nodes begins to have many long Parnews and high CPU
> load. I upgraded to Cassandra 1.0.11, but the GC problem still
> continues on that node.
>
> If I look at the CFStats of the three nodes, there is one CF which is
> different:
>
> Column Family: Logs
> SSTable count: 1
> Space used (live): 47606705
> Space used (total): 47606705
> Number of Keys (estimate): 338176
> Memtable Columns Count: 22297
> Memtable Data Size: 51542275
> Memtable Switch Count: 1
> Read Count: 189441
> Read Latency: 0,768 ms.
> Write Count: 123411
> Write Latency: 0,035 ms.
> Pending Tasks: 0
> Bloom Filter False Postives: 0
> Bloom Filter False Ratio: 0,00000
> Bloom Filter Space Used: 721456
> Key cache capacity: 200000
> Key cache size: 56685
> Key cache hit rate: 0.9132482658217008
> Row cache: disabled
> Compacted row minimum size: 73
> Compacted row maximum size: 263210
> Compacted row mean size: 94
>
> Column Family: Logs
> SSTable count: 3
> Space used (live): 233688199
> Space used (total): 233688199
> Number of Keys (estimate): 1191936
> Memtable Columns Count: 20147
> Memtable Data Size: 47067518
> Memtable Switch Count: 1
> Read Count: 188473
> Read Latency: 4031,791 ms.
> Write Count: 120412
> Write Latency: 0,042 ms.
> Pending Tasks: 0
> Bloom Filter False Postives: 234
> Bloom Filter False Ratio: 0,00000
> Bloom Filter Space Used: 2603808
> Key cache capacity: 200000
> Key cache size: 5153
> Key cache hit rate: 1.0
> Row cache: disabled
> Compacted row minimum size: 73
> Compacted row maximum size: 25109160
> Compacted row mean size: 156
>
> Column Family: Logs
> SSTable count: 1
> Space used (live): 47714798
> Space used (total): 47714798
> Number of Keys (estimate): 338176
> Memtable Columns Count: 29046
> Memtable Data Size: 66585390
> Memtable Switch Count: 1
> Read Count: 196048
> Read Latency: 1,466 ms.
> Write Count: 127709
> Write Latency: 0,034 ms.
> Pending Tasks: 0
> Bloom Filter False Postives: 8
> Bloom Filter False Ratio: 0,00847
> Bloom Filter Space Used: 720496
> Key cache capacity: 200000
> Key cache size: 54166
> Key cache hit rate: 0.9833443960960739
> Row cache: disabled
> Compacted row minimum size: 73
> Compacted row maximum size: 263210
> Compacted row mean size: 95
>
> The second node (the one suffering from many GC) has a high read
> latency compared to the others. Another thing is that the compacted
> row maximum size is bigger than on the other nodes.
>
> What puzzles me:
>
> - Should the other nodes also have that wide row, because the
> replication factor is three and I only have three nodes? I must say
> that the wide row is probably the index row which has columns
> added/removed continuously. Maybe the other nodes lost much data
> because of compactions?
> - Could repeatedly reading a wide row cause parnew problems?
>
> Thanks!
>
> Rene
>
> 2012/8/17 aaron morton <aa...@thelastpickle.com>:
>
> - Cassandra 0.7.10
>
> You _really_ should look at getting up to 1.1 :) Memory management is much
> better and the JVM heap requirements are less.
>
> However, there is one node with high read latency and far too many
> ParNew collections (compared to other nodes).
>
> Check for long running compactions or repairs.
> Check for unexpected row or key cache settings.
> Look at the connections on the box and see if it is getting more client load
> than others.
>
> Restart the node and see if the situations returns. If it does try to
> correlate the start of the GC issues with the cassandra log.
>
> Hope that helps.
>
> -----------------
> Aaron Morton
> Freelance Developer
> @aaronmorton
> http://www.thelastpickle.com
>
> On 17/08/2012, at 2:58 AM, Rene Kochen <re...@schange.com> wrote:
>
> Hi
>
> I have a cluster of 7 nodes:
>
> - Windows Server 2008
> - Cassandra 0.7.10
> - The nodes are identical (hardware, configuration and client request load)
> - Standard batch file with 8GB heap
> - I use disk_access_mode = standard
> - Random partitioner
> - TP stats shows no problems
> - Ring command shows no problems (data is balanced)
>
> However, there is one node with high read latency and far too many
> ParNew collections (compared to other nodes). It also suffers from a
> high CPU load (I guess due to the ParNew collections).
>
> What can be the source of so many ParNew collections? The other
> identical nodes do not have this behavior.
>
> Logging:
>
> 2012-08-16 15:58:46,436906.072: [GC 906.072: [ParNew:
> 345022K->38336K(345024K), 0.2375976 secs]
> 3630599K->3516249K(8350272K), 0.2377296 secs] [Times: user=3.21
> sys=0.00, real=0.23 secs]
> 2012-08-16 15:58:46,888906.517: [GC 906.517: [ParNew:
> 345024K->38336K(345024K), 0.2400594 secs]
> 3822937K->3743690K(8350272K), 0.2401802 secs] [Times: user=3.48
> sys=0.03, real=0.25 secs]
> 2012-08-16 15:58:46,888 INFO 15:58:46,888 GC for ParNew: 478 ms for 2
> collections, 3837792904 used; max is 8550678528
> 2012-08-16 15:58:47,372907.003: [GC 907.003: [ParNew:
> 345024K->38336K(345024K), 0.2405363 secs]
> 4050378K->3971544K(8350272K), 0.2406553 secs] [Times: user=3.34
> sys=0.01, real=0.23 secs]
> 2012-08-16 15:58:47,918907.544: [GC 907.544: [ParNew:
> 345024K->38336K(345024K), 0.2404339 secs]
> 4278232K->4193789K(8350272K), 0.2405540 secs] [Times: user=3.31
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:58:47,918 INFO 15:58:47,918 GC for ParNew: 481 ms for 2
> collections, 4300939752 used; max is 8550678528
> 2012-08-16 15:58:48,464908.079: [GC 908.079: [ParNew:
> 345024K->38336K(345024K), 0.2621174 secs]
> 4500477K->4434112K(8350272K), 0.2622375 secs] [Times: user=3.64
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:58:48,932 INFO 15:58:48,932 GC for ParNew: 262 ms for 1
> collections, 4763583200 used; max is 8550678528
> 2012-08-16 15:58:49,384909.050: [GC 909.051: [ParNew:
> 344972K->38336K(345024K), 0.2033453 secs]
> 4740748K->4563252K(8350272K), 0.2034588 secs] [Times: user=2.89
> sys=0.01, real=0.20 secs]
> 2012-08-16 15:58:49,946 INFO 15:58:49,946 GC for ParNew: 203 ms for 1
> collections, 4885945792 used; max is 8550678528
> 2012-08-16 15:58:50,383909.998: [GC 909.998: [ParNew:
> 345024K->38336K(345024K), 0.2567542 secs]
> 4869940K->4740489K(8350272K), 0.2568804 secs] [Times: user=3.60
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:58:50,882910.474: [GC 910.474: [ParNew:
> 345024K->38336K(345024K), 0.2786205 secs]
> 5047177K->4962531K(8350272K), 0.2787668 secs] [Times: user=3.48
> sys=0.00, real=0.28 secs]
> 2012-08-16 15:58:50,960 INFO 15:58:50,960 GC for ParNew: 536 ms for 2
> collections, 5143423816 used; max is 8550678528
> 2012-08-16 15:58:51,584911.192: [GC 911.192: [ParNew:
> 344963K->38334K(345024K), 0.2664316 secs]
> 5269158K->5196444K(8350272K), 0.2665544 secs] [Times: user=3.74
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:58:52,130911.767: [GC 911.767: [ParNew:
> 345022K->38336K(345024K), 0.2327209 secs]
> 5503132K->5406771K(8350272K), 0.2328457 secs] [Times: user=3.35
> sys=0.00, real=0.23 secs]
> 2012-08-16 15:58:52,130 INFO 15:58:52,130 GC for ParNew: 499 ms for 2
> collections, 5541845264 used; max is 8550678528
> 2012-08-16 15:58:52,816912.460: [GC 912.460: [ParNew:
> 345024K->38334K(345024K), 0.2198399 secs]
> 5713459K->5605670K(8350272K), 0.2199669 secs] [Times: user=3.29
> sys=0.00, real=0.23 secs]
> 2012-08-16 15:58:53,144 INFO 15:58:53,144 GC for ParNew: 220 ms for 1
> collections, 5805870608 used; max is 8550678528
> 2012-08-16 15:58:55,546915.173: [GC 915.173: [ParNew:
> 345022K->38334K(345024K), 0.2369585 secs]
> 5912358K->5702871K(8350272K), 0.2371098 secs] [Times: user=3.18
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:58:56,186 INFO 15:58:56,186 GC for ParNew: 237 ms for 1
> collections, 6089002480 used; max is 8550678528
> 2012-08-16 15:58:56,591916.232: [GC 916.232: [ParNew:
> 345022K->38336K(345024K), 0.2364850 secs]
> 6009559K->5914142K(8350272K), 0.2366075 secs] [Times: user=3.32
> sys=0.00, real=0.23 secs]
> 2012-08-16 15:58:57,340916.989: [GC 916.989: [ParNew:
> 345024K->38334K(345024K), 0.2191751 secs]
> 6220830K->6107217K(8350272K), 0.2192894 secs] [Times: user=2.92
> sys=0.00, real=0.22 secs]
> 2012-08-16 15:58:57,371917.209: [GC [1 CMS-initial-mark:
> 6068883K(8005248K)] 6108716K(8350272K), 0.0272472 secs] [Times:
> user=0.03 sys=0.00, real=0.03 secs]
> 2012-08-16 15:58:57,371917.236: [CMS-concurrent-mark-start]
> 2012-08-16 15:58:57,371 INFO 15:58:57,371 GC for ParNew: 456 ms for 2
> collections, 6255865264 used; max is 8550678528
> 2012-08-16 15:58:57,574917.444: [CMS-concurrent-mark: 0.208/0.208
> secs] [Times: user=1.48 sys=0.06, real=0.20 secs]
> 2012-08-16 15:58:57,574917.444: [CMS-concurrent-preclean-start]
> 2012-08-16 15:58:57,637917.501: [CMS-concurrent-preclean: 0.057/0.057
> secs] [Times: user=0.19 sys=0.00, real=0.06 secs]
> 2012-08-16 15:58:57,637917.501: [CMS-concurrent-abortable-preclean-start]
> 2012-08-16 15:58:58,775918.552: [GC 918.552: [ParNew:
> 345022K->38334K(345024K), 0.0948325 secs]
> 6413905K->6163063K(8350272K), 0.0949661 secs] [Times: user=1.22
> sys=0.00, real=0.09 secs]
> 2012-08-16 15:58:59,025918.896: [CMS-concurrent-abortable-preclean:
> 1.198/1.395 secs] [Times: user=5.26 sys=0.17, real=1.39 secs]
> 2012-08-16 15:58:59,072918.896: [GC[YG occupancy: 274623 K (345024
> K)]918.896: [Rescan (parallel) , 0.0427564 secs]918.939: [weak refs
> processing, 0.0000096 secs] [1 CMS-remark: 6124729K(8005248K)]
> 6399352K(8350272K), 0.0428734 secs] [Times: user=0.62 sys=0.00,
> real=0.05 secs]
> 2012-08-16 15:58:59,072918.939: [CMS-concurrent-sweep-start]
> 2012-08-16 15:58:59,368918.972: [GC 918.972: [ParNew:
> 345022K->38336K(345024K), 0.2652648 secs]
> 6465380K->6379989K(8350272K), 0.2654014 secs] [Times: user=3.71
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:58:59,930919.557: [GC 919.557: [ParNew:
> 345024K->38334K(345024K), 0.2417524 secs]
> 6433484K->6347081K(8350272K), 0.2418748 secs] [Times: user=3.40
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:00,507920.161: [GC 920.162: [ParNew:
> 345015K->38334K(345024K), 0.2142607 secs]
> 6191692K->6086072K(8350272K), 0.2143766 secs] [Times: user=3.09
> sys=0.00, real=0.22 secs]
> 2012-08-16 15:59:00,507 INFO 15:59:00,507 GC for ParNew: 456 ms for 2
> collections, 6233109512 used; max is 8550678528
> 2012-08-16 15:59:01,022920.633: [GC 920.633: [ParNew:
> 345022K->38336K(345024K), 0.2590327 secs]
> 6140813K->6065694K(8350272K), 0.2591528 secs] [Times: user=3.67
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:59:01,521 INFO 15:59:01,521 GC for ParNew: 259 ms for 1
> collections, 5916301064 used; max is 8550678528
> 2012-08-16 15:59:01,942921.604: [GC 921.604: [ParNew:
> 345001K->38334K(345024K), 0.2059791 secs]
> 5576624K->5407950K(8350272K), 0.2060935 secs] [Times: user=3.07
> sys=0.00, real=0.20 secs]
> 2012-08-16 15:59:02,535 INFO 15:59:02,535 GC for ParNew: 206 ms for 1
> collections, 4951508912 used; max is 8550678528
> 2012-08-16 15:59:06,185925.865: [GC 925.865: [ParNew:
> 345022K->38334K(345024K), 0.1944824 secs]
> 2207361K->2034487K(8350272K), 0.1946014 secs] [Times: user=2.54
> sys=0.00, real=0.19 secs]
> 2012-08-16 15:59:06,747926.624: [CMS-concurrent-sweep: 6.301/7.685
> secs] [Times: user=36.33 sys=0.37, real=7.67 secs]
> 2012-08-16 15:59:06,747926.624: [CMS-concurrent-reset-start]
> 2012-08-16 15:59:06,778926.644: [CMS-concurrent-reset: 0.020/0.020
> secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
> 2012-08-16 15:59:07,699927.442: [GC 927.442: [ParNew:
> 345022K->38336K(345024K), 0.1241401 secs]
> 2087777K->1881732K(8350272K), 0.1242536 secs] [Times: user=1.47
> sys=0.00, real=0.13 secs]
> 2012-08-16 15:59:10,241929.912: [GC 929.912: [ParNew:
> 345024K->38334K(345024K), 0.1987855 secs]
> 2188420K->2049927K(8350272K), 0.1989237 secs] [Times: user=2.73
> sys=0.00, real=0.20 secs]
> 2012-08-16 15:59:10,912930.557: [GC 930.558: [ParNew:
> 345022K->38336K(345024K), 0.2269435 secs]
> 2356615K->2253199K(8350272K), 0.2270702 secs] [Times: user=2.98
> sys=0.00, real=0.22 secs]
> 2012-08-16 15:59:10,912 INFO 15:59:10,912 GC for ParNew: 426 ms for 2
> collections, 2312471792 used; max is 8550678528
> 2012-08-16 15:59:11,521931.148: [GC 931.148: [ParNew:
> 345024K->38334K(345024K), 0.2371360 secs]
> 2559887K->2475870K(8350272K), 0.2372526 secs] [Times: user=3.10
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:11,926 INFO 15:59:11,926 GC for ParNew: 237 ms for 1
> collections, 2763895872 used; max is 8550678528
> 2012-08-16 15:59:12,441932.137: [GC 932.137: [ParNew:
> 345022K->38336K(345024K), 0.1733826 secs]
> 2782558K->2622114K(8350272K), 0.1735015 secs] [Times: user=2.42
> sys=0.02, real=0.17 secs]
> 2012-08-16 15:59:13,549933.155: [GC 933.155: [ParNew:
> 345024K->38334K(345024K), 0.2625127 secs]
> 2928802K->2829867K(8350272K), 0.2626344 secs] [Times: user=3.77
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:59:14,188933.808: [GC 933.808: [ParNew:
> 345022K->38334K(345024K), 0.2505625 secs]
> 3136555K->3054091K(8350272K), 0.2506795 secs] [Times: user=3.46
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:14,188 INFO 15:59:14,188 GC for ParNew: 513 ms for 2
> collections, 3134992208 used; max is 8550678528
> 2012-08-16 15:59:14,890934.522: [GC 934.523: [ParNew:
> 345022K->38336K(345024K), 0.2316504 secs]
> 3360779K->3275423K(8350272K), 0.2317766 secs] [Times: user=3.13
> sys=0.00, real=0.23 secs]
> 2012-08-16 15:59:15,202 INFO 15:59:15,202 GC for ParNew: 232 ms for 1
> collections, 3536955232 used; max is 8550678528
> 2012-08-16 15:59:15,920935.625: [GC 935.625: [ParNew:
> 345024K->38334K(345024K), 0.1714062 secs]
> 3582111K->3415888K(8350272K), 0.1715367 secs] [Times: user=2.54
> sys=0.00, real=0.17 secs]
> 2012-08-16 15:59:16,513936.119: [GC 936.119: [ParNew:
> 345022K->38334K(345024K), 0.2719661 secs]
> 3722576K->3649948K(8350272K), 0.2720966 secs] [Times: user=3.74
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:59:17,059936.685: [GC 936.685: [ParNew:
> 345022K->38336K(345024K), 0.2452667 secs]
> 3956636K->3871076K(8350272K), 0.2453914 secs] [Times: user=3.62
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:17,230 INFO 15:59:17,230 GC for ParNew: 517 ms for 2
> collections, 4081462864 used; max is 8550678528
> 2012-08-16 15:59:17,651937.255: [GC 937.255: [ParNew:
> 345024K->38334K(345024K), 0.2594023 secs]
> 4177764K->4099640K(8350272K), 0.2595243 secs] [Times: user=3.49
> sys=0.01, real=0.27 secs]
> 2012-08-16 15:59:18,213937.825: [GC 937.825: [ParNew:
> 345022K->38336K(345024K), 0.2584561 secs]
> 4406328K->4332694K(8350272K), 0.2585750 secs] [Times: user=3.74
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:59:18,244 INFO 15:59:18,244 GC for ParNew: 518 ms for 2
> collections, 4451788480 used; max is 8550678528
> 2012-08-16 15:59:19,165938.841: [GC 938.841: [ParNew:
> 344991K->38334K(345024K), 0.1994641 secs]
> 4639350K->4482568K(8350272K), 0.1995789 secs] [Times: user=2.56
> sys=0.01, real=0.19 secs]
> 2012-08-16 15:59:25,717945.440: [GC 945.440: [ParNew:
> 344963K->38334K(345024K), 0.1440731 secs]
> 4789197K->4538905K(8350272K), 0.1442125 secs] [Times: user=1.61
> sys=0.00, real=0.14 secs]
> 2012-08-16 15:59:26,372945.966: [GC 945.966: [ParNew:
> 345022K->38336K(345024K), 0.2803466 secs]
> 4845593K->4785922K(8350272K), 0.2804798 secs] [Times: user=3.92
> sys=0.00, real=0.28 secs]
> 2012-08-16 15:59:26,372 INFO 15:59:26,372 GC for ParNew: 425 ms for 2
> collections, 4903116472 used; max is 8550678528
> 2012-08-16 15:59:26,965946.589: [GC 946.589: [ParNew:
> 345024K->38336K(345024K), 0.2496506 secs]
> 5092610K->5017752K(8350272K), 0.2497695 secs] [Times: user=3.60
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:27,526947.149: [GC 947.149: [ParNew:
> 345024K->38336K(345024K), 0.2427009 secs]
> 5324440K->5242855K(8350272K), 0.2428195 secs] [Times: user=3.21
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:27,526 INFO 15:59:27,526 GC for ParNew: 492 ms for 2
> collections, 5374819504 used; max is 8550678528
> 2012-08-16 15:59:28,088947.717: [GC 947.717: [ParNew:
> 345024K->38336K(345024K), 0.2467160 secs]
> 5549543K->5469437K(8350272K), 0.2468315 secs] [Times: user=3.39
> sys=0.00, real=0.23 secs]
> 2012-08-16 15:59:28,540 INFO 15:59:28,540 GC for ParNew: 247 ms for 1
> collections, 5756868992 used; max is 8550678528
> 2012-08-16 15:59:29,195948.871: [GC 948.871: [ParNew:
> 345024K->38334K(345024K), 0.1934754 secs]
> 5776125K->5599289K(8350272K), 0.1935862 secs] [Times: user=2.70
> sys=0.00, real=0.20 secs]
> 2012-08-16 15:59:29,710949.316: [GC 949.316: [ParNew:
> 345022K->38334K(345024K), 0.2601060 secs]
> 5905977K->5828882K(8350272K), 0.2602222 secs] [Times: user=3.46
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:59:29,710 INFO 15:59:29,710 GC for ParNew: 454 ms for 2
> collections, 5975471248 used; max is 8550678528
> 2012-08-16 15:59:30,194949.830: [GC 949.830: [ParNew:
> 345022K->38336K(345024K), 0.2380811 secs]
> 6135570K->6042546K(8350272K), 0.2382000 secs] [Times: user=3.14
> sys=0.00, real=0.23 secs]
> 2012-08-16 15:59:30,225950.069: [GC [1 CMS-initial-mark:
> 6004210K(8005248K)] 6042548K(8350272K), 0.0260419 secs] [Times:
> user=0.03 sys=0.00, real=0.03 secs]
> 2012-08-16 15:59:30,225950.095: [CMS-concurrent-mark-start]
> 2012-08-16 15:59:30,443950.316: [CMS-concurrent-mark: 0.221/0.221
> secs] [Times: user=2.06 sys=0.13, real=0.22 secs]
> 2012-08-16 15:59:30,443950.316: [CMS-concurrent-preclean-start]
> 2012-08-16 15:59:30,459950.336: [CMS-concurrent-preclean: 0.020/0.020
> secs] [Times: user=0.06 sys=0.01, real=0.02 secs]
> 2012-08-16 15:59:30,459950.336: [CMS-concurrent-abortable-preclean-start]
> 2012-08-16 15:59:30,818950.463: [GC 950.463: [ParNew:
> 345024K->38336K(345024K), 0.2228510 secs]
> 6349234K->6252442K(8350272K), 0.2229688 secs] [Times: user=3.14
> sys=0.00, real=0.22 secs]
> 2012-08-16 15:59:30,818 INFO 15:59:30,818 GC for ParNew: 461 ms for 2
> collections, 6406860032 used; max is 8550678528
> 2012-08-16 15:59:31,395950.997: [GC 950.997: [ParNew:
> 345024K->38336K(345024K), 0.2692564 secs]
> 6559130K->6493591K(8350272K), 0.2693750 secs] [Times: user=3.81
> sys=0.00, real=0.26 secs]
> 2012-08-16 15:59:31,707951.580: [CMS-concurrent-abortable-preclean:
> 0.750/1.245 secs] [Times: user=10.84 sys=0.13, real=1.25 secs]
> 2012-08-16 15:59:31,723951.581: [GC[YG occupancy: 190327 K (345024
> K)]951.581: [Rescan (parallel) , 0.0126204 secs]951.593: [weak refs
> processing, 0.0000085 secs] [1 CMS-remark: 6455255K(8005248K)]
> 6645582K(8350272K), 0.0127259 secs] [Times: user=0.28 sys=0.00,
> real=0.02 secs]
> 2012-08-16 15:59:31,723951.593: [CMS-concurrent-sweep-start]
> 2012-08-16 15:59:31,832 INFO 15:59:31,832 GC for ParNew: 269 ms for 1
> collections, 6764806360 used; max is 8550678528
> 2012-08-16 15:59:32,362952.030: [GC 952.030: [ParNew:
> 345024K->38334K(345024K), 0.1960234 secs]
> 6293501K->6126054K(8350272K), 0.1961435 secs] [Times: user=2.89
> sys=0.02, real=0.20 secs]
> 2012-08-16 15:59:35,685955.406: [GC 955.406: [ParNew:
> 345006K->38336K(345024K), 0.1556453 secs]
> 2927846K->2691941K(8350272K), 0.1557619 secs] [Times: user=2.39
> sys=0.02, real=0.16 secs]
> 2012-08-16 15:59:36,325955.902: [GC 955.902: [ParNew:
> 345024K->38334K(345024K), 0.2880415 secs]
> 2887108K->2831437K(8350272K), 0.2881643 secs] [Times: user=4.04
> sys=0.00, real=0.30 secs]
> 2012-08-16 15:59:36,902956.561: [GC 956.561: [ParNew:
> 345022K->38334K(345024K), 0.2172772 secs]
> 2933661K->2836344K(8350272K), 0.2173954 secs] [Times: user=3.04
> sys=0.00, real=0.22 secs]
> 2012-08-16 15:59:36,902 INFO 15:59:36,902 GC for ParNew: 505 ms for 2
> collections, 2909226128 used; max is 8550678528
> 2012-08-16 15:59:37,573957.194: [GC 957.194: [ParNew:
> 345022K->38336K(345024K), 0.2457267 secs]
> 2835640K->2761950K(8350272K), 0.2458564 secs] [Times: user=3.43
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:38,087957.692: [GC 957.692: [ParNew:
> 345024K->38334K(345024K), 0.2580753 secs]
> 2883419K->2810105K(8350272K), 0.2581927 secs] [Times: user=3.43
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:38,087 INFO 15:59:38,087 GC for ParNew: 504 ms for 2
> collections, 2883187080 used; max is 8550678528
> 2012-08-16 15:59:39,273958.942: [GC 958.942: [ParNew:
> 345022K->38336K(345024K), 0.1964326 secs]
> 2691229K->2515113K(8350272K), 0.1965519 secs] [Times: user=2.87
> sys=0.00, real=0.20 secs]
> 2012-08-16 15:59:39,694959.568: [CMS-concurrent-sweep: 6.414/7.975
> secs] [Times: user=44.04 sys=0.72, real=7.97 secs]
> 2012-08-16 15:59:39,694959.568: [CMS-concurrent-reset-start]
> 2012-08-16 15:59:39,725959.590: [CMS-concurrent-reset: 0.022/0.022
> secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
> 2012-08-16 15:59:41,956961.725: [GC 961.725: [ParNew:
> 344994K->38334K(345024K), 0.0970048 secs]
> 2645182K->2381114K(8350272K), 0.0971442 secs] [Times: user=0.92
> sys=0.00, real=0.09 secs]
> 2012-08-16 15:59:46,043965.815: [GC 965.816: [ParNew:
> 345022K->38336K(345024K), 0.0998408 secs]
> 2687802K->2449434K(8350272K), 0.0999933 secs] [Times: user=1.08
> sys=0.02, real=0.09 secs]
> 2012-08-16 15:59:46,511966.115: [GC 966.115: [ParNew:
> 344629K->38336K(345024K), 0.2663284 secs]
> 2755727K->2687941K(8350272K), 0.2664512 secs] [Times: user=3.46
> sys=0.00, real=0.26 secs]
> 2012-08-16 15:59:47,089966.709: [GC 966.709: [ParNew:
> 344990K->38336K(345024K), 0.2430397 secs]
> 2994595K->2921799K(8350272K), 0.2431602 secs] [Times: user=3.40
> sys=0.02, real=0.25 secs]
> 2012-08-16 15:59:47,681967.293: [GC 967.293: [ParNew:
> 345024K->38336K(345024K), 0.2527240 secs]
> 3228487K->3156972K(8350272K), 0.2528499 secs] [Times: user=3.45
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:59:47,681 INFO 15:59:47,681 GC for ParNew: 496 ms for 2
> collections, 3235405952 used; max is 8550678528
> 2012-08-16 15:59:48,415968.061: [GC 968.061: [ParNew:
> 345024K->38336K(345024K), 0.2184791 secs]
> 3463660K->3348605K(8350272K), 0.2185973 secs] [Times: user=2.87
> sys=0.00, real=0.22 secs]
> 2012-08-16 15:59:48,695 INFO 15:59:48,695 GC for ParNew: 219 ms for 1
> collections, 3493343744 used; max is 8550678528
> 2012-08-16 15:59:49,631969.245: [GC 969.245: [ParNew:
> 345024K->38336K(345024K), 0.2571372 secs]
> 3655293K->3536159K(8350272K), 0.2572561 secs] [Times: user=3.67
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:49,709 INFO 15:59:49,709 GC for ParNew: 257 ms for 1
> collections, 3726925432 used; max is 8550678528
> 2012-08-16 15:59:50,162969.766: [GC 969.766: [ParNew:
> 345024K->38334K(345024K), 0.2653560 secs]
> 3842847K->3774598K(8350272K), 0.2654692 secs] [Times: user=3.90
> sys=0.00, real=0.26 secs]
> 2012-08-16 15:59:50,723970.347: [GC 970.347: [ParNew:
> 345022K->38336K(345024K), 0.2484206 secs]
> 4081286K->4008970K(8350272K), 0.2485346 secs] [Times: user=3.56
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:50,723 INFO 15:59:50,723 GC for ParNew: 514 ms for 2
> collections, 4110795240 used; max is 8550678528
> 2012-08-16 15:59:51,363970.965: [GC 970.965: [ParNew:
> 345024K->38334K(345024K), 0.2646304 secs]
> 4315658K->4258131K(8350272K), 0.2647516 secs] [Times: user=3.67
> sys=0.00, real=0.26 secs]
> 2012-08-16 15:59:51,737 INFO 15:59:51,737 GC for ParNew: 264 ms for 1
> collections, 4581460088 used; max is 8550678528
> 2012-08-16 15:59:52,299971.961: [GC 971.961: [ParNew:
> 345022K->38334K(345024K), 0.2041610 secs]
> 4564819K->4427702K(8350272K), 0.2042765 secs] [Times: user=2.62
> sys=0.00, real=0.20 secs]
> 2012-08-16 15:59:52,751 INFO 15:59:52,751 GC for ParNew: 205 ms for 1
> collections, 4640258968 used; max is 8550678528
> 2012-08-16 15:59:55,669975.335: [GC 975.335: [ParNew:
> 345022K->38336K(345024K), 0.2031359 secs]
> 4734390K->4513398K(8350272K), 0.2032737 secs] [Times: user=2.67
> sys=0.00, real=0.20 secs]
> 2012-08-16 15:59:55,793 INFO 15:59:55,793 GC for ParNew: 203 ms for 1
> collections, 4637851352 used; max is 8550678528
> 2012-08-16 15:59:56,495976.118: [GC 976.118: [ParNew:
> 345024K->38334K(345024K), 0.2428765 secs]
> 4820086K->4719356K(8350272K), 0.2430081 secs] [Times: user=3.40
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:56,963976.598: [GC 976.598: [ParNew:
> 345022K->38336K(345024K), 0.2291020 secs]
> 5026044K->4940991K(8350272K), 0.2292186 secs] [Times: user=3.35
> sys=0.02, real=0.23 secs]
> 2012-08-16 15:59:56,963 INFO 15:59:56,963 GC for ParNew: 472 ms for 2
> collections, 5061091520 used; max is 8550678528
> 2012-08-16 15:59:57,478977.138: [GC 977.138: [ParNew:
> 345024K->38334K(345024K), 0.2138650 secs]
> 5247679K->5145409K(8350272K), 0.2139793 secs] [Times: user=2.79
> sys=0.00, real=0.20 secs]
> 2012-08-16 15:59:58,024977.628: [GC 977.628: [ParNew:
> 345022K->38334K(345024K), 0.2597949 secs]
> 5452097K->5382216K(8350272K), 0.2599123 secs] [Times: user=3.49
> sys=0.00, real=0.26 secs]
> 2012-08-16 15:59:58,024 INFO 15:59:58,024 GC for ParNew: 474 ms for 2
> collections, 5520513520 used; max is 8550678528
> 2012-08-16 15:59:58,913978.616: [GC 978.616: [ParNew:
> 345022K->38336K(345024K), 0.1699849 secs]
> 5688904K->5512877K(8350272K), 0.1700962 secs] [Times: user=2.50
> sys=0.00, real=0.17 secs]
> 2012-08-16 16:00:00,271979.992: [GC 979.992: [ParNew:
> 344994K->38334K(345024K), 0.1453127 secs]
> 5819535K->5572894K(8350272K), 0.1454497 secs] [Times: user=1.70
> sys=0.02, real=0.16 secs]
> 2012-08-16 16:00:04,545984.343: [GC 984.343: [ParNew:
> 344994K->37933K(345024K), 0.0741034 secs]
> 5879554K->5610224K(8350272K), 0.0742458 secs] [Times: user=0.30
> sys=0.00, real=0.08 secs]
> 2012-08-16 16:00:07,119986.764: [GC 986.764: [ParNew:
> 344621K->38336K(345024K), 0.2181230 secs]
> 5916912K->5759381K(8350272K), 0.2182593 secs] [Times: user=2.67
> sys=0.03, real=0.22 secs]
> 2012-08-16 16:00:07,150 INFO 16:00:07,150 GC for ParNew: 218 ms for 1
> collections, 5930704288 used; max is 8550678528
> 2012-08-16 16:00:08,164987.810: [GC 987.810: [ParNew:
> 345024K->38336K(345024K), 0.2296247 secs]
> 6066069K->5950068K(8350272K), 0.2297637 secs] [Times: user=2.87
> sys=0.00, real=0.22 secs]
> 2012-08-16 16:00:08,164 INFO 16:00:08,164 GC for ParNew: 230 ms for 1
> collections, 6098706784 used; max is 8550678528
> 2012-08-16 16:00:08,819988.430: [GC 988.430: [ParNew:
> 345024K->38336K(345024K), 0.2652883 secs]
> 6256756K->6190892K(8350272K), 0.2654107 secs] [Times: user=3.90
> sys=0.00, real=0.27 secs]
> 2012-08-16 16:00:08,851988.695: [GC [1 CMS-initial-mark:
> 6152556K(8005248K)] 6191809K(8350272K), 0.0267734 secs] [Times:
> user=0.03 sys=0.00, real=0.03 secs]
> 2012-08-16 16:00:08,851988.722: [CMS-concurrent-mark-start]
> 2012-08-16 16:00:09,100988.973: [CMS-concurrent-mark: 0.250/0.250
> secs] [Times: user=2.29 sys=0.06, real=0.25 secs]
> 2012-08-16 16:00:09,100988.973: [CMS-concurrent-preclean-start]
> 2012-08-16 16:00:09,131989.005: [CMS-concurrent-preclean: 0.032/0.033
> secs] [Times: user=0.14 sys=0.02, real=0.03 secs]
> 2012-08-16 16:00:09,131989.005: [CMS-concurrent-abortable-preclean-start]
> 2012-08-16 16:00:09,194 INFO 16:00:09,194 GC for ParNew: 265 ms for 1
> collections, 6523586752 used; max is 8550678528
> 2012-08-16 16:00:09,537989.149: [GC 989.150: [ParNew:
> 345024K->38336K(345024K), 0.2521832 secs]
> 6497580K->6413622K(8350272K), 0.2523014 secs] [Times: user=3.65
> sys=0.00, real=0.26 secs]
> 2012-08-16 16:00:09,896989.760: [CMS-concurrent-abortable-preclean:
> 0.499/0.755 secs] [Times: user=5.90 sys=0.05, real=0.76 secs]
> 2012-08-16 16:00:09,911989.760: [GC[YG occupancy: 215512 K (345024
> K)]989.760: [Rescan (parallel) , 0.0248524 secs]989.785: [weak refs
> processing, 0.0000169 secs] [1 CMS-remark: 6375286K(8005248K)]
> 6590799K(8350272K), 0.0249718 secs] [Times: user=0.19 sys=0.00,
> real=0.02 secs]
> 2012-08-16 16:00:09,911989.785: [CMS-concurrent-sweep-start]
> 2012-08-16 16:00:10,208 INFO 16:00:10,208 GC for ParNew: 253 ms for 1
> collections, 6481264200 used; max is 8550678528
> 2012-08-16 16:00:10,816990.457: [GC 990.457: [ParNew:
> 345024K->38336K(345024K), 0.2229088 secs]
> 5892628K->5747038K(8350272K), 0.2230343 secs] [Times: user=3.14
> sys=0.00, real=0.23 secs]
> 2012-08-16 16:00:11,222 INFO 16:00:11,222 GC for ParNew: 222 ms for 1
> collections, 5618012152 used; max is 8550678528
> 2012-08-16 16:00:16,167995.849: [GC 995.849: [ParNew:
> 345024K->38336K(345024K), 0.1941598 secs]
> 3109823K->2945213K(8350272K), 0.1943046 secs] [Times: user=2.62
> sys=0.00, real=0.19 secs]
> 2012-08-16 16:00:17,072996.699: [GC 996.699: [ParNew:
> 345024K->38336K(345024K), 0.2477104 secs]
> 3005684K->2909884K(8350272K), 0.2478259 secs] [Times: user=3.45
> sys=0.00, real=0.25 secs]
> 2012-08-16 16:00:17,306 INFO 16:00:17,306 GC for ParNew: 247 ms for 1
> collections, 2907671688 used; max is 8550678528
> 2012-08-16 16:00:18,570998.243: [GC 998.243: [ParNew:
> 345024K->38336K(345024K), 0.1898907 secs]
> 2788564K->2632153K(8350272K), 0.1900108 secs] [Times: user=2.64
> sys=0.00, real=0.20 secs]
> 2012-08-16 16:00:19,443999.086: [GC 999.086: [ParNew:
> 345024K->38336K(345024K), 0.2223548 secs]
> 2719738K->2599595K(8350272K), 0.2224745 secs] [Times: user=3.15
> sys=0.00, real=0.23 secs]
> 2012-08-16 16:00:19,443 INFO 16:00:19,443 GC for ParNew: 413 ms for 2
> collections, 2664222584 used; max is 8550678528
> 2012-08-16 16:00:19,911999.515: [GC 999.515: [ParNew:
> 345024K->38334K(345024K), 0.2598227 secs]
> 2719357K->2655204K(8350272K), 0.2599416 secs] [Times: user=3.62
> sys=0.00, real=0.27 secs]
> 2012-08-16 16:00:20,5821000.185: [GC 1000.185: [ParNew:
> 345022K->38336K(345024K), 0.2591240 secs]
> 2761843K->2686494K(8350272K), 0.2592448 secs] [Times: user=3.46
> sys=0.00, real=0.27 secs]
> 2012-08-16 16:00:20,582 INFO 16:00:20,582 GC for ParNew: 519 ms for 2
> collections, 2756113024 used; max is 8550678528
> 2012-08-16 16:00:21,1901000.808: [GC 1000.808: [ParNew:
> 344971K->38334K(345024K), 0.2520519 secs]
> 2760422K->2688079K(8350272K), 0.2521670 secs] [Times: user=3.65
> sys=0.02, real=0.25 secs]
> 2012-08-16 16:00:21,5021001.375: [CMS-concurrent-sweep: 9.737/11.590
> secs] [Times: user=49.31 sys=0.78, real=11.59 secs]
> 2012-08-16 16:00:21,5021001.375: [CMS-concurrent-reset-start]
> 2012-08-16 16:00:21,5341001.403: [CMS-concurrent-reset: 0.028/0.028
> secs] [Times: user=0.16 sys=0.00, real=0.03 secs]
> 2012-08-16 16:00:21,596 INFO 16:00:21,596 GC for ParNew: 252 ms for 1
> collections, 2680484480 used; max is 8550678528
>
>
>
Re: Many ParNew collections
Posted by aaron morton <aa...@thelastpickle.com>.
> The second node (the one suffering from many GC) has a high read
> latency compared to the others. Another thing is that the compacted
> row maximum size is bigger than on the other nodes.
Node 2 also:
* has about 220MB of data, while the others have about 45MB
* has about 1 Million keys while the others have about 0.3 Million
> - Should the other nodes also have that wide row,
yes. Are you running repair ? What CL are you using ?
> - Could repeatedly reading a wide row cause parnew problems?
Maybe. Are you reading the whole thing ?
It's only 22MB, it's big but not huge.
I would:
* ensure repair is running and completing, this may even out the data load.
* determine if GC is associate with compactions, repair or general activity.
* if Gc is associated with compactions the simple thing is to reduce concurrent_compactions and in_memory_compaction_limit in the yaml. Note this is often a simple / quick fix that can increase IO load and slow down compaction. The harder thing is to tune the JVM memory settings (the defaults often do a good job).
Hope that helps.
-----------------
Aaron Morton
Freelance Developer
@aaronmorton
http://www.thelastpickle.com
On 14/09/2012, at 10:41 PM, Rene Kochen <re...@schange.com> wrote:
> Thanks Aaron,
>
> At another production site the exact same problems occur (also after
> ~6 months). Here I have a very small cluster of three nodes with
> replication factor = 3.
> One of the three nodes begins to have many long Parnews and high CPU
> load. I upgraded to Cassandra 1.0.11, but the GC problem still
> continues on that node.
>
> If I look at the CFStats of the three nodes, there is one CF which is different:
>
> Column Family: Logs
> SSTable count: 1
> Space used (live): 47606705
> Space used (total): 47606705
> Number of Keys (estimate): 338176
> Memtable Columns Count: 22297
> Memtable Data Size: 51542275
> Memtable Switch Count: 1
> Read Count: 189441
> Read Latency: 0,768 ms.
> Write Count: 123411
> Write Latency: 0,035 ms.
> Pending Tasks: 0
> Bloom Filter False Postives: 0
> Bloom Filter False Ratio: 0,00000
> Bloom Filter Space Used: 721456
> Key cache capacity: 200000
> Key cache size: 56685
> Key cache hit rate: 0.9132482658217008
> Row cache: disabled
> Compacted row minimum size: 73
> Compacted row maximum size: 263210
> Compacted row mean size: 94
>
> Column Family: Logs
> SSTable count: 3
> Space used (live): 233688199
> Space used (total): 233688199
> Number of Keys (estimate): 1191936
> Memtable Columns Count: 20147
> Memtable Data Size: 47067518
> Memtable Switch Count: 1
> Read Count: 188473
> Read Latency: 4031,791 ms.
> Write Count: 120412
> Write Latency: 0,042 ms.
> Pending Tasks: 0
> Bloom Filter False Postives: 234
> Bloom Filter False Ratio: 0,00000
> Bloom Filter Space Used: 2603808
> Key cache capacity: 200000
> Key cache size: 5153
> Key cache hit rate: 1.0
> Row cache: disabled
> Compacted row minimum size: 73
> Compacted row maximum size: 25109160
> Compacted row mean size: 156
>
> Column Family: Logs
> SSTable count: 1
> Space used (live): 47714798
> Space used (total): 47714798
> Number of Keys (estimate): 338176
> Memtable Columns Count: 29046
> Memtable Data Size: 66585390
> Memtable Switch Count: 1
> Read Count: 196048
> Read Latency: 1,466 ms.
> Write Count: 127709
> Write Latency: 0,034 ms.
> Pending Tasks: 0
> Bloom Filter False Postives: 8
> Bloom Filter False Ratio: 0,00847
> Bloom Filter Space Used: 720496
> Key cache capacity: 200000
> Key cache size: 54166
> Key cache hit rate: 0.9833443960960739
> Row cache: disabled
> Compacted row minimum size: 73
> Compacted row maximum size: 263210
> Compacted row mean size: 95
>
> The second node (the one suffering from many GC) has a high read
> latency compared to the others. Another thing is that the compacted
> row maximum size is bigger than on the other nodes.
>
> What puzzles me:
>
> - Should the other nodes also have that wide row, because the
> replication factor is three and I only have three nodes? I must say
> that the wide row is probably the index row which has columns
> added/removed continuously. Maybe the other nodes lost much data
> because of compactions?
> - Could repeatedly reading a wide row cause parnew problems?
>
> Thanks!
>
> Rene
>
> 2012/8/17 aaron morton <aa...@thelastpickle.com>:
>> - Cassandra 0.7.10
>>
>> You _really_ should look at getting up to 1.1 :) Memory management is much
>> better and the JVM heap requirements are less.
>>
>> However, there is one node with high read latency and far too many
>> ParNew collections (compared to other nodes).
>>
>> Check for long running compactions or repairs.
>> Check for unexpected row or key cache settings.
>> Look at the connections on the box and see if it is getting more client load
>> than others.
>>
>> Restart the node and see if the situations returns. If it does try to
>> correlate the start of the GC issues with the cassandra log.
>>
>> Hope that helps.
>>
>> -----------------
>> Aaron Morton
>> Freelance Developer
>> @aaronmorton
>> http://www.thelastpickle.com
>>
>> On 17/08/2012, at 2:58 AM, Rene Kochen <re...@schange.com> wrote:
>>
>> Hi
>>
>> I have a cluster of 7 nodes:
>>
>> - Windows Server 2008
>> - Cassandra 0.7.10
>> - The nodes are identical (hardware, configuration and client request load)
>> - Standard batch file with 8GB heap
>> - I use disk_access_mode = standard
>> - Random partitioner
>> - TP stats shows no problems
>> - Ring command shows no problems (data is balanced)
>>
>> However, there is one node with high read latency and far too many
>> ParNew collections (compared to other nodes). It also suffers from a
>> high CPU load (I guess due to the ParNew collections).
>>
>> What can be the source of so many ParNew collections? The other
>> identical nodes do not have this behavior.
>>
>> Logging:
>>
>> 2012-08-16 15:58:46,436906.072: [GC 906.072: [ParNew:
>> 345022K->38336K(345024K), 0.2375976 secs]
>> 3630599K->3516249K(8350272K), 0.2377296 secs] [Times: user=3.21
>> sys=0.00, real=0.23 secs]
>> 2012-08-16 15:58:46,888906.517: [GC 906.517: [ParNew:
>> 345024K->38336K(345024K), 0.2400594 secs]
>> 3822937K->3743690K(8350272K), 0.2401802 secs] [Times: user=3.48
>> sys=0.03, real=0.25 secs]
>> 2012-08-16 15:58:46,888 INFO 15:58:46,888 GC for ParNew: 478 ms for 2
>> collections, 3837792904 used; max is 8550678528
>> 2012-08-16 15:58:47,372907.003: [GC 907.003: [ParNew:
>> 345024K->38336K(345024K), 0.2405363 secs]
>> 4050378K->3971544K(8350272K), 0.2406553 secs] [Times: user=3.34
>> sys=0.01, real=0.23 secs]
>> 2012-08-16 15:58:47,918907.544: [GC 907.544: [ParNew:
>> 345024K->38336K(345024K), 0.2404339 secs]
>> 4278232K->4193789K(8350272K), 0.2405540 secs] [Times: user=3.31
>> sys=0.00, real=0.25 secs]
>> 2012-08-16 15:58:47,918 INFO 15:58:47,918 GC for ParNew: 481 ms for 2
>> collections, 4300939752 used; max is 8550678528
>> 2012-08-16 15:58:48,464908.079: [GC 908.079: [ParNew:
>> 345024K->38336K(345024K), 0.2621174 secs]
>> 4500477K->4434112K(8350272K), 0.2622375 secs] [Times: user=3.64
>> sys=0.00, real=0.25 secs]
>> 2012-08-16 15:58:48,932 INFO 15:58:48,932 GC for ParNew: 262 ms for 1
>> collections, 4763583200 used; max is 8550678528
>> 2012-08-16 15:58:49,384909.050: [GC 909.051: [ParNew:
>> 344972K->38336K(345024K), 0.2033453 secs]
>> 4740748K->4563252K(8350272K), 0.2034588 secs] [Times: user=2.89
>> sys=0.01, real=0.20 secs]
>> 2012-08-16 15:58:49,946 INFO 15:58:49,946 GC for ParNew: 203 ms for 1
>> collections, 4885945792 used; max is 8550678528
>> 2012-08-16 15:58:50,383909.998: [GC 909.998: [ParNew:
>> 345024K->38336K(345024K), 0.2567542 secs]
>> 4869940K->4740489K(8350272K), 0.2568804 secs] [Times: user=3.60
>> sys=0.00, real=0.25 secs]
>> 2012-08-16 15:58:50,882910.474: [GC 910.474: [ParNew:
>> 345024K->38336K(345024K), 0.2786205 secs]
>> 5047177K->4962531K(8350272K), 0.2787668 secs] [Times: user=3.48
>> sys=0.00, real=0.28 secs]
>> 2012-08-16 15:58:50,960 INFO 15:58:50,960 GC for ParNew: 536 ms for 2
>> collections, 5143423816 used; max is 8550678528
>> 2012-08-16 15:58:51,584911.192: [GC 911.192: [ParNew:
>> 344963K->38334K(345024K), 0.2664316 secs]
>> 5269158K->5196444K(8350272K), 0.2665544 secs] [Times: user=3.74
>> sys=0.00, real=0.27 secs]
>> 2012-08-16 15:58:52,130911.767: [GC 911.767: [ParNew:
>> 345022K->38336K(345024K), 0.2327209 secs]
>> 5503132K->5406771K(8350272K), 0.2328457 secs] [Times: user=3.35
>> sys=0.00, real=0.23 secs]
>> 2012-08-16 15:58:52,130 INFO 15:58:52,130 GC for ParNew: 499 ms for 2
>> collections, 5541845264 used; max is 8550678528
>> 2012-08-16 15:58:52,816912.460: [GC 912.460: [ParNew:
>> 345024K->38334K(345024K), 0.2198399 secs]
>> 5713459K->5605670K(8350272K), 0.2199669 secs] [Times: user=3.29
>> sys=0.00, real=0.23 secs]
>> 2012-08-16 15:58:53,144 INFO 15:58:53,144 GC for ParNew: 220 ms for 1
>> collections, 5805870608 used; max is 8550678528
>> 2012-08-16 15:58:55,546915.173: [GC 915.173: [ParNew:
>> 345022K->38334K(345024K), 0.2369585 secs]
>> 5912358K->5702871K(8350272K), 0.2371098 secs] [Times: user=3.18
>> sys=0.00, real=0.25 secs]
>> 2012-08-16 15:58:56,186 INFO 15:58:56,186 GC for ParNew: 237 ms for 1
>> collections, 6089002480 used; max is 8550678528
>> 2012-08-16 15:58:56,591916.232: [GC 916.232: [ParNew:
>> 345022K->38336K(345024K), 0.2364850 secs]
>> 6009559K->5914142K(8350272K), 0.2366075 secs] [Times: user=3.32
>> sys=0.00, real=0.23 secs]
>> 2012-08-16 15:58:57,340916.989: [GC 916.989: [ParNew:
>> 345024K->38334K(345024K), 0.2191751 secs]
>> 6220830K->6107217K(8350272K), 0.2192894 secs] [Times: user=2.92
>> sys=0.00, real=0.22 secs]
>> 2012-08-16 15:58:57,371917.209: [GC [1 CMS-initial-mark:
>> 6068883K(8005248K)] 6108716K(8350272K), 0.0272472 secs] [Times:
>> user=0.03 sys=0.00, real=0.03 secs]
>> 2012-08-16 15:58:57,371917.236: [CMS-concurrent-mark-start]
>> 2012-08-16 15:58:57,371 INFO 15:58:57,371 GC for ParNew: 456 ms for 2
>> collections, 6255865264 used; max is 8550678528
>> 2012-08-16 15:58:57,574917.444: [CMS-concurrent-mark: 0.208/0.208
>> secs] [Times: user=1.48 sys=0.06, real=0.20 secs]
>> 2012-08-16 15:58:57,574917.444: [CMS-concurrent-preclean-start]
>> 2012-08-16 15:58:57,637917.501: [CMS-concurrent-preclean: 0.057/0.057
>> secs] [Times: user=0.19 sys=0.00, real=0.06 secs]
>> 2012-08-16 15:58:57,637917.501: [CMS-concurrent-abortable-preclean-start]
>> 2012-08-16 15:58:58,775918.552: [GC 918.552: [ParNew:
>> 345022K->38334K(345024K), 0.0948325 secs]
>> 6413905K->6163063K(8350272K), 0.0949661 secs] [Times: user=1.22
>> sys=0.00, real=0.09 secs]
>> 2012-08-16 15:58:59,025918.896: [CMS-concurrent-abortable-preclean:
>> 1.198/1.395 secs] [Times: user=5.26 sys=0.17, real=1.39 secs]
>> 2012-08-16 15:58:59,072918.896: [GC[YG occupancy: 274623 K (345024
>> K)]918.896: [Rescan (parallel) , 0.0427564 secs]918.939: [weak refs
>> processing, 0.0000096 secs] [1 CMS-remark: 6124729K(8005248K)]
>> 6399352K(8350272K), 0.0428734 secs] [Times: user=0.62 sys=0.00,
>> real=0.05 secs]
>> 2012-08-16 15:58:59,072918.939: [CMS-concurrent-sweep-start]
>> 2012-08-16 15:58:59,368918.972: [GC 918.972: [ParNew:
>> 345022K->38336K(345024K), 0.2652648 secs]
>> 6465380K->6379989K(8350272K), 0.2654014 secs] [Times: user=3.71
>> sys=0.00, real=0.27 secs]
>> 2012-08-16 15:58:59,930919.557: [GC 919.557: [ParNew:
>> 345024K->38334K(345024K), 0.2417524 secs]
>> 6433484K->6347081K(8350272K), 0.2418748 secs] [Times: user=3.40
>> sys=0.00, real=0.25 secs]
>> 2012-08-16 15:59:00,507920.161: [GC 920.162: [ParNew:
>> 345015K->38334K(345024K), 0.2142607 secs]
>> 6191692K->6086072K(8350272K), 0.2143766 secs] [Times: user=3.09
>> sys=0.00, real=0.22 secs]
>> 2012-08-16 15:59:00,507 INFO 15:59:00,507 GC for ParNew: 456 ms for 2
>> collections, 6233109512 used; max is 8550678528
>> 2012-08-16 15:59:01,022920.633: [GC 920.633: [ParNew:
>> 345022K->38336K(345024K), 0.2590327 secs]
>> 6140813K->6065694K(8350272K), 0.2591528 secs] [Times: user=3.67
>> sys=0.00, real=0.27 secs]
>> 2012-08-16 15:59:01,521 INFO 15:59:01,521 GC for ParNew: 259 ms for 1
>> collections, 5916301064 used; max is 8550678528
>> 2012-08-16 15:59:01,942921.604: [GC 921.604: [ParNew:
>> 345001K->38334K(345024K), 0.2059791 secs]
>> 5576624K->5407950K(8350272K), 0.2060935 secs] [Times: user=3.07
>> sys=0.00, real=0.20 secs]
>> 2012-08-16 15:59:02,535 INFO 15:59:02,535 GC for ParNew: 206 ms for 1
>> collections, 4951508912 used; max is 8550678528
>> 2012-08-16 15:59:06,185925.865: [GC 925.865: [ParNew:
>> 345022K->38334K(345024K), 0.1944824 secs]
>> 2207361K->2034487K(8350272K), 0.1946014 secs] [Times: user=2.54
>> sys=0.00, real=0.19 secs]
>> 2012-08-16 15:59:06,747926.624: [CMS-concurrent-sweep: 6.301/7.685
>> secs] [Times: user=36.33 sys=0.37, real=7.67 secs]
>> 2012-08-16 15:59:06,747926.624: [CMS-concurrent-reset-start]
>> 2012-08-16 15:59:06,778926.644: [CMS-concurrent-reset: 0.020/0.020
>> secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
>> 2012-08-16 15:59:07,699927.442: [GC 927.442: [ParNew:
>> 345022K->38336K(345024K), 0.1241401 secs]
>> 2087777K->1881732K(8350272K), 0.1242536 secs] [Times: user=1.47
>> sys=0.00, real=0.13 secs]
>> 2012-08-16 15:59:10,241929.912: [GC 929.912: [ParNew:
>> 345024K->38334K(345024K), 0.1987855 secs]
>> 2188420K->2049927K(8350272K), 0.1989237 secs] [Times: user=2.73
>> sys=0.00, real=0.20 secs]
>> 2012-08-16 15:59:10,912930.557: [GC 930.558: [ParNew:
>> 345022K->38336K(345024K), 0.2269435 secs]
>> 2356615K->2253199K(8350272K), 0.2270702 secs] [Times: user=2.98
>> sys=0.00, real=0.22 secs]
>> 2012-08-16 15:59:10,912 INFO 15:59:10,912 GC for ParNew: 426 ms for 2
>> collections, 2312471792 used; max is 8550678528
>> 2012-08-16 15:59:11,521931.148: [GC 931.148: [ParNew:
>> 345024K->38334K(345024K), 0.2371360 secs]
>> 2559887K->2475870K(8350272K), 0.2372526 secs] [Times: user=3.10
>> sys=0.00, real=0.25 secs]
>> 2012-08-16 15:59:11,926 INFO 15:59:11,926 GC for ParNew: 237 ms for 1
>> collections, 2763895872 used; max is 8550678528
>> 2012-08-16 15:59:12,441932.137: [GC 932.137: [ParNew:
>> 345022K->38336K(345024K), 0.1733826 secs]
>> 2782558K->2622114K(8350272K), 0.1735015 secs] [Times: user=2.42
>> sys=0.02, real=0.17 secs]
>> 2012-08-16 15:59:13,549933.155: [GC 933.155: [ParNew:
>> 345024K->38334K(345024K), 0.2625127 secs]
>> 2928802K->2829867K(8350272K), 0.2626344 secs] [Times: user=3.77
>> sys=0.00, real=0.27 secs]
>> 2012-08-16 15:59:14,188933.808: [GC 933.808: [ParNew:
>> 345022K->38334K(345024K), 0.2505625 secs]
>> 3136555K->3054091K(8350272K), 0.2506795 secs] [Times: user=3.46
>> sys=0.00, real=0.25 secs]
>> 2012-08-16 15:59:14,188 INFO 15:59:14,188 GC for ParNew: 513 ms for 2
>> collections, 3134992208 used; max is 8550678528
>> 2012-08-16 15:59:14,890934.522: [GC 934.523: [ParNew:
>> 345022K->38336K(345024K), 0.2316504 secs]
>> 3360779K->3275423K(8350272K), 0.2317766 secs] [Times: user=3.13
>> sys=0.00, real=0.23 secs]
>> 2012-08-16 15:59:15,202 INFO 15:59:15,202 GC for ParNew: 232 ms for 1
>> collections, 3536955232 used; max is 8550678528
>> 2012-08-16 15:59:15,920935.625: [GC 935.625: [ParNew:
>> 345024K->38334K(345024K), 0.1714062 secs]
>> 3582111K->3415888K(8350272K), 0.1715367 secs] [Times: user=2.54
>> sys=0.00, real=0.17 secs]
>> 2012-08-16 15:59:16,513936.119: [GC 936.119: [ParNew:
>> 345022K->38334K(345024K), 0.2719661 secs]
>> 3722576K->3649948K(8350272K), 0.2720966 secs] [Times: user=3.74
>> sys=0.00, real=0.27 secs]
>> 2012-08-16 15:59:17,059936.685: [GC 936.685: [ParNew:
>> 345022K->38336K(345024K), 0.2452667 secs]
>> 3956636K->3871076K(8350272K), 0.2453914 secs] [Times: user=3.62
>> sys=0.00, real=0.25 secs]
>> 2012-08-16 15:59:17,230 INFO 15:59:17,230 GC for ParNew: 517 ms for 2
>> collections, 4081462864 used; max is 8550678528
>> 2012-08-16 15:59:17,651937.255: [GC 937.255: [ParNew:
>> 345024K->38334K(345024K), 0.2594023 secs]
>> 4177764K->4099640K(8350272K), 0.2595243 secs] [Times: user=3.49
>> sys=0.01, real=0.27 secs]
>> 2012-08-16 15:59:18,213937.825: [GC 937.825: [ParNew:
>> 345022K->38336K(345024K), 0.2584561 secs]
>> 4406328K->4332694K(8350272K), 0.2585750 secs] [Times: user=3.74
>> sys=0.00, real=0.27 secs]
>> 2012-08-16 15:59:18,244 INFO 15:59:18,244 GC for ParNew: 518 ms for 2
>> collections, 4451788480 used; max is 8550678528
>> 2012-08-16 15:59:19,165938.841: [GC 938.841: [ParNew:
>> 344991K->38334K(345024K), 0.1994641 secs]
>> 4639350K->4482568K(8350272K), 0.1995789 secs] [Times: user=2.56
>> sys=0.01, real=0.19 secs]
>> 2012-08-16 15:59:25,717945.440: [GC 945.440: [ParNew:
>> 344963K->38334K(345024K), 0.1440731 secs]
>> 4789197K->4538905K(8350272K), 0.1442125 secs] [Times: user=1.61
>> sys=0.00, real=0.14 secs]
>> 2012-08-16 15:59:26,372945.966: [GC 945.966: [ParNew:
>> 345022K->38336K(345024K), 0.2803466 secs]
>> 4845593K->4785922K(8350272K), 0.2804798 secs] [Times: user=3.92
>> sys=0.00, real=0.28 secs]
>> 2012-08-16 15:59:26,372 INFO 15:59:26,372 GC for ParNew: 425 ms for 2
>> collections, 4903116472 used; max is 8550678528
>> 2012-08-16 15:59:26,965946.589: [GC 946.589: [ParNew:
>> 345024K->38336K(345024K), 0.2496506 secs]
>> 5092610K->5017752K(8350272K), 0.2497695 secs] [Times: user=3.60
>> sys=0.00, real=0.25 secs]
>> 2012-08-16 15:59:27,526947.149: [GC 947.149: [ParNew:
>> 345024K->38336K(345024K), 0.2427009 secs]
>> 5324440K->5242855K(8350272K), 0.2428195 secs] [Times: user=3.21
>> sys=0.00, real=0.25 secs]
>> 2012-08-16 15:59:27,526 INFO 15:59:27,526 GC for ParNew: 492 ms for 2
>> collections, 5374819504 used; max is 8550678528
>> 2012-08-16 15:59:28,088947.717: [GC 947.717: [ParNew:
>> 345024K->38336K(345024K), 0.2467160 secs]
>> 5549543K->5469437K(8350272K), 0.2468315 secs] [Times: user=3.39
>> sys=0.00, real=0.23 secs]
>> 2012-08-16 15:59:28,540 INFO 15:59:28,540 GC for ParNew: 247 ms for 1
>> collections, 5756868992 used; max is 8550678528
>> 2012-08-16 15:59:29,195948.871: [GC 948.871: [ParNew:
>> 345024K->38334K(345024K), 0.1934754 secs]
>> 5776125K->5599289K(8350272K), 0.1935862 secs] [Times: user=2.70
>> sys=0.00, real=0.20 secs]
>> 2012-08-16 15:59:29,710949.316: [GC 949.316: [ParNew:
>> 345022K->38334K(345024K), 0.2601060 secs]
>> 5905977K->5828882K(8350272K), 0.2602222 secs] [Times: user=3.46
>> sys=0.00, real=0.27 secs]
>> 2012-08-16 15:59:29,710 INFO 15:59:29,710 GC for ParNew: 454 ms for 2
>> collections, 5975471248 used; max is 8550678528
>> 2012-08-16 15:59:30,194949.830: [GC 949.830: [ParNew:
>> 345022K->38336K(345024K), 0.2380811 secs]
>> 6135570K->6042546K(8350272K), 0.2382000 secs] [Times: user=3.14
>> sys=0.00, real=0.23 secs]
>> 2012-08-16 15:59:30,225950.069: [GC [1 CMS-initial-mark:
>> 6004210K(8005248K)] 6042548K(8350272K), 0.0260419 secs] [Times:
>> user=0.03 sys=0.00, real=0.03 secs]
>> 2012-08-16 15:59:30,225950.095: [CMS-concurrent-mark-start]
>> 2012-08-16 15:59:30,443950.316: [CMS-concurrent-mark: 0.221/0.221
>> secs] [Times: user=2.06 sys=0.13, real=0.22 secs]
>> 2012-08-16 15:59:30,443950.316: [CMS-concurrent-preclean-start]
>> 2012-08-16 15:59:30,459950.336: [CMS-concurrent-preclean: 0.020/0.020
>> secs] [Times: user=0.06 sys=0.01, real=0.02 secs]
>> 2012-08-16 15:59:30,459950.336: [CMS-concurrent-abortable-preclean-start]
>> 2012-08-16 15:59:30,818950.463: [GC 950.463: [ParNew:
>> 345024K->38336K(345024K), 0.2228510 secs]
>> 6349234K->6252442K(8350272K), 0.2229688 secs] [Times: user=3.14
>> sys=0.00, real=0.22 secs]
>> 2012-08-16 15:59:30,818 INFO 15:59:30,818 GC for ParNew: 461 ms for 2
>> collections, 6406860032 used; max is 8550678528
>> 2012-08-16 15:59:31,395950.997: [GC 950.997: [ParNew:
>> 345024K->38336K(345024K), 0.2692564 secs]
>> 6559130K->6493591K(8350272K), 0.2693750 secs] [Times: user=3.81
>> sys=0.00, real=0.26 secs]
>> 2012-08-16 15:59:31,707951.580: [CMS-concurrent-abortable-preclean:
>> 0.750/1.245 secs] [Times: user=10.84 sys=0.13, real=1.25 secs]
>> 2012-08-16 15:59:31,723951.581: [GC[YG occupancy: 190327 K (345024
>> K)]951.581: [Rescan (parallel) , 0.0126204 secs]951.593: [weak refs
>> processing, 0.0000085 secs] [1 CMS-remark: 6455255K(8005248K)]
>> 6645582K(8350272K), 0.0127259 secs] [Times: user=0.28 sys=0.00,
>> real=0.02 secs]
>> 2012-08-16 15:59:31,723951.593: [CMS-concurrent-sweep-start]
>> 2012-08-16 15:59:31,832 INFO 15:59:31,832 GC for ParNew: 269 ms for 1
>> collections, 6764806360 used; max is 8550678528
>> 2012-08-16 15:59:32,362952.030: [GC 952.030: [ParNew:
>> 345024K->38334K(345024K), 0.1960234 secs]
>> 6293501K->6126054K(8350272K), 0.1961435 secs] [Times: user=2.89
>> sys=0.02, real=0.20 secs]
>> 2012-08-16 15:59:35,685955.406: [GC 955.406: [ParNew:
>> 345006K->38336K(345024K), 0.1556453 secs]
>> 2927846K->2691941K(8350272K), 0.1557619 secs] [Times: user=2.39
>> sys=0.02, real=0.16 secs]
>> 2012-08-16 15:59:36,325955.902: [GC 955.902: [ParNew:
>> 345024K->38334K(345024K), 0.2880415 secs]
>> 2887108K->2831437K(8350272K), 0.2881643 secs] [Times: user=4.04
>> sys=0.00, real=0.30 secs]
>> 2012-08-16 15:59:36,902956.561: [GC 956.561: [ParNew:
>> 345022K->38334K(345024K), 0.2172772 secs]
>> 2933661K->2836344K(8350272K), 0.2173954 secs] [Times: user=3.04
>> sys=0.00, real=0.22 secs]
>> 2012-08-16 15:59:36,902 INFO 15:59:36,902 GC for ParNew: 505 ms for 2
>> collections, 2909226128 used; max is 8550678528
>> 2012-08-16 15:59:37,573957.194: [GC 957.194: [ParNew:
>> 345022K->38336K(345024K), 0.2457267 secs]
>> 2835640K->2761950K(8350272K), 0.2458564 secs] [Times: user=3.43
>> sys=0.00, real=0.25 secs]
>> 2012-08-16 15:59:38,087957.692: [GC 957.692: [ParNew:
>> 345024K->38334K(345024K), 0.2580753 secs]
>> 2883419K->2810105K(8350272K), 0.2581927 secs] [Times: user=3.43
>> sys=0.00, real=0.25 secs]
>> 2012-08-16 15:59:38,087 INFO 15:59:38,087 GC for ParNew: 504 ms for 2
>> collections, 2883187080 used; max is 8550678528
>> 2012-08-16 15:59:39,273958.942: [GC 958.942: [ParNew:
>> 345022K->38336K(345024K), 0.1964326 secs]
>> 2691229K->2515113K(8350272K), 0.1965519 secs] [Times: user=2.87
>> sys=0.00, real=0.20 secs]
>> 2012-08-16 15:59:39,694959.568: [CMS-concurrent-sweep: 6.414/7.975
>> secs] [Times: user=44.04 sys=0.72, real=7.97 secs]
>> 2012-08-16 15:59:39,694959.568: [CMS-concurrent-reset-start]
>> 2012-08-16 15:59:39,725959.590: [CMS-concurrent-reset: 0.022/0.022
>> secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
>> 2012-08-16 15:59:41,956961.725: [GC 961.725: [ParNew:
>> 344994K->38334K(345024K), 0.0970048 secs]
>> 2645182K->2381114K(8350272K), 0.0971442 secs] [Times: user=0.92
>> sys=0.00, real=0.09 secs]
>> 2012-08-16 15:59:46,043965.815: [GC 965.816: [ParNew:
>> 345022K->38336K(345024K), 0.0998408 secs]
>> 2687802K->2449434K(8350272K), 0.0999933 secs] [Times: user=1.08
>> sys=0.02, real=0.09 secs]
>> 2012-08-16 15:59:46,511966.115: [GC 966.115: [ParNew:
>> 344629K->38336K(345024K), 0.2663284 secs]
>> 2755727K->2687941K(8350272K), 0.2664512 secs] [Times: user=3.46
>> sys=0.00, real=0.26 secs]
>> 2012-08-16 15:59:47,089966.709: [GC 966.709: [ParNew:
>> 344990K->38336K(345024K), 0.2430397 secs]
>> 2994595K->2921799K(8350272K), 0.2431602 secs] [Times: user=3.40
>> sys=0.02, real=0.25 secs]
>> 2012-08-16 15:59:47,681967.293: [GC 967.293: [ParNew:
>> 345024K->38336K(345024K), 0.2527240 secs]
>> 3228487K->3156972K(8350272K), 0.2528499 secs] [Times: user=3.45
>> sys=0.00, real=0.27 secs]
>> 2012-08-16 15:59:47,681 INFO 15:59:47,681 GC for ParNew: 496 ms for 2
>> collections, 3235405952 used; max is 8550678528
>> 2012-08-16 15:59:48,415968.061: [GC 968.061: [ParNew:
>> 345024K->38336K(345024K), 0.2184791 secs]
>> 3463660K->3348605K(8350272K), 0.2185973 secs] [Times: user=2.87
>> sys=0.00, real=0.22 secs]
>> 2012-08-16 15:59:48,695 INFO 15:59:48,695 GC for ParNew: 219 ms for 1
>> collections, 3493343744 used; max is 8550678528
>> 2012-08-16 15:59:49,631969.245: [GC 969.245: [ParNew:
>> 345024K->38336K(345024K), 0.2571372 secs]
>> 3655293K->3536159K(8350272K), 0.2572561 secs] [Times: user=3.67
>> sys=0.00, real=0.25 secs]
>> 2012-08-16 15:59:49,709 INFO 15:59:49,709 GC for ParNew: 257 ms for 1
>> collections, 3726925432 used; max is 8550678528
>> 2012-08-16 15:59:50,162969.766: [GC 969.766: [ParNew:
>> 345024K->38334K(345024K), 0.2653560 secs]
>> 3842847K->3774598K(8350272K), 0.2654692 secs] [Times: user=3.90
>> sys=0.00, real=0.26 secs]
>> 2012-08-16 15:59:50,723970.347: [GC 970.347: [ParNew:
>> 345022K->38336K(345024K), 0.2484206 secs]
>> 4081286K->4008970K(8350272K), 0.2485346 secs] [Times: user=3.56
>> sys=0.00, real=0.25 secs]
>> 2012-08-16 15:59:50,723 INFO 15:59:50,723 GC for ParNew: 514 ms for 2
>> collections, 4110795240 used; max is 8550678528
>> 2012-08-16 15:59:51,363970.965: [GC 970.965: [ParNew:
>> 345024K->38334K(345024K), 0.2646304 secs]
>> 4315658K->4258131K(8350272K), 0.2647516 secs] [Times: user=3.67
>> sys=0.00, real=0.26 secs]
>> 2012-08-16 15:59:51,737 INFO 15:59:51,737 GC for ParNew: 264 ms for 1
>> collections, 4581460088 used; max is 8550678528
>> 2012-08-16 15:59:52,299971.961: [GC 971.961: [ParNew:
>> 345022K->38334K(345024K), 0.2041610 secs]
>> 4564819K->4427702K(8350272K), 0.2042765 secs] [Times: user=2.62
>> sys=0.00, real=0.20 secs]
>> 2012-08-16 15:59:52,751 INFO 15:59:52,751 GC for ParNew: 205 ms for 1
>> collections, 4640258968 used; max is 8550678528
>> 2012-08-16 15:59:55,669975.335: [GC 975.335: [ParNew:
>> 345022K->38336K(345024K), 0.2031359 secs]
>> 4734390K->4513398K(8350272K), 0.2032737 secs] [Times: user=2.67
>> sys=0.00, real=0.20 secs]
>> 2012-08-16 15:59:55,793 INFO 15:59:55,793 GC for ParNew: 203 ms for 1
>> collections, 4637851352 used; max is 8550678528
>> 2012-08-16 15:59:56,495976.118: [GC 976.118: [ParNew:
>> 345024K->38334K(345024K), 0.2428765 secs]
>> 4820086K->4719356K(8350272K), 0.2430081 secs] [Times: user=3.40
>> sys=0.00, real=0.25 secs]
>> 2012-08-16 15:59:56,963976.598: [GC 976.598: [ParNew:
>> 345022K->38336K(345024K), 0.2291020 secs]
>> 5026044K->4940991K(8350272K), 0.2292186 secs] [Times: user=3.35
>> sys=0.02, real=0.23 secs]
>> 2012-08-16 15:59:56,963 INFO 15:59:56,963 GC for ParNew: 472 ms for 2
>> collections, 5061091520 used; max is 8550678528
>> 2012-08-16 15:59:57,478977.138: [GC 977.138: [ParNew:
>> 345024K->38334K(345024K), 0.2138650 secs]
>> 5247679K->5145409K(8350272K), 0.2139793 secs] [Times: user=2.79
>> sys=0.00, real=0.20 secs]
>> 2012-08-16 15:59:58,024977.628: [GC 977.628: [ParNew:
>> 345022K->38334K(345024K), 0.2597949 secs]
>> 5452097K->5382216K(8350272K), 0.2599123 secs] [Times: user=3.49
>> sys=0.00, real=0.26 secs]
>> 2012-08-16 15:59:58,024 INFO 15:59:58,024 GC for ParNew: 474 ms for 2
>> collections, 5520513520 used; max is 8550678528
>> 2012-08-16 15:59:58,913978.616: [GC 978.616: [ParNew:
>> 345022K->38336K(345024K), 0.1699849 secs]
>> 5688904K->5512877K(8350272K), 0.1700962 secs] [Times: user=2.50
>> sys=0.00, real=0.17 secs]
>> 2012-08-16 16:00:00,271979.992: [GC 979.992: [ParNew:
>> 344994K->38334K(345024K), 0.1453127 secs]
>> 5819535K->5572894K(8350272K), 0.1454497 secs] [Times: user=1.70
>> sys=0.02, real=0.16 secs]
>> 2012-08-16 16:00:04,545984.343: [GC 984.343: [ParNew:
>> 344994K->37933K(345024K), 0.0741034 secs]
>> 5879554K->5610224K(8350272K), 0.0742458 secs] [Times: user=0.30
>> sys=0.00, real=0.08 secs]
>> 2012-08-16 16:00:07,119986.764: [GC 986.764: [ParNew:
>> 344621K->38336K(345024K), 0.2181230 secs]
>> 5916912K->5759381K(8350272K), 0.2182593 secs] [Times: user=2.67
>> sys=0.03, real=0.22 secs]
>> 2012-08-16 16:00:07,150 INFO 16:00:07,150 GC for ParNew: 218 ms for 1
>> collections, 5930704288 used; max is 8550678528
>> 2012-08-16 16:00:08,164987.810: [GC 987.810: [ParNew:
>> 345024K->38336K(345024K), 0.2296247 secs]
>> 6066069K->5950068K(8350272K), 0.2297637 secs] [Times: user=2.87
>> sys=0.00, real=0.22 secs]
>> 2012-08-16 16:00:08,164 INFO 16:00:08,164 GC for ParNew: 230 ms for 1
>> collections, 6098706784 used; max is 8550678528
>> 2012-08-16 16:00:08,819988.430: [GC 988.430: [ParNew:
>> 345024K->38336K(345024K), 0.2652883 secs]
>> 6256756K->6190892K(8350272K), 0.2654107 secs] [Times: user=3.90
>> sys=0.00, real=0.27 secs]
>> 2012-08-16 16:00:08,851988.695: [GC [1 CMS-initial-mark:
>> 6152556K(8005248K)] 6191809K(8350272K), 0.0267734 secs] [Times:
>> user=0.03 sys=0.00, real=0.03 secs]
>> 2012-08-16 16:00:08,851988.722: [CMS-concurrent-mark-start]
>> 2012-08-16 16:00:09,100988.973: [CMS-concurrent-mark: 0.250/0.250
>> secs] [Times: user=2.29 sys=0.06, real=0.25 secs]
>> 2012-08-16 16:00:09,100988.973: [CMS-concurrent-preclean-start]
>> 2012-08-16 16:00:09,131989.005: [CMS-concurrent-preclean: 0.032/0.033
>> secs] [Times: user=0.14 sys=0.02, real=0.03 secs]
>> 2012-08-16 16:00:09,131989.005: [CMS-concurrent-abortable-preclean-start]
>> 2012-08-16 16:00:09,194 INFO 16:00:09,194 GC for ParNew: 265 ms for 1
>> collections, 6523586752 used; max is 8550678528
>> 2012-08-16 16:00:09,537989.149: [GC 989.150: [ParNew:
>> 345024K->38336K(345024K), 0.2521832 secs]
>> 6497580K->6413622K(8350272K), 0.2523014 secs] [Times: user=3.65
>> sys=0.00, real=0.26 secs]
>> 2012-08-16 16:00:09,896989.760: [CMS-concurrent-abortable-preclean:
>> 0.499/0.755 secs] [Times: user=5.90 sys=0.05, real=0.76 secs]
>> 2012-08-16 16:00:09,911989.760: [GC[YG occupancy: 215512 K (345024
>> K)]989.760: [Rescan (parallel) , 0.0248524 secs]989.785: [weak refs
>> processing, 0.0000169 secs] [1 CMS-remark: 6375286K(8005248K)]
>> 6590799K(8350272K), 0.0249718 secs] [Times: user=0.19 sys=0.00,
>> real=0.02 secs]
>> 2012-08-16 16:00:09,911989.785: [CMS-concurrent-sweep-start]
>> 2012-08-16 16:00:10,208 INFO 16:00:10,208 GC for ParNew: 253 ms for 1
>> collections, 6481264200 used; max is 8550678528
>> 2012-08-16 16:00:10,816990.457: [GC 990.457: [ParNew:
>> 345024K->38336K(345024K), 0.2229088 secs]
>> 5892628K->5747038K(8350272K), 0.2230343 secs] [Times: user=3.14
>> sys=0.00, real=0.23 secs]
>> 2012-08-16 16:00:11,222 INFO 16:00:11,222 GC for ParNew: 222 ms for 1
>> collections, 5618012152 used; max is 8550678528
>> 2012-08-16 16:00:16,167995.849: [GC 995.849: [ParNew:
>> 345024K->38336K(345024K), 0.1941598 secs]
>> 3109823K->2945213K(8350272K), 0.1943046 secs] [Times: user=2.62
>> sys=0.00, real=0.19 secs]
>> 2012-08-16 16:00:17,072996.699: [GC 996.699: [ParNew:
>> 345024K->38336K(345024K), 0.2477104 secs]
>> 3005684K->2909884K(8350272K), 0.2478259 secs] [Times: user=3.45
>> sys=0.00, real=0.25 secs]
>> 2012-08-16 16:00:17,306 INFO 16:00:17,306 GC for ParNew: 247 ms for 1
>> collections, 2907671688 used; max is 8550678528
>> 2012-08-16 16:00:18,570998.243: [GC 998.243: [ParNew:
>> 345024K->38336K(345024K), 0.1898907 secs]
>> 2788564K->2632153K(8350272K), 0.1900108 secs] [Times: user=2.64
>> sys=0.00, real=0.20 secs]
>> 2012-08-16 16:00:19,443999.086: [GC 999.086: [ParNew:
>> 345024K->38336K(345024K), 0.2223548 secs]
>> 2719738K->2599595K(8350272K), 0.2224745 secs] [Times: user=3.15
>> sys=0.00, real=0.23 secs]
>> 2012-08-16 16:00:19,443 INFO 16:00:19,443 GC for ParNew: 413 ms for 2
>> collections, 2664222584 used; max is 8550678528
>> 2012-08-16 16:00:19,911999.515: [GC 999.515: [ParNew:
>> 345024K->38334K(345024K), 0.2598227 secs]
>> 2719357K->2655204K(8350272K), 0.2599416 secs] [Times: user=3.62
>> sys=0.00, real=0.27 secs]
>> 2012-08-16 16:00:20,5821000.185: [GC 1000.185: [ParNew:
>> 345022K->38336K(345024K), 0.2591240 secs]
>> 2761843K->2686494K(8350272K), 0.2592448 secs] [Times: user=3.46
>> sys=0.00, real=0.27 secs]
>> 2012-08-16 16:00:20,582 INFO 16:00:20,582 GC for ParNew: 519 ms for 2
>> collections, 2756113024 used; max is 8550678528
>> 2012-08-16 16:00:21,1901000.808: [GC 1000.808: [ParNew:
>> 344971K->38334K(345024K), 0.2520519 secs]
>> 2760422K->2688079K(8350272K), 0.2521670 secs] [Times: user=3.65
>> sys=0.02, real=0.25 secs]
>> 2012-08-16 16:00:21,5021001.375: [CMS-concurrent-sweep: 9.737/11.590
>> secs] [Times: user=49.31 sys=0.78, real=11.59 secs]
>> 2012-08-16 16:00:21,5021001.375: [CMS-concurrent-reset-start]
>> 2012-08-16 16:00:21,5341001.403: [CMS-concurrent-reset: 0.028/0.028
>> secs] [Times: user=0.16 sys=0.00, real=0.03 secs]
>> 2012-08-16 16:00:21,596 INFO 16:00:21,596 GC for ParNew: 252 ms for 1
>> collections, 2680484480 used; max is 8550678528
>>
>>
Re: Many ParNew collections
Posted by Rene Kochen <re...@schange.com>.
Thanks Aaron,
At another production site the exact same problems occur (also after
~6 months). Here I have a very small cluster of three nodes with
replication factor = 3.
One of the three nodes begins to have many long Parnews and high CPU
load. I upgraded to Cassandra 1.0.11, but the GC problem still
continues on that node.
If I look at the CFStats of the three nodes, there is one CF which is different:
Column Family: Logs
SSTable count: 1
Space used (live): 47606705
Space used (total): 47606705
Number of Keys (estimate): 338176
Memtable Columns Count: 22297
Memtable Data Size: 51542275
Memtable Switch Count: 1
Read Count: 189441
Read Latency: 0,768 ms.
Write Count: 123411
Write Latency: 0,035 ms.
Pending Tasks: 0
Bloom Filter False Postives: 0
Bloom Filter False Ratio: 0,00000
Bloom Filter Space Used: 721456
Key cache capacity: 200000
Key cache size: 56685
Key cache hit rate: 0.9132482658217008
Row cache: disabled
Compacted row minimum size: 73
Compacted row maximum size: 263210
Compacted row mean size: 94
Column Family: Logs
SSTable count: 3
Space used (live): 233688199
Space used (total): 233688199
Number of Keys (estimate): 1191936
Memtable Columns Count: 20147
Memtable Data Size: 47067518
Memtable Switch Count: 1
Read Count: 188473
Read Latency: 4031,791 ms.
Write Count: 120412
Write Latency: 0,042 ms.
Pending Tasks: 0
Bloom Filter False Postives: 234
Bloom Filter False Ratio: 0,00000
Bloom Filter Space Used: 2603808
Key cache capacity: 200000
Key cache size: 5153
Key cache hit rate: 1.0
Row cache: disabled
Compacted row minimum size: 73
Compacted row maximum size: 25109160
Compacted row mean size: 156
Column Family: Logs
SSTable count: 1
Space used (live): 47714798
Space used (total): 47714798
Number of Keys (estimate): 338176
Memtable Columns Count: 29046
Memtable Data Size: 66585390
Memtable Switch Count: 1
Read Count: 196048
Read Latency: 1,466 ms.
Write Count: 127709
Write Latency: 0,034 ms.
Pending Tasks: 0
Bloom Filter False Postives: 8
Bloom Filter False Ratio: 0,00847
Bloom Filter Space Used: 720496
Key cache capacity: 200000
Key cache size: 54166
Key cache hit rate: 0.9833443960960739
Row cache: disabled
Compacted row minimum size: 73
Compacted row maximum size: 263210
Compacted row mean size: 95
The second node (the one suffering from many GC) has a high read
latency compared to the others. Another thing is that the compacted
row maximum size is bigger than on the other nodes.
What puzzles me:
- Should the other nodes also have that wide row, because the
replication factor is three and I only have three nodes? I must say
that the wide row is probably the index row which has columns
added/removed continuously. Maybe the other nodes lost much data
because of compactions?
- Could repeatedly reading a wide row cause parnew problems?
Thanks!
Rene
2012/8/17 aaron morton <aa...@thelastpickle.com>:
> - Cassandra 0.7.10
>
> You _really_ should look at getting up to 1.1 :) Memory management is much
> better and the JVM heap requirements are less.
>
> However, there is one node with high read latency and far too many
> ParNew collections (compared to other nodes).
>
> Check for long running compactions or repairs.
> Check for unexpected row or key cache settings.
> Look at the connections on the box and see if it is getting more client load
> than others.
>
> Restart the node and see if the situations returns. If it does try to
> correlate the start of the GC issues with the cassandra log.
>
> Hope that helps.
>
> -----------------
> Aaron Morton
> Freelance Developer
> @aaronmorton
> http://www.thelastpickle.com
>
> On 17/08/2012, at 2:58 AM, Rene Kochen <re...@schange.com> wrote:
>
> Hi
>
> I have a cluster of 7 nodes:
>
> - Windows Server 2008
> - Cassandra 0.7.10
> - The nodes are identical (hardware, configuration and client request load)
> - Standard batch file with 8GB heap
> - I use disk_access_mode = standard
> - Random partitioner
> - TP stats shows no problems
> - Ring command shows no problems (data is balanced)
>
> However, there is one node with high read latency and far too many
> ParNew collections (compared to other nodes). It also suffers from a
> high CPU load (I guess due to the ParNew collections).
>
> What can be the source of so many ParNew collections? The other
> identical nodes do not have this behavior.
>
> Logging:
>
> 2012-08-16 15:58:46,436906.072: [GC 906.072: [ParNew:
> 345022K->38336K(345024K), 0.2375976 secs]
> 3630599K->3516249K(8350272K), 0.2377296 secs] [Times: user=3.21
> sys=0.00, real=0.23 secs]
> 2012-08-16 15:58:46,888906.517: [GC 906.517: [ParNew:
> 345024K->38336K(345024K), 0.2400594 secs]
> 3822937K->3743690K(8350272K), 0.2401802 secs] [Times: user=3.48
> sys=0.03, real=0.25 secs]
> 2012-08-16 15:58:46,888 INFO 15:58:46,888 GC for ParNew: 478 ms for 2
> collections, 3837792904 used; max is 8550678528
> 2012-08-16 15:58:47,372907.003: [GC 907.003: [ParNew:
> 345024K->38336K(345024K), 0.2405363 secs]
> 4050378K->3971544K(8350272K), 0.2406553 secs] [Times: user=3.34
> sys=0.01, real=0.23 secs]
> 2012-08-16 15:58:47,918907.544: [GC 907.544: [ParNew:
> 345024K->38336K(345024K), 0.2404339 secs]
> 4278232K->4193789K(8350272K), 0.2405540 secs] [Times: user=3.31
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:58:47,918 INFO 15:58:47,918 GC for ParNew: 481 ms for 2
> collections, 4300939752 used; max is 8550678528
> 2012-08-16 15:58:48,464908.079: [GC 908.079: [ParNew:
> 345024K->38336K(345024K), 0.2621174 secs]
> 4500477K->4434112K(8350272K), 0.2622375 secs] [Times: user=3.64
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:58:48,932 INFO 15:58:48,932 GC for ParNew: 262 ms for 1
> collections, 4763583200 used; max is 8550678528
> 2012-08-16 15:58:49,384909.050: [GC 909.051: [ParNew:
> 344972K->38336K(345024K), 0.2033453 secs]
> 4740748K->4563252K(8350272K), 0.2034588 secs] [Times: user=2.89
> sys=0.01, real=0.20 secs]
> 2012-08-16 15:58:49,946 INFO 15:58:49,946 GC for ParNew: 203 ms for 1
> collections, 4885945792 used; max is 8550678528
> 2012-08-16 15:58:50,383909.998: [GC 909.998: [ParNew:
> 345024K->38336K(345024K), 0.2567542 secs]
> 4869940K->4740489K(8350272K), 0.2568804 secs] [Times: user=3.60
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:58:50,882910.474: [GC 910.474: [ParNew:
> 345024K->38336K(345024K), 0.2786205 secs]
> 5047177K->4962531K(8350272K), 0.2787668 secs] [Times: user=3.48
> sys=0.00, real=0.28 secs]
> 2012-08-16 15:58:50,960 INFO 15:58:50,960 GC for ParNew: 536 ms for 2
> collections, 5143423816 used; max is 8550678528
> 2012-08-16 15:58:51,584911.192: [GC 911.192: [ParNew:
> 344963K->38334K(345024K), 0.2664316 secs]
> 5269158K->5196444K(8350272K), 0.2665544 secs] [Times: user=3.74
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:58:52,130911.767: [GC 911.767: [ParNew:
> 345022K->38336K(345024K), 0.2327209 secs]
> 5503132K->5406771K(8350272K), 0.2328457 secs] [Times: user=3.35
> sys=0.00, real=0.23 secs]
> 2012-08-16 15:58:52,130 INFO 15:58:52,130 GC for ParNew: 499 ms for 2
> collections, 5541845264 used; max is 8550678528
> 2012-08-16 15:58:52,816912.460: [GC 912.460: [ParNew:
> 345024K->38334K(345024K), 0.2198399 secs]
> 5713459K->5605670K(8350272K), 0.2199669 secs] [Times: user=3.29
> sys=0.00, real=0.23 secs]
> 2012-08-16 15:58:53,144 INFO 15:58:53,144 GC for ParNew: 220 ms for 1
> collections, 5805870608 used; max is 8550678528
> 2012-08-16 15:58:55,546915.173: [GC 915.173: [ParNew:
> 345022K->38334K(345024K), 0.2369585 secs]
> 5912358K->5702871K(8350272K), 0.2371098 secs] [Times: user=3.18
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:58:56,186 INFO 15:58:56,186 GC for ParNew: 237 ms for 1
> collections, 6089002480 used; max is 8550678528
> 2012-08-16 15:58:56,591916.232: [GC 916.232: [ParNew:
> 345022K->38336K(345024K), 0.2364850 secs]
> 6009559K->5914142K(8350272K), 0.2366075 secs] [Times: user=3.32
> sys=0.00, real=0.23 secs]
> 2012-08-16 15:58:57,340916.989: [GC 916.989: [ParNew:
> 345024K->38334K(345024K), 0.2191751 secs]
> 6220830K->6107217K(8350272K), 0.2192894 secs] [Times: user=2.92
> sys=0.00, real=0.22 secs]
> 2012-08-16 15:58:57,371917.209: [GC [1 CMS-initial-mark:
> 6068883K(8005248K)] 6108716K(8350272K), 0.0272472 secs] [Times:
> user=0.03 sys=0.00, real=0.03 secs]
> 2012-08-16 15:58:57,371917.236: [CMS-concurrent-mark-start]
> 2012-08-16 15:58:57,371 INFO 15:58:57,371 GC for ParNew: 456 ms for 2
> collections, 6255865264 used; max is 8550678528
> 2012-08-16 15:58:57,574917.444: [CMS-concurrent-mark: 0.208/0.208
> secs] [Times: user=1.48 sys=0.06, real=0.20 secs]
> 2012-08-16 15:58:57,574917.444: [CMS-concurrent-preclean-start]
> 2012-08-16 15:58:57,637917.501: [CMS-concurrent-preclean: 0.057/0.057
> secs] [Times: user=0.19 sys=0.00, real=0.06 secs]
> 2012-08-16 15:58:57,637917.501: [CMS-concurrent-abortable-preclean-start]
> 2012-08-16 15:58:58,775918.552: [GC 918.552: [ParNew:
> 345022K->38334K(345024K), 0.0948325 secs]
> 6413905K->6163063K(8350272K), 0.0949661 secs] [Times: user=1.22
> sys=0.00, real=0.09 secs]
> 2012-08-16 15:58:59,025918.896: [CMS-concurrent-abortable-preclean:
> 1.198/1.395 secs] [Times: user=5.26 sys=0.17, real=1.39 secs]
> 2012-08-16 15:58:59,072918.896: [GC[YG occupancy: 274623 K (345024
> K)]918.896: [Rescan (parallel) , 0.0427564 secs]918.939: [weak refs
> processing, 0.0000096 secs] [1 CMS-remark: 6124729K(8005248K)]
> 6399352K(8350272K), 0.0428734 secs] [Times: user=0.62 sys=0.00,
> real=0.05 secs]
> 2012-08-16 15:58:59,072918.939: [CMS-concurrent-sweep-start]
> 2012-08-16 15:58:59,368918.972: [GC 918.972: [ParNew:
> 345022K->38336K(345024K), 0.2652648 secs]
> 6465380K->6379989K(8350272K), 0.2654014 secs] [Times: user=3.71
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:58:59,930919.557: [GC 919.557: [ParNew:
> 345024K->38334K(345024K), 0.2417524 secs]
> 6433484K->6347081K(8350272K), 0.2418748 secs] [Times: user=3.40
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:00,507920.161: [GC 920.162: [ParNew:
> 345015K->38334K(345024K), 0.2142607 secs]
> 6191692K->6086072K(8350272K), 0.2143766 secs] [Times: user=3.09
> sys=0.00, real=0.22 secs]
> 2012-08-16 15:59:00,507 INFO 15:59:00,507 GC for ParNew: 456 ms for 2
> collections, 6233109512 used; max is 8550678528
> 2012-08-16 15:59:01,022920.633: [GC 920.633: [ParNew:
> 345022K->38336K(345024K), 0.2590327 secs]
> 6140813K->6065694K(8350272K), 0.2591528 secs] [Times: user=3.67
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:59:01,521 INFO 15:59:01,521 GC for ParNew: 259 ms for 1
> collections, 5916301064 used; max is 8550678528
> 2012-08-16 15:59:01,942921.604: [GC 921.604: [ParNew:
> 345001K->38334K(345024K), 0.2059791 secs]
> 5576624K->5407950K(8350272K), 0.2060935 secs] [Times: user=3.07
> sys=0.00, real=0.20 secs]
> 2012-08-16 15:59:02,535 INFO 15:59:02,535 GC for ParNew: 206 ms for 1
> collections, 4951508912 used; max is 8550678528
> 2012-08-16 15:59:06,185925.865: [GC 925.865: [ParNew:
> 345022K->38334K(345024K), 0.1944824 secs]
> 2207361K->2034487K(8350272K), 0.1946014 secs] [Times: user=2.54
> sys=0.00, real=0.19 secs]
> 2012-08-16 15:59:06,747926.624: [CMS-concurrent-sweep: 6.301/7.685
> secs] [Times: user=36.33 sys=0.37, real=7.67 secs]
> 2012-08-16 15:59:06,747926.624: [CMS-concurrent-reset-start]
> 2012-08-16 15:59:06,778926.644: [CMS-concurrent-reset: 0.020/0.020
> secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
> 2012-08-16 15:59:07,699927.442: [GC 927.442: [ParNew:
> 345022K->38336K(345024K), 0.1241401 secs]
> 2087777K->1881732K(8350272K), 0.1242536 secs] [Times: user=1.47
> sys=0.00, real=0.13 secs]
> 2012-08-16 15:59:10,241929.912: [GC 929.912: [ParNew:
> 345024K->38334K(345024K), 0.1987855 secs]
> 2188420K->2049927K(8350272K), 0.1989237 secs] [Times: user=2.73
> sys=0.00, real=0.20 secs]
> 2012-08-16 15:59:10,912930.557: [GC 930.558: [ParNew:
> 345022K->38336K(345024K), 0.2269435 secs]
> 2356615K->2253199K(8350272K), 0.2270702 secs] [Times: user=2.98
> sys=0.00, real=0.22 secs]
> 2012-08-16 15:59:10,912 INFO 15:59:10,912 GC for ParNew: 426 ms for 2
> collections, 2312471792 used; max is 8550678528
> 2012-08-16 15:59:11,521931.148: [GC 931.148: [ParNew:
> 345024K->38334K(345024K), 0.2371360 secs]
> 2559887K->2475870K(8350272K), 0.2372526 secs] [Times: user=3.10
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:11,926 INFO 15:59:11,926 GC for ParNew: 237 ms for 1
> collections, 2763895872 used; max is 8550678528
> 2012-08-16 15:59:12,441932.137: [GC 932.137: [ParNew:
> 345022K->38336K(345024K), 0.1733826 secs]
> 2782558K->2622114K(8350272K), 0.1735015 secs] [Times: user=2.42
> sys=0.02, real=0.17 secs]
> 2012-08-16 15:59:13,549933.155: [GC 933.155: [ParNew:
> 345024K->38334K(345024K), 0.2625127 secs]
> 2928802K->2829867K(8350272K), 0.2626344 secs] [Times: user=3.77
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:59:14,188933.808: [GC 933.808: [ParNew:
> 345022K->38334K(345024K), 0.2505625 secs]
> 3136555K->3054091K(8350272K), 0.2506795 secs] [Times: user=3.46
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:14,188 INFO 15:59:14,188 GC for ParNew: 513 ms for 2
> collections, 3134992208 used; max is 8550678528
> 2012-08-16 15:59:14,890934.522: [GC 934.523: [ParNew:
> 345022K->38336K(345024K), 0.2316504 secs]
> 3360779K->3275423K(8350272K), 0.2317766 secs] [Times: user=3.13
> sys=0.00, real=0.23 secs]
> 2012-08-16 15:59:15,202 INFO 15:59:15,202 GC for ParNew: 232 ms for 1
> collections, 3536955232 used; max is 8550678528
> 2012-08-16 15:59:15,920935.625: [GC 935.625: [ParNew:
> 345024K->38334K(345024K), 0.1714062 secs]
> 3582111K->3415888K(8350272K), 0.1715367 secs] [Times: user=2.54
> sys=0.00, real=0.17 secs]
> 2012-08-16 15:59:16,513936.119: [GC 936.119: [ParNew:
> 345022K->38334K(345024K), 0.2719661 secs]
> 3722576K->3649948K(8350272K), 0.2720966 secs] [Times: user=3.74
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:59:17,059936.685: [GC 936.685: [ParNew:
> 345022K->38336K(345024K), 0.2452667 secs]
> 3956636K->3871076K(8350272K), 0.2453914 secs] [Times: user=3.62
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:17,230 INFO 15:59:17,230 GC for ParNew: 517 ms for 2
> collections, 4081462864 used; max is 8550678528
> 2012-08-16 15:59:17,651937.255: [GC 937.255: [ParNew:
> 345024K->38334K(345024K), 0.2594023 secs]
> 4177764K->4099640K(8350272K), 0.2595243 secs] [Times: user=3.49
> sys=0.01, real=0.27 secs]
> 2012-08-16 15:59:18,213937.825: [GC 937.825: [ParNew:
> 345022K->38336K(345024K), 0.2584561 secs]
> 4406328K->4332694K(8350272K), 0.2585750 secs] [Times: user=3.74
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:59:18,244 INFO 15:59:18,244 GC for ParNew: 518 ms for 2
> collections, 4451788480 used; max is 8550678528
> 2012-08-16 15:59:19,165938.841: [GC 938.841: [ParNew:
> 344991K->38334K(345024K), 0.1994641 secs]
> 4639350K->4482568K(8350272K), 0.1995789 secs] [Times: user=2.56
> sys=0.01, real=0.19 secs]
> 2012-08-16 15:59:25,717945.440: [GC 945.440: [ParNew:
> 344963K->38334K(345024K), 0.1440731 secs]
> 4789197K->4538905K(8350272K), 0.1442125 secs] [Times: user=1.61
> sys=0.00, real=0.14 secs]
> 2012-08-16 15:59:26,372945.966: [GC 945.966: [ParNew:
> 345022K->38336K(345024K), 0.2803466 secs]
> 4845593K->4785922K(8350272K), 0.2804798 secs] [Times: user=3.92
> sys=0.00, real=0.28 secs]
> 2012-08-16 15:59:26,372 INFO 15:59:26,372 GC for ParNew: 425 ms for 2
> collections, 4903116472 used; max is 8550678528
> 2012-08-16 15:59:26,965946.589: [GC 946.589: [ParNew:
> 345024K->38336K(345024K), 0.2496506 secs]
> 5092610K->5017752K(8350272K), 0.2497695 secs] [Times: user=3.60
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:27,526947.149: [GC 947.149: [ParNew:
> 345024K->38336K(345024K), 0.2427009 secs]
> 5324440K->5242855K(8350272K), 0.2428195 secs] [Times: user=3.21
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:27,526 INFO 15:59:27,526 GC for ParNew: 492 ms for 2
> collections, 5374819504 used; max is 8550678528
> 2012-08-16 15:59:28,088947.717: [GC 947.717: [ParNew:
> 345024K->38336K(345024K), 0.2467160 secs]
> 5549543K->5469437K(8350272K), 0.2468315 secs] [Times: user=3.39
> sys=0.00, real=0.23 secs]
> 2012-08-16 15:59:28,540 INFO 15:59:28,540 GC for ParNew: 247 ms for 1
> collections, 5756868992 used; max is 8550678528
> 2012-08-16 15:59:29,195948.871: [GC 948.871: [ParNew:
> 345024K->38334K(345024K), 0.1934754 secs]
> 5776125K->5599289K(8350272K), 0.1935862 secs] [Times: user=2.70
> sys=0.00, real=0.20 secs]
> 2012-08-16 15:59:29,710949.316: [GC 949.316: [ParNew:
> 345022K->38334K(345024K), 0.2601060 secs]
> 5905977K->5828882K(8350272K), 0.2602222 secs] [Times: user=3.46
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:59:29,710 INFO 15:59:29,710 GC for ParNew: 454 ms for 2
> collections, 5975471248 used; max is 8550678528
> 2012-08-16 15:59:30,194949.830: [GC 949.830: [ParNew:
> 345022K->38336K(345024K), 0.2380811 secs]
> 6135570K->6042546K(8350272K), 0.2382000 secs] [Times: user=3.14
> sys=0.00, real=0.23 secs]
> 2012-08-16 15:59:30,225950.069: [GC [1 CMS-initial-mark:
> 6004210K(8005248K)] 6042548K(8350272K), 0.0260419 secs] [Times:
> user=0.03 sys=0.00, real=0.03 secs]
> 2012-08-16 15:59:30,225950.095: [CMS-concurrent-mark-start]
> 2012-08-16 15:59:30,443950.316: [CMS-concurrent-mark: 0.221/0.221
> secs] [Times: user=2.06 sys=0.13, real=0.22 secs]
> 2012-08-16 15:59:30,443950.316: [CMS-concurrent-preclean-start]
> 2012-08-16 15:59:30,459950.336: [CMS-concurrent-preclean: 0.020/0.020
> secs] [Times: user=0.06 sys=0.01, real=0.02 secs]
> 2012-08-16 15:59:30,459950.336: [CMS-concurrent-abortable-preclean-start]
> 2012-08-16 15:59:30,818950.463: [GC 950.463: [ParNew:
> 345024K->38336K(345024K), 0.2228510 secs]
> 6349234K->6252442K(8350272K), 0.2229688 secs] [Times: user=3.14
> sys=0.00, real=0.22 secs]
> 2012-08-16 15:59:30,818 INFO 15:59:30,818 GC for ParNew: 461 ms for 2
> collections, 6406860032 used; max is 8550678528
> 2012-08-16 15:59:31,395950.997: [GC 950.997: [ParNew:
> 345024K->38336K(345024K), 0.2692564 secs]
> 6559130K->6493591K(8350272K), 0.2693750 secs] [Times: user=3.81
> sys=0.00, real=0.26 secs]
> 2012-08-16 15:59:31,707951.580: [CMS-concurrent-abortable-preclean:
> 0.750/1.245 secs] [Times: user=10.84 sys=0.13, real=1.25 secs]
> 2012-08-16 15:59:31,723951.581: [GC[YG occupancy: 190327 K (345024
> K)]951.581: [Rescan (parallel) , 0.0126204 secs]951.593: [weak refs
> processing, 0.0000085 secs] [1 CMS-remark: 6455255K(8005248K)]
> 6645582K(8350272K), 0.0127259 secs] [Times: user=0.28 sys=0.00,
> real=0.02 secs]
> 2012-08-16 15:59:31,723951.593: [CMS-concurrent-sweep-start]
> 2012-08-16 15:59:31,832 INFO 15:59:31,832 GC for ParNew: 269 ms for 1
> collections, 6764806360 used; max is 8550678528
> 2012-08-16 15:59:32,362952.030: [GC 952.030: [ParNew:
> 345024K->38334K(345024K), 0.1960234 secs]
> 6293501K->6126054K(8350272K), 0.1961435 secs] [Times: user=2.89
> sys=0.02, real=0.20 secs]
> 2012-08-16 15:59:35,685955.406: [GC 955.406: [ParNew:
> 345006K->38336K(345024K), 0.1556453 secs]
> 2927846K->2691941K(8350272K), 0.1557619 secs] [Times: user=2.39
> sys=0.02, real=0.16 secs]
> 2012-08-16 15:59:36,325955.902: [GC 955.902: [ParNew:
> 345024K->38334K(345024K), 0.2880415 secs]
> 2887108K->2831437K(8350272K), 0.2881643 secs] [Times: user=4.04
> sys=0.00, real=0.30 secs]
> 2012-08-16 15:59:36,902956.561: [GC 956.561: [ParNew:
> 345022K->38334K(345024K), 0.2172772 secs]
> 2933661K->2836344K(8350272K), 0.2173954 secs] [Times: user=3.04
> sys=0.00, real=0.22 secs]
> 2012-08-16 15:59:36,902 INFO 15:59:36,902 GC for ParNew: 505 ms for 2
> collections, 2909226128 used; max is 8550678528
> 2012-08-16 15:59:37,573957.194: [GC 957.194: [ParNew:
> 345022K->38336K(345024K), 0.2457267 secs]
> 2835640K->2761950K(8350272K), 0.2458564 secs] [Times: user=3.43
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:38,087957.692: [GC 957.692: [ParNew:
> 345024K->38334K(345024K), 0.2580753 secs]
> 2883419K->2810105K(8350272K), 0.2581927 secs] [Times: user=3.43
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:38,087 INFO 15:59:38,087 GC for ParNew: 504 ms for 2
> collections, 2883187080 used; max is 8550678528
> 2012-08-16 15:59:39,273958.942: [GC 958.942: [ParNew:
> 345022K->38336K(345024K), 0.1964326 secs]
> 2691229K->2515113K(8350272K), 0.1965519 secs] [Times: user=2.87
> sys=0.00, real=0.20 secs]
> 2012-08-16 15:59:39,694959.568: [CMS-concurrent-sweep: 6.414/7.975
> secs] [Times: user=44.04 sys=0.72, real=7.97 secs]
> 2012-08-16 15:59:39,694959.568: [CMS-concurrent-reset-start]
> 2012-08-16 15:59:39,725959.590: [CMS-concurrent-reset: 0.022/0.022
> secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
> 2012-08-16 15:59:41,956961.725: [GC 961.725: [ParNew:
> 344994K->38334K(345024K), 0.0970048 secs]
> 2645182K->2381114K(8350272K), 0.0971442 secs] [Times: user=0.92
> sys=0.00, real=0.09 secs]
> 2012-08-16 15:59:46,043965.815: [GC 965.816: [ParNew:
> 345022K->38336K(345024K), 0.0998408 secs]
> 2687802K->2449434K(8350272K), 0.0999933 secs] [Times: user=1.08
> sys=0.02, real=0.09 secs]
> 2012-08-16 15:59:46,511966.115: [GC 966.115: [ParNew:
> 344629K->38336K(345024K), 0.2663284 secs]
> 2755727K->2687941K(8350272K), 0.2664512 secs] [Times: user=3.46
> sys=0.00, real=0.26 secs]
> 2012-08-16 15:59:47,089966.709: [GC 966.709: [ParNew:
> 344990K->38336K(345024K), 0.2430397 secs]
> 2994595K->2921799K(8350272K), 0.2431602 secs] [Times: user=3.40
> sys=0.02, real=0.25 secs]
> 2012-08-16 15:59:47,681967.293: [GC 967.293: [ParNew:
> 345024K->38336K(345024K), 0.2527240 secs]
> 3228487K->3156972K(8350272K), 0.2528499 secs] [Times: user=3.45
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:59:47,681 INFO 15:59:47,681 GC for ParNew: 496 ms for 2
> collections, 3235405952 used; max is 8550678528
> 2012-08-16 15:59:48,415968.061: [GC 968.061: [ParNew:
> 345024K->38336K(345024K), 0.2184791 secs]
> 3463660K->3348605K(8350272K), 0.2185973 secs] [Times: user=2.87
> sys=0.00, real=0.22 secs]
> 2012-08-16 15:59:48,695 INFO 15:59:48,695 GC for ParNew: 219 ms for 1
> collections, 3493343744 used; max is 8550678528
> 2012-08-16 15:59:49,631969.245: [GC 969.245: [ParNew:
> 345024K->38336K(345024K), 0.2571372 secs]
> 3655293K->3536159K(8350272K), 0.2572561 secs] [Times: user=3.67
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:49,709 INFO 15:59:49,709 GC for ParNew: 257 ms for 1
> collections, 3726925432 used; max is 8550678528
> 2012-08-16 15:59:50,162969.766: [GC 969.766: [ParNew:
> 345024K->38334K(345024K), 0.2653560 secs]
> 3842847K->3774598K(8350272K), 0.2654692 secs] [Times: user=3.90
> sys=0.00, real=0.26 secs]
> 2012-08-16 15:59:50,723970.347: [GC 970.347: [ParNew:
> 345022K->38336K(345024K), 0.2484206 secs]
> 4081286K->4008970K(8350272K), 0.2485346 secs] [Times: user=3.56
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:50,723 INFO 15:59:50,723 GC for ParNew: 514 ms for 2
> collections, 4110795240 used; max is 8550678528
> 2012-08-16 15:59:51,363970.965: [GC 970.965: [ParNew:
> 345024K->38334K(345024K), 0.2646304 secs]
> 4315658K->4258131K(8350272K), 0.2647516 secs] [Times: user=3.67
> sys=0.00, real=0.26 secs]
> 2012-08-16 15:59:51,737 INFO 15:59:51,737 GC for ParNew: 264 ms for 1
> collections, 4581460088 used; max is 8550678528
> 2012-08-16 15:59:52,299971.961: [GC 971.961: [ParNew:
> 345022K->38334K(345024K), 0.2041610 secs]
> 4564819K->4427702K(8350272K), 0.2042765 secs] [Times: user=2.62
> sys=0.00, real=0.20 secs]
> 2012-08-16 15:59:52,751 INFO 15:59:52,751 GC for ParNew: 205 ms for 1
> collections, 4640258968 used; max is 8550678528
> 2012-08-16 15:59:55,669975.335: [GC 975.335: [ParNew:
> 345022K->38336K(345024K), 0.2031359 secs]
> 4734390K->4513398K(8350272K), 0.2032737 secs] [Times: user=2.67
> sys=0.00, real=0.20 secs]
> 2012-08-16 15:59:55,793 INFO 15:59:55,793 GC for ParNew: 203 ms for 1
> collections, 4637851352 used; max is 8550678528
> 2012-08-16 15:59:56,495976.118: [GC 976.118: [ParNew:
> 345024K->38334K(345024K), 0.2428765 secs]
> 4820086K->4719356K(8350272K), 0.2430081 secs] [Times: user=3.40
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:56,963976.598: [GC 976.598: [ParNew:
> 345022K->38336K(345024K), 0.2291020 secs]
> 5026044K->4940991K(8350272K), 0.2292186 secs] [Times: user=3.35
> sys=0.02, real=0.23 secs]
> 2012-08-16 15:59:56,963 INFO 15:59:56,963 GC for ParNew: 472 ms for 2
> collections, 5061091520 used; max is 8550678528
> 2012-08-16 15:59:57,478977.138: [GC 977.138: [ParNew:
> 345024K->38334K(345024K), 0.2138650 secs]
> 5247679K->5145409K(8350272K), 0.2139793 secs] [Times: user=2.79
> sys=0.00, real=0.20 secs]
> 2012-08-16 15:59:58,024977.628: [GC 977.628: [ParNew:
> 345022K->38334K(345024K), 0.2597949 secs]
> 5452097K->5382216K(8350272K), 0.2599123 secs] [Times: user=3.49
> sys=0.00, real=0.26 secs]
> 2012-08-16 15:59:58,024 INFO 15:59:58,024 GC for ParNew: 474 ms for 2
> collections, 5520513520 used; max is 8550678528
> 2012-08-16 15:59:58,913978.616: [GC 978.616: [ParNew:
> 345022K->38336K(345024K), 0.1699849 secs]
> 5688904K->5512877K(8350272K), 0.1700962 secs] [Times: user=2.50
> sys=0.00, real=0.17 secs]
> 2012-08-16 16:00:00,271979.992: [GC 979.992: [ParNew:
> 344994K->38334K(345024K), 0.1453127 secs]
> 5819535K->5572894K(8350272K), 0.1454497 secs] [Times: user=1.70
> sys=0.02, real=0.16 secs]
> 2012-08-16 16:00:04,545984.343: [GC 984.343: [ParNew:
> 344994K->37933K(345024K), 0.0741034 secs]
> 5879554K->5610224K(8350272K), 0.0742458 secs] [Times: user=0.30
> sys=0.00, real=0.08 secs]
> 2012-08-16 16:00:07,119986.764: [GC 986.764: [ParNew:
> 344621K->38336K(345024K), 0.2181230 secs]
> 5916912K->5759381K(8350272K), 0.2182593 secs] [Times: user=2.67
> sys=0.03, real=0.22 secs]
> 2012-08-16 16:00:07,150 INFO 16:00:07,150 GC for ParNew: 218 ms for 1
> collections, 5930704288 used; max is 8550678528
> 2012-08-16 16:00:08,164987.810: [GC 987.810: [ParNew:
> 345024K->38336K(345024K), 0.2296247 secs]
> 6066069K->5950068K(8350272K), 0.2297637 secs] [Times: user=2.87
> sys=0.00, real=0.22 secs]
> 2012-08-16 16:00:08,164 INFO 16:00:08,164 GC for ParNew: 230 ms for 1
> collections, 6098706784 used; max is 8550678528
> 2012-08-16 16:00:08,819988.430: [GC 988.430: [ParNew:
> 345024K->38336K(345024K), 0.2652883 secs]
> 6256756K->6190892K(8350272K), 0.2654107 secs] [Times: user=3.90
> sys=0.00, real=0.27 secs]
> 2012-08-16 16:00:08,851988.695: [GC [1 CMS-initial-mark:
> 6152556K(8005248K)] 6191809K(8350272K), 0.0267734 secs] [Times:
> user=0.03 sys=0.00, real=0.03 secs]
> 2012-08-16 16:00:08,851988.722: [CMS-concurrent-mark-start]
> 2012-08-16 16:00:09,100988.973: [CMS-concurrent-mark: 0.250/0.250
> secs] [Times: user=2.29 sys=0.06, real=0.25 secs]
> 2012-08-16 16:00:09,100988.973: [CMS-concurrent-preclean-start]
> 2012-08-16 16:00:09,131989.005: [CMS-concurrent-preclean: 0.032/0.033
> secs] [Times: user=0.14 sys=0.02, real=0.03 secs]
> 2012-08-16 16:00:09,131989.005: [CMS-concurrent-abortable-preclean-start]
> 2012-08-16 16:00:09,194 INFO 16:00:09,194 GC for ParNew: 265 ms for 1
> collections, 6523586752 used; max is 8550678528
> 2012-08-16 16:00:09,537989.149: [GC 989.150: [ParNew:
> 345024K->38336K(345024K), 0.2521832 secs]
> 6497580K->6413622K(8350272K), 0.2523014 secs] [Times: user=3.65
> sys=0.00, real=0.26 secs]
> 2012-08-16 16:00:09,896989.760: [CMS-concurrent-abortable-preclean:
> 0.499/0.755 secs] [Times: user=5.90 sys=0.05, real=0.76 secs]
> 2012-08-16 16:00:09,911989.760: [GC[YG occupancy: 215512 K (345024
> K)]989.760: [Rescan (parallel) , 0.0248524 secs]989.785: [weak refs
> processing, 0.0000169 secs] [1 CMS-remark: 6375286K(8005248K)]
> 6590799K(8350272K), 0.0249718 secs] [Times: user=0.19 sys=0.00,
> real=0.02 secs]
> 2012-08-16 16:00:09,911989.785: [CMS-concurrent-sweep-start]
> 2012-08-16 16:00:10,208 INFO 16:00:10,208 GC for ParNew: 253 ms for 1
> collections, 6481264200 used; max is 8550678528
> 2012-08-16 16:00:10,816990.457: [GC 990.457: [ParNew:
> 345024K->38336K(345024K), 0.2229088 secs]
> 5892628K->5747038K(8350272K), 0.2230343 secs] [Times: user=3.14
> sys=0.00, real=0.23 secs]
> 2012-08-16 16:00:11,222 INFO 16:00:11,222 GC for ParNew: 222 ms for 1
> collections, 5618012152 used; max is 8550678528
> 2012-08-16 16:00:16,167995.849: [GC 995.849: [ParNew:
> 345024K->38336K(345024K), 0.1941598 secs]
> 3109823K->2945213K(8350272K), 0.1943046 secs] [Times: user=2.62
> sys=0.00, real=0.19 secs]
> 2012-08-16 16:00:17,072996.699: [GC 996.699: [ParNew:
> 345024K->38336K(345024K), 0.2477104 secs]
> 3005684K->2909884K(8350272K), 0.2478259 secs] [Times: user=3.45
> sys=0.00, real=0.25 secs]
> 2012-08-16 16:00:17,306 INFO 16:00:17,306 GC for ParNew: 247 ms for 1
> collections, 2907671688 used; max is 8550678528
> 2012-08-16 16:00:18,570998.243: [GC 998.243: [ParNew:
> 345024K->38336K(345024K), 0.1898907 secs]
> 2788564K->2632153K(8350272K), 0.1900108 secs] [Times: user=2.64
> sys=0.00, real=0.20 secs]
> 2012-08-16 16:00:19,443999.086: [GC 999.086: [ParNew:
> 345024K->38336K(345024K), 0.2223548 secs]
> 2719738K->2599595K(8350272K), 0.2224745 secs] [Times: user=3.15
> sys=0.00, real=0.23 secs]
> 2012-08-16 16:00:19,443 INFO 16:00:19,443 GC for ParNew: 413 ms for 2
> collections, 2664222584 used; max is 8550678528
> 2012-08-16 16:00:19,911999.515: [GC 999.515: [ParNew:
> 345024K->38334K(345024K), 0.2598227 secs]
> 2719357K->2655204K(8350272K), 0.2599416 secs] [Times: user=3.62
> sys=0.00, real=0.27 secs]
> 2012-08-16 16:00:20,5821000.185: [GC 1000.185: [ParNew:
> 345022K->38336K(345024K), 0.2591240 secs]
> 2761843K->2686494K(8350272K), 0.2592448 secs] [Times: user=3.46
> sys=0.00, real=0.27 secs]
> 2012-08-16 16:00:20,582 INFO 16:00:20,582 GC for ParNew: 519 ms for 2
> collections, 2756113024 used; max is 8550678528
> 2012-08-16 16:00:21,1901000.808: [GC 1000.808: [ParNew:
> 344971K->38334K(345024K), 0.2520519 secs]
> 2760422K->2688079K(8350272K), 0.2521670 secs] [Times: user=3.65
> sys=0.02, real=0.25 secs]
> 2012-08-16 16:00:21,5021001.375: [CMS-concurrent-sweep: 9.737/11.590
> secs] [Times: user=49.31 sys=0.78, real=11.59 secs]
> 2012-08-16 16:00:21,5021001.375: [CMS-concurrent-reset-start]
> 2012-08-16 16:00:21,5341001.403: [CMS-concurrent-reset: 0.028/0.028
> secs] [Times: user=0.16 sys=0.00, real=0.03 secs]
> 2012-08-16 16:00:21,596 INFO 16:00:21,596 GC for ParNew: 252 ms for 1
> collections, 2680484480 used; max is 8550678528
>
>
Re: Many ParNew collections
Posted by aaron morton <aa...@thelastpickle.com>.
> - Cassandra 0.7.10
You _really_ should look at getting up to 1.1 :) Memory management is much better and the JVM heap requirements are less.
> However, there is one node with high read latency and far too many
> ParNew collections (compared to other nodes).
Check for long running compactions or repairs.
Check for unexpected row or key cache settings.
Look at the connections on the box and see if it is getting more client load than others.
Restart the node and see if the situations returns. If it does try to correlate the start of the GC issues with the cassandra log.
Hope that helps.
-----------------
Aaron Morton
Freelance Developer
@aaronmorton
http://www.thelastpickle.com
On 17/08/2012, at 2:58 AM, Rene Kochen <re...@schange.com> wrote:
> Hi
>
> I have a cluster of 7 nodes:
>
> - Windows Server 2008
> - Cassandra 0.7.10
> - The nodes are identical (hardware, configuration and client request load)
> - Standard batch file with 8GB heap
> - I use disk_access_mode = standard
> - Random partitioner
> - TP stats shows no problems
> - Ring command shows no problems (data is balanced)
>
> However, there is one node with high read latency and far too many
> ParNew collections (compared to other nodes). It also suffers from a
> high CPU load (I guess due to the ParNew collections).
>
> What can be the source of so many ParNew collections? The other
> identical nodes do not have this behavior.
>
> Logging:
>
> 2012-08-16 15:58:46,436906.072: [GC 906.072: [ParNew:
> 345022K->38336K(345024K), 0.2375976 secs]
> 3630599K->3516249K(8350272K), 0.2377296 secs] [Times: user=3.21
> sys=0.00, real=0.23 secs]
> 2012-08-16 15:58:46,888906.517: [GC 906.517: [ParNew:
> 345024K->38336K(345024K), 0.2400594 secs]
> 3822937K->3743690K(8350272K), 0.2401802 secs] [Times: user=3.48
> sys=0.03, real=0.25 secs]
> 2012-08-16 15:58:46,888 INFO 15:58:46,888 GC for ParNew: 478 ms for 2
> collections, 3837792904 used; max is 8550678528
> 2012-08-16 15:58:47,372907.003: [GC 907.003: [ParNew:
> 345024K->38336K(345024K), 0.2405363 secs]
> 4050378K->3971544K(8350272K), 0.2406553 secs] [Times: user=3.34
> sys=0.01, real=0.23 secs]
> 2012-08-16 15:58:47,918907.544: [GC 907.544: [ParNew:
> 345024K->38336K(345024K), 0.2404339 secs]
> 4278232K->4193789K(8350272K), 0.2405540 secs] [Times: user=3.31
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:58:47,918 INFO 15:58:47,918 GC for ParNew: 481 ms for 2
> collections, 4300939752 used; max is 8550678528
> 2012-08-16 15:58:48,464908.079: [GC 908.079: [ParNew:
> 345024K->38336K(345024K), 0.2621174 secs]
> 4500477K->4434112K(8350272K), 0.2622375 secs] [Times: user=3.64
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:58:48,932 INFO 15:58:48,932 GC for ParNew: 262 ms for 1
> collections, 4763583200 used; max is 8550678528
> 2012-08-16 15:58:49,384909.050: [GC 909.051: [ParNew:
> 344972K->38336K(345024K), 0.2033453 secs]
> 4740748K->4563252K(8350272K), 0.2034588 secs] [Times: user=2.89
> sys=0.01, real=0.20 secs]
> 2012-08-16 15:58:49,946 INFO 15:58:49,946 GC for ParNew: 203 ms for 1
> collections, 4885945792 used; max is 8550678528
> 2012-08-16 15:58:50,383909.998: [GC 909.998: [ParNew:
> 345024K->38336K(345024K), 0.2567542 secs]
> 4869940K->4740489K(8350272K), 0.2568804 secs] [Times: user=3.60
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:58:50,882910.474: [GC 910.474: [ParNew:
> 345024K->38336K(345024K), 0.2786205 secs]
> 5047177K->4962531K(8350272K), 0.2787668 secs] [Times: user=3.48
> sys=0.00, real=0.28 secs]
> 2012-08-16 15:58:50,960 INFO 15:58:50,960 GC for ParNew: 536 ms for 2
> collections, 5143423816 used; max is 8550678528
> 2012-08-16 15:58:51,584911.192: [GC 911.192: [ParNew:
> 344963K->38334K(345024K), 0.2664316 secs]
> 5269158K->5196444K(8350272K), 0.2665544 secs] [Times: user=3.74
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:58:52,130911.767: [GC 911.767: [ParNew:
> 345022K->38336K(345024K), 0.2327209 secs]
> 5503132K->5406771K(8350272K), 0.2328457 secs] [Times: user=3.35
> sys=0.00, real=0.23 secs]
> 2012-08-16 15:58:52,130 INFO 15:58:52,130 GC for ParNew: 499 ms for 2
> collections, 5541845264 used; max is 8550678528
> 2012-08-16 15:58:52,816912.460: [GC 912.460: [ParNew:
> 345024K->38334K(345024K), 0.2198399 secs]
> 5713459K->5605670K(8350272K), 0.2199669 secs] [Times: user=3.29
> sys=0.00, real=0.23 secs]
> 2012-08-16 15:58:53,144 INFO 15:58:53,144 GC for ParNew: 220 ms for 1
> collections, 5805870608 used; max is 8550678528
> 2012-08-16 15:58:55,546915.173: [GC 915.173: [ParNew:
> 345022K->38334K(345024K), 0.2369585 secs]
> 5912358K->5702871K(8350272K), 0.2371098 secs] [Times: user=3.18
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:58:56,186 INFO 15:58:56,186 GC for ParNew: 237 ms for 1
> collections, 6089002480 used; max is 8550678528
> 2012-08-16 15:58:56,591916.232: [GC 916.232: [ParNew:
> 345022K->38336K(345024K), 0.2364850 secs]
> 6009559K->5914142K(8350272K), 0.2366075 secs] [Times: user=3.32
> sys=0.00, real=0.23 secs]
> 2012-08-16 15:58:57,340916.989: [GC 916.989: [ParNew:
> 345024K->38334K(345024K), 0.2191751 secs]
> 6220830K->6107217K(8350272K), 0.2192894 secs] [Times: user=2.92
> sys=0.00, real=0.22 secs]
> 2012-08-16 15:58:57,371917.209: [GC [1 CMS-initial-mark:
> 6068883K(8005248K)] 6108716K(8350272K), 0.0272472 secs] [Times:
> user=0.03 sys=0.00, real=0.03 secs]
> 2012-08-16 15:58:57,371917.236: [CMS-concurrent-mark-start]
> 2012-08-16 15:58:57,371 INFO 15:58:57,371 GC for ParNew: 456 ms for 2
> collections, 6255865264 used; max is 8550678528
> 2012-08-16 15:58:57,574917.444: [CMS-concurrent-mark: 0.208/0.208
> secs] [Times: user=1.48 sys=0.06, real=0.20 secs]
> 2012-08-16 15:58:57,574917.444: [CMS-concurrent-preclean-start]
> 2012-08-16 15:58:57,637917.501: [CMS-concurrent-preclean: 0.057/0.057
> secs] [Times: user=0.19 sys=0.00, real=0.06 secs]
> 2012-08-16 15:58:57,637917.501: [CMS-concurrent-abortable-preclean-start]
> 2012-08-16 15:58:58,775918.552: [GC 918.552: [ParNew:
> 345022K->38334K(345024K), 0.0948325 secs]
> 6413905K->6163063K(8350272K), 0.0949661 secs] [Times: user=1.22
> sys=0.00, real=0.09 secs]
> 2012-08-16 15:58:59,025918.896: [CMS-concurrent-abortable-preclean:
> 1.198/1.395 secs] [Times: user=5.26 sys=0.17, real=1.39 secs]
> 2012-08-16 15:58:59,072918.896: [GC[YG occupancy: 274623 K (345024
> K)]918.896: [Rescan (parallel) , 0.0427564 secs]918.939: [weak refs
> processing, 0.0000096 secs] [1 CMS-remark: 6124729K(8005248K)]
> 6399352K(8350272K), 0.0428734 secs] [Times: user=0.62 sys=0.00,
> real=0.05 secs]
> 2012-08-16 15:58:59,072918.939: [CMS-concurrent-sweep-start]
> 2012-08-16 15:58:59,368918.972: [GC 918.972: [ParNew:
> 345022K->38336K(345024K), 0.2652648 secs]
> 6465380K->6379989K(8350272K), 0.2654014 secs] [Times: user=3.71
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:58:59,930919.557: [GC 919.557: [ParNew:
> 345024K->38334K(345024K), 0.2417524 secs]
> 6433484K->6347081K(8350272K), 0.2418748 secs] [Times: user=3.40
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:00,507920.161: [GC 920.162: [ParNew:
> 345015K->38334K(345024K), 0.2142607 secs]
> 6191692K->6086072K(8350272K), 0.2143766 secs] [Times: user=3.09
> sys=0.00, real=0.22 secs]
> 2012-08-16 15:59:00,507 INFO 15:59:00,507 GC for ParNew: 456 ms for 2
> collections, 6233109512 used; max is 8550678528
> 2012-08-16 15:59:01,022920.633: [GC 920.633: [ParNew:
> 345022K->38336K(345024K), 0.2590327 secs]
> 6140813K->6065694K(8350272K), 0.2591528 secs] [Times: user=3.67
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:59:01,521 INFO 15:59:01,521 GC for ParNew: 259 ms for 1
> collections, 5916301064 used; max is 8550678528
> 2012-08-16 15:59:01,942921.604: [GC 921.604: [ParNew:
> 345001K->38334K(345024K), 0.2059791 secs]
> 5576624K->5407950K(8350272K), 0.2060935 secs] [Times: user=3.07
> sys=0.00, real=0.20 secs]
> 2012-08-16 15:59:02,535 INFO 15:59:02,535 GC for ParNew: 206 ms for 1
> collections, 4951508912 used; max is 8550678528
> 2012-08-16 15:59:06,185925.865: [GC 925.865: [ParNew:
> 345022K->38334K(345024K), 0.1944824 secs]
> 2207361K->2034487K(8350272K), 0.1946014 secs] [Times: user=2.54
> sys=0.00, real=0.19 secs]
> 2012-08-16 15:59:06,747926.624: [CMS-concurrent-sweep: 6.301/7.685
> secs] [Times: user=36.33 sys=0.37, real=7.67 secs]
> 2012-08-16 15:59:06,747926.624: [CMS-concurrent-reset-start]
> 2012-08-16 15:59:06,778926.644: [CMS-concurrent-reset: 0.020/0.020
> secs] [Times: user=0.06 sys=0.00, real=0.03 secs]
> 2012-08-16 15:59:07,699927.442: [GC 927.442: [ParNew:
> 345022K->38336K(345024K), 0.1241401 secs]
> 2087777K->1881732K(8350272K), 0.1242536 secs] [Times: user=1.47
> sys=0.00, real=0.13 secs]
> 2012-08-16 15:59:10,241929.912: [GC 929.912: [ParNew:
> 345024K->38334K(345024K), 0.1987855 secs]
> 2188420K->2049927K(8350272K), 0.1989237 secs] [Times: user=2.73
> sys=0.00, real=0.20 secs]
> 2012-08-16 15:59:10,912930.557: [GC 930.558: [ParNew:
> 345022K->38336K(345024K), 0.2269435 secs]
> 2356615K->2253199K(8350272K), 0.2270702 secs] [Times: user=2.98
> sys=0.00, real=0.22 secs]
> 2012-08-16 15:59:10,912 INFO 15:59:10,912 GC for ParNew: 426 ms for 2
> collections, 2312471792 used; max is 8550678528
> 2012-08-16 15:59:11,521931.148: [GC 931.148: [ParNew:
> 345024K->38334K(345024K), 0.2371360 secs]
> 2559887K->2475870K(8350272K), 0.2372526 secs] [Times: user=3.10
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:11,926 INFO 15:59:11,926 GC for ParNew: 237 ms for 1
> collections, 2763895872 used; max is 8550678528
> 2012-08-16 15:59:12,441932.137: [GC 932.137: [ParNew:
> 345022K->38336K(345024K), 0.1733826 secs]
> 2782558K->2622114K(8350272K), 0.1735015 secs] [Times: user=2.42
> sys=0.02, real=0.17 secs]
> 2012-08-16 15:59:13,549933.155: [GC 933.155: [ParNew:
> 345024K->38334K(345024K), 0.2625127 secs]
> 2928802K->2829867K(8350272K), 0.2626344 secs] [Times: user=3.77
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:59:14,188933.808: [GC 933.808: [ParNew:
> 345022K->38334K(345024K), 0.2505625 secs]
> 3136555K->3054091K(8350272K), 0.2506795 secs] [Times: user=3.46
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:14,188 INFO 15:59:14,188 GC for ParNew: 513 ms for 2
> collections, 3134992208 used; max is 8550678528
> 2012-08-16 15:59:14,890934.522: [GC 934.523: [ParNew:
> 345022K->38336K(345024K), 0.2316504 secs]
> 3360779K->3275423K(8350272K), 0.2317766 secs] [Times: user=3.13
> sys=0.00, real=0.23 secs]
> 2012-08-16 15:59:15,202 INFO 15:59:15,202 GC for ParNew: 232 ms for 1
> collections, 3536955232 used; max is 8550678528
> 2012-08-16 15:59:15,920935.625: [GC 935.625: [ParNew:
> 345024K->38334K(345024K), 0.1714062 secs]
> 3582111K->3415888K(8350272K), 0.1715367 secs] [Times: user=2.54
> sys=0.00, real=0.17 secs]
> 2012-08-16 15:59:16,513936.119: [GC 936.119: [ParNew:
> 345022K->38334K(345024K), 0.2719661 secs]
> 3722576K->3649948K(8350272K), 0.2720966 secs] [Times: user=3.74
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:59:17,059936.685: [GC 936.685: [ParNew:
> 345022K->38336K(345024K), 0.2452667 secs]
> 3956636K->3871076K(8350272K), 0.2453914 secs] [Times: user=3.62
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:17,230 INFO 15:59:17,230 GC for ParNew: 517 ms for 2
> collections, 4081462864 used; max is 8550678528
> 2012-08-16 15:59:17,651937.255: [GC 937.255: [ParNew:
> 345024K->38334K(345024K), 0.2594023 secs]
> 4177764K->4099640K(8350272K), 0.2595243 secs] [Times: user=3.49
> sys=0.01, real=0.27 secs]
> 2012-08-16 15:59:18,213937.825: [GC 937.825: [ParNew:
> 345022K->38336K(345024K), 0.2584561 secs]
> 4406328K->4332694K(8350272K), 0.2585750 secs] [Times: user=3.74
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:59:18,244 INFO 15:59:18,244 GC for ParNew: 518 ms for 2
> collections, 4451788480 used; max is 8550678528
> 2012-08-16 15:59:19,165938.841: [GC 938.841: [ParNew:
> 344991K->38334K(345024K), 0.1994641 secs]
> 4639350K->4482568K(8350272K), 0.1995789 secs] [Times: user=2.56
> sys=0.01, real=0.19 secs]
> 2012-08-16 15:59:25,717945.440: [GC 945.440: [ParNew:
> 344963K->38334K(345024K), 0.1440731 secs]
> 4789197K->4538905K(8350272K), 0.1442125 secs] [Times: user=1.61
> sys=0.00, real=0.14 secs]
> 2012-08-16 15:59:26,372945.966: [GC 945.966: [ParNew:
> 345022K->38336K(345024K), 0.2803466 secs]
> 4845593K->4785922K(8350272K), 0.2804798 secs] [Times: user=3.92
> sys=0.00, real=0.28 secs]
> 2012-08-16 15:59:26,372 INFO 15:59:26,372 GC for ParNew: 425 ms for 2
> collections, 4903116472 used; max is 8550678528
> 2012-08-16 15:59:26,965946.589: [GC 946.589: [ParNew:
> 345024K->38336K(345024K), 0.2496506 secs]
> 5092610K->5017752K(8350272K), 0.2497695 secs] [Times: user=3.60
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:27,526947.149: [GC 947.149: [ParNew:
> 345024K->38336K(345024K), 0.2427009 secs]
> 5324440K->5242855K(8350272K), 0.2428195 secs] [Times: user=3.21
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:27,526 INFO 15:59:27,526 GC for ParNew: 492 ms for 2
> collections, 5374819504 used; max is 8550678528
> 2012-08-16 15:59:28,088947.717: [GC 947.717: [ParNew:
> 345024K->38336K(345024K), 0.2467160 secs]
> 5549543K->5469437K(8350272K), 0.2468315 secs] [Times: user=3.39
> sys=0.00, real=0.23 secs]
> 2012-08-16 15:59:28,540 INFO 15:59:28,540 GC for ParNew: 247 ms for 1
> collections, 5756868992 used; max is 8550678528
> 2012-08-16 15:59:29,195948.871: [GC 948.871: [ParNew:
> 345024K->38334K(345024K), 0.1934754 secs]
> 5776125K->5599289K(8350272K), 0.1935862 secs] [Times: user=2.70
> sys=0.00, real=0.20 secs]
> 2012-08-16 15:59:29,710949.316: [GC 949.316: [ParNew:
> 345022K->38334K(345024K), 0.2601060 secs]
> 5905977K->5828882K(8350272K), 0.2602222 secs] [Times: user=3.46
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:59:29,710 INFO 15:59:29,710 GC for ParNew: 454 ms for 2
> collections, 5975471248 used; max is 8550678528
> 2012-08-16 15:59:30,194949.830: [GC 949.830: [ParNew:
> 345022K->38336K(345024K), 0.2380811 secs]
> 6135570K->6042546K(8350272K), 0.2382000 secs] [Times: user=3.14
> sys=0.00, real=0.23 secs]
> 2012-08-16 15:59:30,225950.069: [GC [1 CMS-initial-mark:
> 6004210K(8005248K)] 6042548K(8350272K), 0.0260419 secs] [Times:
> user=0.03 sys=0.00, real=0.03 secs]
> 2012-08-16 15:59:30,225950.095: [CMS-concurrent-mark-start]
> 2012-08-16 15:59:30,443950.316: [CMS-concurrent-mark: 0.221/0.221
> secs] [Times: user=2.06 sys=0.13, real=0.22 secs]
> 2012-08-16 15:59:30,443950.316: [CMS-concurrent-preclean-start]
> 2012-08-16 15:59:30,459950.336: [CMS-concurrent-preclean: 0.020/0.020
> secs] [Times: user=0.06 sys=0.01, real=0.02 secs]
> 2012-08-16 15:59:30,459950.336: [CMS-concurrent-abortable-preclean-start]
> 2012-08-16 15:59:30,818950.463: [GC 950.463: [ParNew:
> 345024K->38336K(345024K), 0.2228510 secs]
> 6349234K->6252442K(8350272K), 0.2229688 secs] [Times: user=3.14
> sys=0.00, real=0.22 secs]
> 2012-08-16 15:59:30,818 INFO 15:59:30,818 GC for ParNew: 461 ms for 2
> collections, 6406860032 used; max is 8550678528
> 2012-08-16 15:59:31,395950.997: [GC 950.997: [ParNew:
> 345024K->38336K(345024K), 0.2692564 secs]
> 6559130K->6493591K(8350272K), 0.2693750 secs] [Times: user=3.81
> sys=0.00, real=0.26 secs]
> 2012-08-16 15:59:31,707951.580: [CMS-concurrent-abortable-preclean:
> 0.750/1.245 secs] [Times: user=10.84 sys=0.13, real=1.25 secs]
> 2012-08-16 15:59:31,723951.581: [GC[YG occupancy: 190327 K (345024
> K)]951.581: [Rescan (parallel) , 0.0126204 secs]951.593: [weak refs
> processing, 0.0000085 secs] [1 CMS-remark: 6455255K(8005248K)]
> 6645582K(8350272K), 0.0127259 secs] [Times: user=0.28 sys=0.00,
> real=0.02 secs]
> 2012-08-16 15:59:31,723951.593: [CMS-concurrent-sweep-start]
> 2012-08-16 15:59:31,832 INFO 15:59:31,832 GC for ParNew: 269 ms for 1
> collections, 6764806360 used; max is 8550678528
> 2012-08-16 15:59:32,362952.030: [GC 952.030: [ParNew:
> 345024K->38334K(345024K), 0.1960234 secs]
> 6293501K->6126054K(8350272K), 0.1961435 secs] [Times: user=2.89
> sys=0.02, real=0.20 secs]
> 2012-08-16 15:59:35,685955.406: [GC 955.406: [ParNew:
> 345006K->38336K(345024K), 0.1556453 secs]
> 2927846K->2691941K(8350272K), 0.1557619 secs] [Times: user=2.39
> sys=0.02, real=0.16 secs]
> 2012-08-16 15:59:36,325955.902: [GC 955.902: [ParNew:
> 345024K->38334K(345024K), 0.2880415 secs]
> 2887108K->2831437K(8350272K), 0.2881643 secs] [Times: user=4.04
> sys=0.00, real=0.30 secs]
> 2012-08-16 15:59:36,902956.561: [GC 956.561: [ParNew:
> 345022K->38334K(345024K), 0.2172772 secs]
> 2933661K->2836344K(8350272K), 0.2173954 secs] [Times: user=3.04
> sys=0.00, real=0.22 secs]
> 2012-08-16 15:59:36,902 INFO 15:59:36,902 GC for ParNew: 505 ms for 2
> collections, 2909226128 used; max is 8550678528
> 2012-08-16 15:59:37,573957.194: [GC 957.194: [ParNew:
> 345022K->38336K(345024K), 0.2457267 secs]
> 2835640K->2761950K(8350272K), 0.2458564 secs] [Times: user=3.43
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:38,087957.692: [GC 957.692: [ParNew:
> 345024K->38334K(345024K), 0.2580753 secs]
> 2883419K->2810105K(8350272K), 0.2581927 secs] [Times: user=3.43
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:38,087 INFO 15:59:38,087 GC for ParNew: 504 ms for 2
> collections, 2883187080 used; max is 8550678528
> 2012-08-16 15:59:39,273958.942: [GC 958.942: [ParNew:
> 345022K->38336K(345024K), 0.1964326 secs]
> 2691229K->2515113K(8350272K), 0.1965519 secs] [Times: user=2.87
> sys=0.00, real=0.20 secs]
> 2012-08-16 15:59:39,694959.568: [CMS-concurrent-sweep: 6.414/7.975
> secs] [Times: user=44.04 sys=0.72, real=7.97 secs]
> 2012-08-16 15:59:39,694959.568: [CMS-concurrent-reset-start]
> 2012-08-16 15:59:39,725959.590: [CMS-concurrent-reset: 0.022/0.022
> secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
> 2012-08-16 15:59:41,956961.725: [GC 961.725: [ParNew:
> 344994K->38334K(345024K), 0.0970048 secs]
> 2645182K->2381114K(8350272K), 0.0971442 secs] [Times: user=0.92
> sys=0.00, real=0.09 secs]
> 2012-08-16 15:59:46,043965.815: [GC 965.816: [ParNew:
> 345022K->38336K(345024K), 0.0998408 secs]
> 2687802K->2449434K(8350272K), 0.0999933 secs] [Times: user=1.08
> sys=0.02, real=0.09 secs]
> 2012-08-16 15:59:46,511966.115: [GC 966.115: [ParNew:
> 344629K->38336K(345024K), 0.2663284 secs]
> 2755727K->2687941K(8350272K), 0.2664512 secs] [Times: user=3.46
> sys=0.00, real=0.26 secs]
> 2012-08-16 15:59:47,089966.709: [GC 966.709: [ParNew:
> 344990K->38336K(345024K), 0.2430397 secs]
> 2994595K->2921799K(8350272K), 0.2431602 secs] [Times: user=3.40
> sys=0.02, real=0.25 secs]
> 2012-08-16 15:59:47,681967.293: [GC 967.293: [ParNew:
> 345024K->38336K(345024K), 0.2527240 secs]
> 3228487K->3156972K(8350272K), 0.2528499 secs] [Times: user=3.45
> sys=0.00, real=0.27 secs]
> 2012-08-16 15:59:47,681 INFO 15:59:47,681 GC for ParNew: 496 ms for 2
> collections, 3235405952 used; max is 8550678528
> 2012-08-16 15:59:48,415968.061: [GC 968.061: [ParNew:
> 345024K->38336K(345024K), 0.2184791 secs]
> 3463660K->3348605K(8350272K), 0.2185973 secs] [Times: user=2.87
> sys=0.00, real=0.22 secs]
> 2012-08-16 15:59:48,695 INFO 15:59:48,695 GC for ParNew: 219 ms for 1
> collections, 3493343744 used; max is 8550678528
> 2012-08-16 15:59:49,631969.245: [GC 969.245: [ParNew:
> 345024K->38336K(345024K), 0.2571372 secs]
> 3655293K->3536159K(8350272K), 0.2572561 secs] [Times: user=3.67
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:49,709 INFO 15:59:49,709 GC for ParNew: 257 ms for 1
> collections, 3726925432 used; max is 8550678528
> 2012-08-16 15:59:50,162969.766: [GC 969.766: [ParNew:
> 345024K->38334K(345024K), 0.2653560 secs]
> 3842847K->3774598K(8350272K), 0.2654692 secs] [Times: user=3.90
> sys=0.00, real=0.26 secs]
> 2012-08-16 15:59:50,723970.347: [GC 970.347: [ParNew:
> 345022K->38336K(345024K), 0.2484206 secs]
> 4081286K->4008970K(8350272K), 0.2485346 secs] [Times: user=3.56
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:50,723 INFO 15:59:50,723 GC for ParNew: 514 ms for 2
> collections, 4110795240 used; max is 8550678528
> 2012-08-16 15:59:51,363970.965: [GC 970.965: [ParNew:
> 345024K->38334K(345024K), 0.2646304 secs]
> 4315658K->4258131K(8350272K), 0.2647516 secs] [Times: user=3.67
> sys=0.00, real=0.26 secs]
> 2012-08-16 15:59:51,737 INFO 15:59:51,737 GC for ParNew: 264 ms for 1
> collections, 4581460088 used; max is 8550678528
> 2012-08-16 15:59:52,299971.961: [GC 971.961: [ParNew:
> 345022K->38334K(345024K), 0.2041610 secs]
> 4564819K->4427702K(8350272K), 0.2042765 secs] [Times: user=2.62
> sys=0.00, real=0.20 secs]
> 2012-08-16 15:59:52,751 INFO 15:59:52,751 GC for ParNew: 205 ms for 1
> collections, 4640258968 used; max is 8550678528
> 2012-08-16 15:59:55,669975.335: [GC 975.335: [ParNew:
> 345022K->38336K(345024K), 0.2031359 secs]
> 4734390K->4513398K(8350272K), 0.2032737 secs] [Times: user=2.67
> sys=0.00, real=0.20 secs]
> 2012-08-16 15:59:55,793 INFO 15:59:55,793 GC for ParNew: 203 ms for 1
> collections, 4637851352 used; max is 8550678528
> 2012-08-16 15:59:56,495976.118: [GC 976.118: [ParNew:
> 345024K->38334K(345024K), 0.2428765 secs]
> 4820086K->4719356K(8350272K), 0.2430081 secs] [Times: user=3.40
> sys=0.00, real=0.25 secs]
> 2012-08-16 15:59:56,963976.598: [GC 976.598: [ParNew:
> 345022K->38336K(345024K), 0.2291020 secs]
> 5026044K->4940991K(8350272K), 0.2292186 secs] [Times: user=3.35
> sys=0.02, real=0.23 secs]
> 2012-08-16 15:59:56,963 INFO 15:59:56,963 GC for ParNew: 472 ms for 2
> collections, 5061091520 used; max is 8550678528
> 2012-08-16 15:59:57,478977.138: [GC 977.138: [ParNew:
> 345024K->38334K(345024K), 0.2138650 secs]
> 5247679K->5145409K(8350272K), 0.2139793 secs] [Times: user=2.79
> sys=0.00, real=0.20 secs]
> 2012-08-16 15:59:58,024977.628: [GC 977.628: [ParNew:
> 345022K->38334K(345024K), 0.2597949 secs]
> 5452097K->5382216K(8350272K), 0.2599123 secs] [Times: user=3.49
> sys=0.00, real=0.26 secs]
> 2012-08-16 15:59:58,024 INFO 15:59:58,024 GC for ParNew: 474 ms for 2
> collections, 5520513520 used; max is 8550678528
> 2012-08-16 15:59:58,913978.616: [GC 978.616: [ParNew:
> 345022K->38336K(345024K), 0.1699849 secs]
> 5688904K->5512877K(8350272K), 0.1700962 secs] [Times: user=2.50
> sys=0.00, real=0.17 secs]
> 2012-08-16 16:00:00,271979.992: [GC 979.992: [ParNew:
> 344994K->38334K(345024K), 0.1453127 secs]
> 5819535K->5572894K(8350272K), 0.1454497 secs] [Times: user=1.70
> sys=0.02, real=0.16 secs]
> 2012-08-16 16:00:04,545984.343: [GC 984.343: [ParNew:
> 344994K->37933K(345024K), 0.0741034 secs]
> 5879554K->5610224K(8350272K), 0.0742458 secs] [Times: user=0.30
> sys=0.00, real=0.08 secs]
> 2012-08-16 16:00:07,119986.764: [GC 986.764: [ParNew:
> 344621K->38336K(345024K), 0.2181230 secs]
> 5916912K->5759381K(8350272K), 0.2182593 secs] [Times: user=2.67
> sys=0.03, real=0.22 secs]
> 2012-08-16 16:00:07,150 INFO 16:00:07,150 GC for ParNew: 218 ms for 1
> collections, 5930704288 used; max is 8550678528
> 2012-08-16 16:00:08,164987.810: [GC 987.810: [ParNew:
> 345024K->38336K(345024K), 0.2296247 secs]
> 6066069K->5950068K(8350272K), 0.2297637 secs] [Times: user=2.87
> sys=0.00, real=0.22 secs]
> 2012-08-16 16:00:08,164 INFO 16:00:08,164 GC for ParNew: 230 ms for 1
> collections, 6098706784 used; max is 8550678528
> 2012-08-16 16:00:08,819988.430: [GC 988.430: [ParNew:
> 345024K->38336K(345024K), 0.2652883 secs]
> 6256756K->6190892K(8350272K), 0.2654107 secs] [Times: user=3.90
> sys=0.00, real=0.27 secs]
> 2012-08-16 16:00:08,851988.695: [GC [1 CMS-initial-mark:
> 6152556K(8005248K)] 6191809K(8350272K), 0.0267734 secs] [Times:
> user=0.03 sys=0.00, real=0.03 secs]
> 2012-08-16 16:00:08,851988.722: [CMS-concurrent-mark-start]
> 2012-08-16 16:00:09,100988.973: [CMS-concurrent-mark: 0.250/0.250
> secs] [Times: user=2.29 sys=0.06, real=0.25 secs]
> 2012-08-16 16:00:09,100988.973: [CMS-concurrent-preclean-start]
> 2012-08-16 16:00:09,131989.005: [CMS-concurrent-preclean: 0.032/0.033
> secs] [Times: user=0.14 sys=0.02, real=0.03 secs]
> 2012-08-16 16:00:09,131989.005: [CMS-concurrent-abortable-preclean-start]
> 2012-08-16 16:00:09,194 INFO 16:00:09,194 GC for ParNew: 265 ms for 1
> collections, 6523586752 used; max is 8550678528
> 2012-08-16 16:00:09,537989.149: [GC 989.150: [ParNew:
> 345024K->38336K(345024K), 0.2521832 secs]
> 6497580K->6413622K(8350272K), 0.2523014 secs] [Times: user=3.65
> sys=0.00, real=0.26 secs]
> 2012-08-16 16:00:09,896989.760: [CMS-concurrent-abortable-preclean:
> 0.499/0.755 secs] [Times: user=5.90 sys=0.05, real=0.76 secs]
> 2012-08-16 16:00:09,911989.760: [GC[YG occupancy: 215512 K (345024
> K)]989.760: [Rescan (parallel) , 0.0248524 secs]989.785: [weak refs
> processing, 0.0000169 secs] [1 CMS-remark: 6375286K(8005248K)]
> 6590799K(8350272K), 0.0249718 secs] [Times: user=0.19 sys=0.00,
> real=0.02 secs]
> 2012-08-16 16:00:09,911989.785: [CMS-concurrent-sweep-start]
> 2012-08-16 16:00:10,208 INFO 16:00:10,208 GC for ParNew: 253 ms for 1
> collections, 6481264200 used; max is 8550678528
> 2012-08-16 16:00:10,816990.457: [GC 990.457: [ParNew:
> 345024K->38336K(345024K), 0.2229088 secs]
> 5892628K->5747038K(8350272K), 0.2230343 secs] [Times: user=3.14
> sys=0.00, real=0.23 secs]
> 2012-08-16 16:00:11,222 INFO 16:00:11,222 GC for ParNew: 222 ms for 1
> collections, 5618012152 used; max is 8550678528
> 2012-08-16 16:00:16,167995.849: [GC 995.849: [ParNew:
> 345024K->38336K(345024K), 0.1941598 secs]
> 3109823K->2945213K(8350272K), 0.1943046 secs] [Times: user=2.62
> sys=0.00, real=0.19 secs]
> 2012-08-16 16:00:17,072996.699: [GC 996.699: [ParNew:
> 345024K->38336K(345024K), 0.2477104 secs]
> 3005684K->2909884K(8350272K), 0.2478259 secs] [Times: user=3.45
> sys=0.00, real=0.25 secs]
> 2012-08-16 16:00:17,306 INFO 16:00:17,306 GC for ParNew: 247 ms for 1
> collections, 2907671688 used; max is 8550678528
> 2012-08-16 16:00:18,570998.243: [GC 998.243: [ParNew:
> 345024K->38336K(345024K), 0.1898907 secs]
> 2788564K->2632153K(8350272K), 0.1900108 secs] [Times: user=2.64
> sys=0.00, real=0.20 secs]
> 2012-08-16 16:00:19,443999.086: [GC 999.086: [ParNew:
> 345024K->38336K(345024K), 0.2223548 secs]
> 2719738K->2599595K(8350272K), 0.2224745 secs] [Times: user=3.15
> sys=0.00, real=0.23 secs]
> 2012-08-16 16:00:19,443 INFO 16:00:19,443 GC for ParNew: 413 ms for 2
> collections, 2664222584 used; max is 8550678528
> 2012-08-16 16:00:19,911999.515: [GC 999.515: [ParNew:
> 345024K->38334K(345024K), 0.2598227 secs]
> 2719357K->2655204K(8350272K), 0.2599416 secs] [Times: user=3.62
> sys=0.00, real=0.27 secs]
> 2012-08-16 16:00:20,5821000.185: [GC 1000.185: [ParNew:
> 345022K->38336K(345024K), 0.2591240 secs]
> 2761843K->2686494K(8350272K), 0.2592448 secs] [Times: user=3.46
> sys=0.00, real=0.27 secs]
> 2012-08-16 16:00:20,582 INFO 16:00:20,582 GC for ParNew: 519 ms for 2
> collections, 2756113024 used; max is 8550678528
> 2012-08-16 16:00:21,1901000.808: [GC 1000.808: [ParNew:
> 344971K->38334K(345024K), 0.2520519 secs]
> 2760422K->2688079K(8350272K), 0.2521670 secs] [Times: user=3.65
> sys=0.02, real=0.25 secs]
> 2012-08-16 16:00:21,5021001.375: [CMS-concurrent-sweep: 9.737/11.590
> secs] [Times: user=49.31 sys=0.78, real=11.59 secs]
> 2012-08-16 16:00:21,5021001.375: [CMS-concurrent-reset-start]
> 2012-08-16 16:00:21,5341001.403: [CMS-concurrent-reset: 0.028/0.028
> secs] [Times: user=0.16 sys=0.00, real=0.03 secs]
> 2012-08-16 16:00:21,596 INFO 16:00:21,596 GC for ParNew: 252 ms for 1
> collections, 2680484480 used; max is 8550678528