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 <rene.koc...@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 > >
