Identifying and fixing humongous allocations in cassandra
You have cassandra running fine, and then one day you start seeing long gc’s. What do you do? Well, in this case, I’m going to cover humongous allocations, what they look like in the logs, and what can be done.
First, identify that there’s a gc issue:
(ctool-env) ~/Downloads/61530 $ grep -iR "\d\d\d\dms" seed1 --include=system.log
seed1/logs/cassandra/system.log:WARN [GCInspector:1] 2020-04-29 04:27:33,100 GCInspector.java:311 - G1 Young Generation GC in 1392ms. G1 Old Gen: 9942380664 -> 17187822392; G1 Survivor Space: 167772160 -> 0; G1 Eden Space: 10141827072 -> 0seed1/logs/cassandra/system.log:WARN [GCInspector:1] 2020-04-29 04:33:00,874 GCInspector.java:311 - G1 Young Generation GC in 1248ms. G1 Old Gen: 11575799776 -> 16012529088; G1 Survivor Space: 75497472 -> 0; G1 Eden Space: 8371830784 -> 0seed1/logs/cassandra/system.log:WARN [GCInspector:1] 2020-04-29 04:33:04,496 GCInspector.java:311 - G1 Young Generation GC in 1802ms. G1 Old Gen: 19678328520 -> 17038250640; G1 Eden Space: 973078528 -> 0seed1/logs/cassandra/system.log:WARN [GCInspector:1] 2020-04-29 04:35:12,493 GCInspector.java:311 - G1 Young Generation GC in 1673ms. G1 Old Gen: 11019168568 -> 16922677384; G1 Survivor Space: 142606336 -> 0; G1 Eden Space: 9219080192 -> 0seed1/logs/cassandra/system.log:WARN [GCInspector:1] 2020-04-29 04:35:48,505 GCInspector.java:311 - G1 Old Generation GC in 16871ms. G1 Old Gen: 21391316304 -> 7196108584
Ouch. Those are all over 1s, and look at that last old gen pause, 16s. What can we glean from that information. For one, take a look at the Eden Space and Survivor Space on some of the gc’s, they’re 0. That’s not normal. You should see Eden clearing, but Survivor should not be 0. And then that last Old Gen gc, that makes a clear pattern, like we’re totally skipping young gen and going straight to old gen. And, that is indeed what is happening.
I pulled the gc logs and noticed that around the time of the long gc’s above, there were several humongous allocations:
seed1/logs/cassandra/gc.log.7:2020-04-29T04:33:04.519+0000: 9527741.690: [GC pause (G1 Humongous Allocation) (young) (initial-mark)
seed1/logs/cassandra/gc.log.7:2020-04-29T04:34:10.165+0000: 9527807.336: [GC pause (G1 Humongous Allocation) (young) (initial-mark)
seed1/logs/cassandra/gc.log.7:2020-04-29T04:34:51.737+0000: 9527848.909: [GC pause (G1 Humongous Allocation) (young) (initial-mark)
seed1/logs/cassandra/gc.log.7:2020-04-29T04:35:14.298+0000: 9527871.469: [GC pause (G1 Humongous Allocation) (young) (initial-mark)
seed1/logs/cassandra/gc.log.7:2020-04-29T04:35:18.853+0000: 9527876.024: [GC pause (G1 Humongous Allocation) (young)
seed1/logs/cassandra/gc.log.7:2020-04-29T04:35:19.913+0000: 9527877.084: [GC pause (G1 Humongous Allocation) (young)
seed1/logs/cassandra/gc.log.7:2020-04-29T04:35:20.947+0000: 9527878.119: [GC pause (G1 Humongous Allocation) (young)Now I know that there’s humongous allocations, but what size? No idea at this point. I need to add -XX:+PrintAdaptiveSizePolicy to jvm.options. This parameter prints the size of the humongous allocation.
14998: 6153.045: [G1Ergonomics (Concurrent Cycles) do not request concurrent cycle initiation, reason: still doing mixed collections, occupancy: 18245222400 bytes, allocation request: 4524944 bytes, threshold: 9663676380 bytes (45.00 %), source: concurrent humongous allocation]14999: 6153.047: [G1Ergonomics (Concurrent Cycles) do not request concurrent cycle initiation, reason: still doing mixed collections, occupancy: 18253611008 bytes, allocation request: 4299032 bytes, threshold: 9663676380 bytes (45.00 %), source: concurrent humongous allocation]
What I’m looking at is the allocation request size. In this case, it’s about 4.5MB. Well, I know from the gc logs, that the region size is 8MB:
14.414: [G1Ergonomics (Concurrent Cycles) request concurrent cycle initiation, reason: requested by GC cause, GC cause: Metadata GC Threshold]
{Heap before GC invocations=0 (full 0):
garbage-first heap total 20971520K, used 212992K [0x00000002c0000000, 0x00000002c0805000, 0x00000007c0000000)
region size 8192K, 27 young (221184K), 0 survivors (0K)The region size needs to be 2 times the allocation request size, which in this case 4.5 * 2 = ~9MB, so it’s not double the size. So, the allocation request is considered a humongous allocation and will totally skip young gen and get promoted directly to old gen. This is extremely inefficient because old gen is for one thing usually larger, and for another, not cleaned up as regularly.
There’s a few things to do to resolve this. First, why is so much being allocated? Usually the answer will be large blobs, and so that should be looked at from the application perspective. In this case, we are using blobs and it’s not terrible, we just have a small heap at 20G, so the region size measures out to 8M (20,000MB / 2048 = 9.76MB rounded down to nearest multiple of 2, ie. 2, 4, 8, 16, 32…where 32 is max).
NOTE: Tracking down and resolving the size of the blob is always the first option. Barring that, continue on to below.
To resolve the issue we increased the region size, -XX:G1HeapRegionSize=16M, and what a dramatic difference. We went from a high of 16s old gen gc to max of 348ms.
Check out gc easy graphs before and after we made the change on April 30, what a difference:
I hope this helped.
