A DESCRIPTION OF THE PROBLEM :
When running an application using ZGC, we're seeing differing results reported in the GC log vs the GC. Based on heap dumps and the performance of the application, the GC Log appears to be accurate. The issue seems to be that the GC Notification is firing before the garbage collection has actually completed. And in this case there's not another GC notification, until the next garbage collection. In particular the GC log says that

[2020-03-04T17:49:01.022+0000][info][gc ] GC(35453) Garbage Collection (Allocation Rate) 2824M(92%)->660M(21%)

While for the ZHeap post-gc memory usage we're seeing

2020-03-04 17:49:00.937 [TRUNCATED] memoryUsageAfterGc={ZHeap=init = 134217728(131072K) used = 2734686208(2670592K) committed = 3221225472(3145728K) max = 3221225472(3145728K)

Here is the complete GC Notification object log

2020-03-04 17:49:00.937 [Service Thread] DEBUG c.h.s.g.n.GcLoggingNotificationListener - Received gc notification gcName=ZGC, gcAction=end of major GC, gcCause=Allocation Rate, durationMs=278, memoryUsageBeforeGc={ZHeap=init = 134217728(131072K) used = 2961178624(2891776K) committed = 3221225472(3145728K) max = 3221225472(3145728K), CodeHeap 'profiled nmethods'=init = 2555904(2496K) used = 9267200(9050K) committed = 48955392(47808K) max = 122908672(120028K), CodeHeap 'non-profiled nmethods'=init = 2555904(2496K) used = 35616640(34781K) committed = 39583744(38656K) max = 122912768(120032K), Metaspace=init = 0(0K) used = 128999872(125976K) committed = 130547712(127488K) max = 268435456(262144K), CodeHeap 'non-nmethods'=init = 2555904(2496K) used = 1462656(1428K) committed = 2555904(2496K) max = 5836800(5700K)}, memoryUsageAfterGc={ZHeap=init = 134217728(131072K) used = 2734686208(2670592K) committed = 3221225472(3145728K) max = 3221225472(3145728K), CodeHeap 'profiled nmethods'=init = 2555904(2496K) used = 9267200(9050K) committed = 48955392(47808K) max = 122908672(120028K), CodeHeap 'non-profiled nmethods'=init = 2555904(2496K) used = 35616640(34781K) committed = 39583744(38656K) max = 122912768(120032K), Metaspace=init = 0(0K) used = 128999872(125976K) committed = 130547712(127488K) max = 268435456(262144K), CodeHeap 'non-nmethods'=init = 2555904(2496K) used = 1462656(1428K) committed = 2555904(2496K) max = 5836800(5700K)}

And here is the complete GC Log
[2020-03-04T17:49:00.658+0000][info][gc,start ] GC(35453) Garbage Collection (Allocation Rate)
[2020-03-04T17:49:00.661+0000][info][gc,phases ] GC(35453) Pause Mark Start 2.303ms
[2020-03-04T17:49:00.897+0000][info][gc,phases ] GC(35453) Concurrent Mark 235.470ms
[2020-03-04T17:49:00.897+0000][info][gc,phases ] GC(35453) Pause Mark End 0.249ms
[2020-03-04T17:49:00.899+0000][info][gc,phases ] GC(35453) Concurrent Process Non-Strong References 1.713ms
[2020-03-04T17:49:00.903+0000][info][gc,phases ] GC(35453) Concurrent Reset Relocation Set 3.443ms
[2020-03-04T17:49:00.903+0000][info][gc,phases ] GC(35453) Concurrent Destroy Detached Pages 0.001ms
[2020-03-04T17:49:00.903+0000][info][gc ] Allocation Stall (REDACTED) 128.797ms
[2020-03-04T17:49:00.903+0000][info][gc ] Allocation Stall (REDACTED) 100.720ms
[2020-03-04T17:49:00.903+0000][info][gc ] Allocation Stall (REDACTED) 79.658ms
[2020-03-04T17:49:00.903+0000][info][gc ] Allocation Stall (REDACTED) 64.611ms
[2020-03-04T17:49:00.903+0000][info][gc ] Allocation Stall (REDACTED) 114.481ms
[2020-03-04T17:49:00.903+0000][info][gc ] Allocation Stall (REDACTED) 117.579ms
[2020-03-04T17:49:00.903+0000][info][gc ] Allocation Stall (REDACTED) 131.113ms
[2020-03-04T17:49:00.905+0000][info][gc,phases ] GC(35453) Concurrent Select Relocation Set 2.032ms
[2020-03-04T17:49:00.933+0000][info][gc,phases ] GC(35453) Concurrent Prepare Relocation Set 27.905ms
[2020-03-04T17:49:00.936+0000][info][gc,phases ] GC(35453) Pause Relocate Start 3.189ms
[2020-03-04T17:49:01.021+0000][info][gc,phases ] GC(35453) Concurrent Relocate 84.751ms
[2020-03-04T17:49:01.021+0000][info][gc,load ] GC(35453) Load: 30.29/30.11/30.54
[2020-03-04T17:49:01.021+0000][info][gc,mmu ] GC(35453) MMU: 2ms/0.0%, 5ms/0.0%, 10ms/0.0%, 20ms/0.0%, 50ms/44.6%, 100ms/71.8%
[2020-03-04T17:49:01.021+0000][info][gc,marking ] GC(35453) Mark: 4 stripe(s), 6 proactive flush(es), 1 terminate flush(es), 0 completion(s), 0 continuation(s)
[2020-03-04T17:49:01.021+0000][info][gc,reloc ] GC(35453) Relocation: Successful, 164M relocated
[2020-03-04T17:49:01.021+0000][info][gc,nmethod ] GC(35453) NMethods: 9809 registered, 35 unregistered
[2020-03-04T17:49:01.021+0000][info][gc,metaspace] GC(35453) Metaspace: 123M used, 124M capacity, 124M committed, 126M reserved
[2020-03-04T17:49:01.021+0000][info][gc,ref ] GC(35453) Soft: 2537 encountered, 296 discovered, 0 enqueued
[2020-03-04T17:49:01.021+0000][info][gc,ref ] GC(35453) Weak: 9215 encountered, 4662 discovered, 8 enqueued
[2020-03-04T17:49:01.021+0000][info][gc,ref ] GC(35453) Final: 1474 encountered, 18 discovered, 18 enqueued
[2020-03-04T17:49:01.021+0000][info][gc,ref ] GC(35453) Phantom: 2272 encountered, 2015 discovered, 2 enqueued
[2020-03-04T17:49:01.021+0000][info][gc,heap ] GC(35453) Mark Start Mark End Relocate Start Relocate End High Low
[2020-03-04T17:49:01.021+0000][info][gc,heap ] GC(35453) Capacity: 3072M (100%) 3072M (100%) 3072M (100%) 3072M (100%) 3072M (100%) 3072M (100%)
[2020-03-04T17:49:01.021+0000][info][gc,heap ] GC(35453) Reserve: 44M (1%) 44M (1%) 44M (1%) 44M (1%) 44M (1%) 44M (1%)
[2020-03-04T17:49:01.021+0000][info][gc,heap ] GC(35453) Free: 204M (7%) 0M (0%) 432M (14%) 2368M (77%) 2368M (77%) 0M (0%)
[2020-03-04T17:49:01.022+0000][info][gc,heap ] GC(35453) Used: 2824M (92%) 3028M (99%) 2596M (85%) 660M (21%) 3028M (99%) 660M (21%)
[2020-03-04T17:49:01.022+0000][info][gc,heap ] GC(35453) Live: - 320M (10%) 320M (10%) 320M (10%) - -
[2020-03-04T17:49:01.022+0000][info][gc,heap ] GC(35453) Allocated: - 204M (7%) 242M (8%) 392M (13%) - -
[2020-03-04T17:49:01.022+0000][info][gc,heap ] GC(35453) Garbage: - 2503M (81%) 2041M (66%) 85M (3%) - -
[2020-03-04T17:49:01.022+0000][info][gc,heap ] GC(35453) Reclaimed: - - 462M (15%) 2418M (79%) - -
[2020-03-04T17:49:01.022+0000][info][gc ] GC(35453) Garbage Collection (Allocation Rate) 2824M(92%)->660M(21%)



FREQUENCY : always