incubator-cassandra-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Rene Kochen <rene.koc...@schange.com>
Subject Re: Many ParNew collections
Date Fri, 14 Sep 2012 10:41:12 GMT
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 <aaron@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.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