heap memory usage increasing over time with a fixed live set size

[Amir Hadadi]

Hello all,
I've encountered a problem of increasing heap usage with Shenandoah.
For a workload with a non increasing live set, the used memory as reported in the logs at the end of a gc cycle is constantly increasing.
The total time spent in concurrent gc as reported by GarbageCollectorMXBean::getCollectionTime is also constantly increasing, starting at 5% of the time going up to 60% and more.
The memory usage is going up from 500MB to 2500MB over a period of 2-3 days, again without the live set materially changing. At this point I'm forced to restart the nodes.

I'm using an OpenJDK 12.0.2 binary from AdoptOpenJdk in a container based on alpine linux.
No special command line flags, I'm only setting the number of concurrent gc threads to 2.
Any pointers on what can be the issue and how to debug it will be greatly appreciated!

This is an excerpt from the gc logs at a stage where the used memory is 985MB:


[60988.631s][info][gc            ] Trigger: Average GC time (338.67 ms) is above the time for allocation rate (628.11 MB/s) to deplete free headroom (212M)

[60988.631s][info][gc,ergo       ] Free headroom: 366M (free) - 153M (spike) - 0M (penalties) = 212M

[60988.631s][info][gc,ergo       ] Free: 366M (373 regions), Max regular: 1024K, Max humongous: 161792K, External frag: 57%, Internal frag: 1%

[60988.631s][info][gc,ergo       ] Evacuation Reserve: 154M (154 regions), Max regular: 1024K

[60988.631s][info][gc,start      ] GC(16150) Concurrent reset

[60988.631s][info][gc,task       ] GC(16150) Using 2 of 6 workers for concurrent reset

[60988.634s][info][gc            ] GC(16150) Concurrent reset 2540M->2541M(3072M) 2.908ms

[60988.635s][info][gc,start      ] GC(16150) Pause Init Mark (process weakrefs)

[60988.635s][info][gc,task       ] GC(16150) Using 6 of 6 workers for init marking

[60988.640s][info][gc,ergo       ] GC(16150) Pacer for Mark. Expected Live: 512M, Free: 365M, Non-Taxable: 36M, Alloc Tax Rate: 5.1x

[60988.640s][info][gc            ] GC(16150) Pause Init Mark (process weakrefs) 5.468ms

[60988.641s][info][gc,start      ] GC(16150) Concurrent marking (process weakrefs)

[60988.641s][info][gc,task       ] GC(16150) Using 2 of 6 workers for concurrent marking

[60988.838s][info][gc            ] GC(16150) Concurrent marking (process weakrefs) 2543M->2648M(3072M) 196.966ms

[60988.838s][info][gc,start      ] GC(16150) Concurrent precleaning

[60988.838s][info][gc,task       ] GC(16150) Using 1 of 6 workers for concurrent preclean

[60988.839s][info][gc            ] GC(16150) Concurrent precleaning 2648M->2649M(3072M) 1.010ms

[60988.840s][info][gc,start      ] GC(16150) Pause Final Mark (process weakrefs)

[60988.840s][info][gc,task       ] GC(16150) Using 6 of 6 workers for final marking

[60988.841s][info][gc,ergo       ] GC(16150) Adaptive CSet Selection. Target Free: 307M, Actual Free: 1071M, Max CSet: 128M, Min Garbage: 0M

[60988.842s][info][gc,ergo       ] GC(16150) Collectable Garbage: 923M (45% of total), 4M CSet, 928 CSet regions

[60988.842s][info][gc,ergo       ] GC(16150) Immediate Garbage: 856M (42% of total), 857 regions

[60988.843s][info][gc,ergo       ] GC(16150) Pacer for Evacuation. Used CSet: 927M, Free: 1113M, Non-Taxable: 111M, Alloc Tax Rate: 2.0x

[60988.843s][info][gc            ] GC(16150) Pause Final Mark (process weakrefs) 2.489ms

[60988.843s][info][gc,start      ] GC(16150) Concurrent cleanup

[60988.843s][info][gc            ] GC(16150) Concurrent cleanup 2649M->1800M(3072M) 0.581ms

[60988.843s][info][gc,ergo       ] GC(16150) Free: 1106M (1113 regions), Max regular: 1024K, Max humongous: 61440K, External frag: 95%, Internal frag: 0%

[60988.843s][info][gc,ergo       ] GC(16150) Evacuation Reserve: 153M (154 regions), Max regular: 1024K

[60988.843s][info][gc,start      ] GC(16150) Concurrent evacuation

[60988.843s][info][gc,task       ] GC(16150) Using 2 of 6 workers for concurrent evacuation

[60988.849s][info][gc            ] GC(16150) Concurrent evacuation 1800M->1834M(3072M) 5.537ms

[60988.850s][info][gc,start      ] GC(16150) Pause Init Update Refs

[60988.850s][info][gc,ergo       ] GC(16150) Pacer for Update Refs. Used: 1834M, Free: 1078M, Non-Taxable: 107M, Alloc Tax Rate: 2.1x

[60988.850s][info][gc            ] GC(16150) Pause Init Update Refs 0.163ms

[60988.850s][info][gc,start      ] GC(16150) Concurrent update references

[60988.850s][info][gc,task       ] GC(16150) Using 2 of 6 workers for concurrent reference update

[60988.955s][info][gc            ] GC(16150) Concurrent update references 1834M->1913M(3072M) 104.698ms

[60988.955s][info][gc,start      ] GC(16150) Pause Final Update Refs

[60988.955s][info][gc,task       ] GC(16150) Using 6 of 6 workers for final reference update

[60988.958s][info][gc            ] GC(16150) Pause Final Update Refs 2.189ms

[60988.958s][info][gc,start      ] GC(16150) Concurrent cleanup

[60988.958s][info][gc            ] GC(16150) Concurrent cleanup 1913M->985M(3072M) 0.464ms

[60988.958s][info][gc,ergo       ] Free: 1921M (1928 regions), Max regular: 1024K, Max humongous: 1040384K, External frag: 48%, Internal frag: 0%

[60988.958s][info][gc,ergo       ] Evacuation Reserve: 154M (154 regions), Max regular: 1024K

[60988.958s][info][gc,ergo       ] Pacer for Idle. Initial: 61M, Alloc Tax Rate: 1.0x