incubator-cassandra-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From André Cruz <andre.c...@co.sapo.pt>
Subject Frequent Full GC that take > 30s
Date Mon, 23 Sep 2013 14:51:38 GMT
Hello.

I'm having problems with frequent Full GCs that take a long time, and cause a burst of timeouts
for the client application. But first, here is my configuration:

Cassandra: 1.1.5
Key Cache        : size 209715168 (bytes), capacity 209715168 (bytes), 1331992571 hits, 1831790912
requests, 0.854 recent hit rate, 14400 save period in seconds
Row Cache        : size 104588313 (bytes), capacity 104857600 (bytes), 585590776 hits, 646992444
requests, 0.880 recent hit rate, 0 save period in seconds
flush_largest_memtables_at: 0.8
memtable_total_space_in_mb: 2048

JVM: 
java version "1.6.0_35"
Java(TM) SE Runtime Environment (build 1.6.0_35-b10)
Java HotSpot(TM) 64-Bit Server VM (build 20.10-b01, mixed mode)

JVM Options:
-XX:+UseParNewGC
-XX:+UseConcMarkSweepGC
-XX:+CMSParallelRemarkEnabled
-XX:SurvivorRatio=8
-XX:MaxTenuringThreshold=1
-XX:CMSInitiatingOccupancyFraction=75
-XX:+UseCMSInitiatingOccupancyOnly
-XX:ParallelCMSThreads=4
-Xms16G
-Xmx16G
-Xmn800M
-Xss196k

6 nodes with 32GB RAM, Intel(R) Xeon(R) CPU E5-2609, 300GB data per node.


Current status:
I had to raise the heap to 16GB due to constant very high heap usage. I've since lowered the
bf ratio, but still haven't got to lowering the heap size because I'm still not sure a 8GB
heap can handle the load per node.

Things I plan to do:
- upgrade to Cassandra 1.2. Supposedly it makes better use of the heap.
- add more nodes. Still waiting for the hardware.
- test again with lower heap sizes.
- test JVM 7 (G1?). I've read somewhere that JVM 6 is recommended for Cassandra but Cassandra
2.0 requires JVM 7 so...

Besides these, I would also like to double-check my current GC parameters. I'm thinking of
increasing the NewSize to 1200M, so that less garbage ends up in the old generation. But here
are the GC logs, maybe someone has a better idea?

2013-09-20T07:32:59.090+0100: 141675.121: [GC 141675.121: [ParNew (2: promotion failure size
= 9564)  (promotion failed)
Desired survivor size 41943040 bytes, new threshold 1 (max 1)
- age   1:     569496 bytes,     569496 total
: 85346K->67732K(737280K), 0.1206690 secs] 14838953K->14882152K(16695296K), 0.1210110
secs] [Times: user=0.58 sys=0.01, real=0.12 secs] 
Heap after GC invocations=190322 (full 281):
 par new generation   total 737280K, used 67732K [0x00000003fae00000, 0x000000042ce00000,
0x000000042ce00000)
  eden space 655360K,   3% used [0x00000003fae00000, 0x00000003fc212690, 0x0000000422e00000)
  from space 81920K,  57% used [0x0000000427e00000, 0x000000042ac12988, 0x000000042ce00000)
  to   space 81920K,  79% used [0x0000000422e00000, 0x0000000426d46538, 0x0000000427e00000)
 concurrent mark-sweep generation total 15958016K, used 14814420K [0x000000042ce00000, 0x00000007fae00000,
0x00000007fae00000)
 concurrent-mark-sweep perm gen total 44188K, used 26411K [0x00000007fae00000, 0x00000007fd927000,
0x0000000800000000)
}
GC locker: Trying a full collection because scavenge failed
{Heap before GC invocations=190322 (full 281):
 par new generation   total 737280K, used 67732K [0x00000003fae00000, 0x000000042ce00000,
0x000000042ce00000)
  eden space 655360K,   3% used [0x00000003fae00000, 0x00000003fc212690, 0x0000000422e00000)
  from space 81920K,  57% used [0x0000000427e00000, 0x000000042ac12988, 0x000000042ce00000)
  to   space 81920K,  79% used [0x0000000422e00000, 0x0000000426d46538, 0x0000000427e00000)
 concurrent mark-sweep generation total 15958016K, used 14814420K [0x000000042ce00000, 0x00000007fae00000,
0x00000007fae00000)
 concurrent-mark-sweep perm gen total 44188K, used 26411K [0x00000007fae00000, 0x00000007fd927000,
0x0000000800000000)
2013-09-20T07:32:59.212+0100: 141675.242: [Full GC 141675.242: [CMS2013-09-20T07:33:06.691+0100:
141682.721: [CMS-concurrent-sweep: 19.719/29.300 secs] [Times: user=146.19 sys=3.74, real=29.31
secs] 
 (concurrent mode failure): 14814420K->7653329K(15958016K), 35.8052520 secs] 14882152K->7653329K(16695296K),
[CMS Perm : 26411K->26355K(44188K)], 35.8055760 secs] [Times: user=35.74 sys=0.04, real=35.80
secs] 
Heap after GC invocations=190323 (full 282):
 par new generation   total 737280K, used 0K [0x00000003fae00000, 0x000000042ce00000, 0x000000042ce00000)
  eden space 655360K,   0% used [0x00000003fae00000, 0x00000003fae00000, 0x0000000422e00000)
  from space 81920K,   0% used [0x0000000427e00000, 0x0000000427e00000, 0x000000042ce00000)
  to   space 81920K,   0% used [0x0000000422e00000, 0x0000000422e00000, 0x0000000427e00000)
 concurrent mark-sweep generation total 15958016K, used 7653329K [0x000000042ce00000, 0x00000007fae00000,
0x00000007fae00000)
 concurrent-mark-sweep perm gen total 44188K, used 26355K [0x00000007fae00000, 0x00000007fd927000,
0x0000000800000000)
}
Total time for which application threads were stopped: 35.9305810 seconds
Total time for which application threads were stopped: 0.0030240 seconds


...


