Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8240679

ZGC GarbageCollectorMXBean reports inaccurate post GC heap size for ZHeap pool

    Details

    • Subcomponent:
      gc
    • Resolved In Build:
      b22
    • CPU:
      x86
    • OS:
      linux

      Description

      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


        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                pliden Per Liden
                Reporter:
                webbuggrp Webbug Group
              • Votes:
                0 Vote for this issue
                Watchers:
                4 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: