incubator-cassandra-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From aaron morton <aa...@thelastpickle.com>
Subject Re: Many ParNew collections
Date Thu, 16 Aug 2012 23:04:08 GMT
> - 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.kochen@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


Mime
View raw message