2013-09-20T09:58:41.765+0100: 150417.795: [GC 150417.796: [ParNew
Desired survivor size 41943040 bytes, new threshold 1 (max 1)
- age   1:   83887848 bytes,   83887848 total
: 674422K->81920K(737280K), 0.0680000 secs] 15824090K->15233726K(16695296K), 0.0685120
secs] [Times: user=0.54 sys=0.00, real=0.07 secs] 
Heap after GC invocations=214529 (full 323):
 par new generation   total 737280K, used 81920K [0x00000003fae00000, 0x000000042ce00000,
0x000000042ce00000)
  eden space 655360K,   0% used [0x00000003fae00000, 0x00000003fae00000, 0x0000000422e00000)
  from space 81920K, 100% used [0x0000000427e00000, 0x000000042ce00000, 0x000000042ce00000)
  to   space 81920K,   0% used [0x0000000422e00000, 0x0000000422e00000, 0x0000000427e00000)
 concurrent mark-sweep generation total 15958016K, used 15151806K [0x000000042ce00000, 0x00000007fae00000,
0x00000007fae00000)
 concurrent-mark-sweep perm gen total 44188K, used 26424K [0x00000007fae00000, 0x00000007fd927000,
0x0000000800000000)
}
Total time for which application threads were stopped: 0.0721100 seconds
{Heap before GC invocations=214529 (full 323):
 par new generation   total 737280K, used 82214K [0x00000003fae00000, 0x000000042ce00000,
0x000000042ce00000)
  eden space 655360K,   0% used [0x00000003fae00000, 0x00000003fae49998, 0x0000000422e00000)
  from space 81920K, 100% used [0x0000000427e00000, 0x000000042ce00000, 0x000000042ce00000)
  to   space 81920K,   0% used [0x0000000422e00000, 0x0000000422e00000, 0x0000000427e00000)
 concurrent mark-sweep generation total 15958016K, used 15151806K [0x000000042ce00000, 0x00000007fae00000,
0x00000007fae00000)
 concurrent-mark-sweep perm gen total 44188K, used 26424K [0x00000007fae00000, 0x00000007fd927000,
0x0000000800000000)
2013-09-20T09:58:41.837+0100: 150417.868: [GC 150417.868: [ParNew (0: promotion failure size
= 1677)  (1: promotion failure size = 2584)  (2: promotion failure size = 2584)  (3: promotion
failure size = 1723)  (4: promotion failure size = 1723)  (7: promotion failure size
 = 4766)  (promotion failed)
Desired survivor size 41943040 bytes, new threshold 1 (max 1)
- age   1:      10688 bytes,      10688 total
: 82214K->62920K(737280K), 0.4677070 secs] 15234020K->15298061K(16695296K), 0.4681720
secs] [Times: user=1.15 sys=0.01, real=0.46 secs] 
Heap after GC invocations=214530 (full 323):
 par new generation   total 737280K, used 62920K [0x00000003fae00000, 0x000000042ce00000,
0x000000042ce00000)
  eden space 655360K,   0% used [0x00000003fae00000, 0x00000003fae49998, 0x0000000422e00000)
  from space 81920K,  76% used [0x0000000422e00000, 0x0000000426b28940, 0x0000000427e00000)
  to   space 81920K, 100% used [0x0000000427e00000, 0x000000042ce00000, 0x000000042ce00000)
 concurrent mark-sweep generation total 15958016K, used 15235140K [0x000000042ce00000, 0x00000007fae00000,
0x00000007fae00000)
 concurrent-mark-sweep perm gen total 44188K, used 26424K [0x00000007fae00000, 0x00000007fd927000,
0x0000000800000000)
}
GC locker: Trying a full collection because scavenge failed
{Heap before GC invocations=214530 (full 323):
 par new generation   total 737280K, used 62920K [0x00000003fae00000, 0x000000042ce00000,
0x000000042ce00000)
  eden space 655360K,   0% used [0x00000003fae00000, 0x00000003fae49998, 0x0000000422e00000)
  from space 81920K,  76% used [0x0000000422e00000, 0x0000000426b28940, 0x0000000427e00000)
  to   space 81920K, 100% used [0x0000000427e00000, 0x000000042ce00000, 0x000000042ce00000)
 concurrent mark-sweep generation total 15958016K, used 15235140K [0x000000042ce00000, 0x00000007fae00000,
0x00000007fae00000)
 concurrent-mark-sweep perm gen total 44188K, used 26424K [0x00000007fae00000, 0x00000007fd927000,
0x0000000800000000)
2013-09-20T09:58:42.306+0100: 150418.336: [Full GC 150418.336: [CMS2013-09-20T09:58:46.720+0100:
150422.751: [CMS-concurrent-preclean: 7.057/10.443 secs] [Times: user=45.24 sys=0.32, real=10.44
secs] 
 (concurrent mode failure): 15235140K->5325067K(15958016K), 26.3214360 secs] 15298061K->5325067K(16695296K),
[CMS Perm : 26424K->26343K(44188K)], 26.3218650 secs] [Times: user=26.29 sys=0.02, real=26.33
secs] 
Heap after GC invocations=214531 (full 324):
 par new generation   total 737280K, used 0K [0x00000003fae00000, 0x000000042ce00000, 0x000000042ce00000)
  eden space 655360K,   0% used [0x00000003fae00000, 0x00000003fae00000, 0x0000000422e00000)
  from space 81920K,   0% used [0x0000000422e00000, 0x0000000422e00000, 0x0000000427e00000)
  to   space 81920K,   0% used [0x0000000427e00000, 0x0000000427e00000, 0x000000042ce00000)
 concurrent mark-sweep generation total 15958016K, used 5325067K [0x000000042ce00000, 0x00000007fae00000,
0x00000007fae00000)
 concurrent-mark-sweep perm gen total 44188K, used 26343K [0x00000007fae00000, 0x00000007fd927000,
0x0000000800000000)
}
Total time for which application threads were stopped: 26.7940000 seconds
Total time for which application threads were stopped: 0.0408350 seconds
Total time for which application threads were stopped: 0.0264510 seconds



Thanks for the help,
André Cruz

Mime
View raw message