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

ZGC: Heap iteration and verification pollutes GC statistics

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Fixed
    • Icon: P4 P4
    • 13
    • 13
    • hotspot
    • gc
    • b15

      When performing heap iteration / inspection operation the root iteration is recorded in our gc stats. Since this kind of iteration is single-threaded and slower than normal GCs, it show up as a hickup in our gc stats. The ouput looks odd, because there's no GC Pause associated with these events.

      [981,393s][info][gc,stats ] === Garbage Collection Statistics =======================================================================================================================
      [981,393s][info][gc,stats ] Last 10s Last 10m Last 10h Total
      [981,393s][info][gc,stats ] Avg / Max Avg / Max Avg / Max Avg / Max
      [981,393s][info][gc,stats ] Collector: Garbage Collection Cycle 0,000 / 0,000 386,139 / 423,359 283,046 / 423,359 283,046 / 423,359 ms
      [981,393s][info][gc,stats ] Contention: Mark Segment Reset Contention 0 / 0 0 / 0 0 / 8 0 / 8 ops/s
      [981,393s][info][gc,stats ] Contention: Mark SeqNum Reset Contention 0 / 0 0 / 0 0 / 0 0 / 0 ops/s
      [981,393s][info][gc,stats ] Contention: Relocation Contention 0 / 0 0 / 1 0 / 6 0 / 6 ops/s
      [981,394s][info][gc,stats ] Critical: Allocation Stall 0,000 / 0,000 0,000 / 0,000 0,000 / 0,000 0,000 / 0,000 ms
      [981,394s][info][gc,stats ] Critical: Allocation Stall 0 / 0 0 / 0 0 / 0 0 / 0 ops/s
      [981,394s][info][gc,stats ] Critical: GC Locker Stall 0,000 / 0,000 0,000 / 0,000 0,000 / 0,000 0,000 / 0,000 ms
      [981,394s][info][gc,stats ] Critical: GC Locker Stall 0 / 0 0 / 0 0 / 0 0 / 0 ops/s
      [981,394s][info][gc,stats ] Memory: Allocation Rate 222 / 1144 9 / 1144 9 / 1144 9 / 1144 MB/s
      [981,394s][info][gc,stats ] Memory: Heap Used After Mark 0 / 0 1886 / 2426 1055 / 2426 1055 / 2426 MB
      [981,394s][info][gc,stats ] Memory: Heap Used After Relocation 0 / 0 250 / 252 202 / 252 202 / 252 MB
      [981,394s][info][gc,stats ] Memory: Heap Used Before Mark 0 / 0 1884 / 2424 1040 / 2424 1040 / 2424 MB
      [981,394s][info][gc,stats ] Memory: Heap Used Before Relocation 0 / 0 953 / 1080 688 / 1136 688 / 1136 MB
      [981,394s][info][gc,stats ] Memory: Out Of Memory 0 / 0 0 / 0 0 / 0 0 / 0 ops/s
      [981,394s][info][gc,stats ] Memory: Page Cache Flush 0 / 0 0 / 0 0 / 0 0 / 0 MB/s
      [981,394s][info][gc,stats ] Memory: Page Cache Hit L1 17 / 92 1 / 92 1 / 92 1 / 92 ops/s
      [981,394s][info][gc,stats ] Memory: Page Cache Hit L2 4 / 23 0 / 30 0 / 41 0 / 41 ops/s
      [981,394s][info][gc,stats ] Memory: Page Cache Miss 3 / 12 0 / 34 0 / 148 0 / 148 ops/s
      [981,394s][info][gc,stats ] Memory: Undo Object Allocation Failed 0 / 0 0 / 0 0 / 0 0 / 0 ops/s
      [981,394s][info][gc,stats ] Memory: Undo Object Allocation Succeeded 0 / 0 0 / 1 0 / 6 0 / 6 ops/s

      81,394s][info][gc,stats ] Memory: Undo Page Allocation 0 / 0 0 / 1 0 / 1 0 / 1 ops/s
      [981,394s][info][gc,stats ] Phase: Concurrent Destroy Detached Pages 0,000 / 0,000 0,001 / 0,001 0,001 / 0,001 0,001 / 0,001 ms
      [981,394s][info][gc,stats ] Phase: Concurrent Mark 0,000 / 0,000 267,866 / 302,469 155,921 / 302,469 155,921 / 302,469 ms
      [981,394s][info][gc,stats ] Phase: Concurrent Mark Continue 0,000 / 0,000 10,942 / 11,035 9,121 / 14,714 9,121 / 14,714 ms
      [981,394s][info][gc,stats ] Phase: Concurrent Prepare Relocation Set 0,000 / 0,000 13,074 / 14,429 11,154 / 14,429 11,154 / 14,429 ms
      [981,394s][info][gc,stats ] Phase: Concurrent Process Non-Strong References 0,000 / 0,000 31,321 / 31,614 58,810 / 178,253 58,810 / 178,253 ms
      [981,394s][info][gc,stats ] Phase: Concurrent Relocate 0,000 / 0,000 49,866 / 51,448 36,762 / 51,448 36,762 / 51,448 ms
      [981,394s][info][gc,stats ] Phase: Concurrent Reset Relocation Set 0,000 / 0,000 2,207 / 2,489 1,325 / 2,489 1,325 / 2,489 ms
      [981,394s][info][gc,stats ] Phase: Concurrent Select Relocation Set 0,000 / 0,000 7,290 / 7,657 5,091 / 9,431 5,091 / 9,431 ms
      [981,394s][info][gc,stats ] Phase: Pause Mark End 0,000 / 0,000 0,670 / 1,208 1,025 / 2,597 1,025 / 2,597 ms
      [981,394s][info][gc,stats ] Phase: Pause Mark Start 0,000 / 0,000 0,463 / 0,469 1,043 / 2,434 1,043 / 2,434 ms
      [981,394s][info][gc,stats ] Phase: Pause Relocate Start 0,000 / 0,000 0,191 / 0,208 0,568 / 1,644 0,568 / 1,644 ms
      [981,394s][info][gc,stats ] Subphase: Concurrent Classes Unload 0,000 / 0,000 26,813 / 26,957 55,859 / 173,824 55,859 / 173,824 ms
      [981,394s][info][gc,stats ] Subphase: Concurrent Mark 0,000 / 0,000 137,887 / 300,747 87,077 / 300,747 87,077 / 300,747 ms
      [981,394s][info][gc,stats ] Subphase: Concurrent Mark Idle 0,000 / 0,000 1,086 / 1,110 1,085 / 1,121 1,085 / 1,121 ms
      [981,394s][info][gc,stats ] Subphase: Concurrent Mark Try Flush 0,000 / 0,000 0,077 / 0,122 0,116 / 0,492 0,116 / 0,492 ms
      [981,394s][info][gc,stats ] Subphase: Concurrent Mark Try Terminate 0,000 / 0,000 0,688 / 1,120 0,720 / 1,123 0,720 / 1,123 ms
      [981,394s][info][gc,stats ] Subphase: Concurrent References Enqueue 0,000 / 0,000 0,018 / 0,031 0,012 / 0,031 0,012 / 0,031 ms
      [981,394s][info][gc,stats ] Subphase: Concurrent References Process 0,000 / 0,000 1,764 / 1,887 1,056 / 1,887 1,056 / 1,887 ms
      [981,394s][info][gc,stats ] Subphase: Concurrent Roots 2,356 / 5,908 1,365 / 5,908 0,717 / 5,908 0,717 / 5,908 ms
      [981,394s][info][gc,stats ] Subphase: Concurrent Roots ClassLoaderDataGraph 2,320 / 5,781 1,341 / 5,781 0,743 / 5,781 0,743 / 5,781 ms
      [981,394s][info][gc,stats ] Subphase: Concurrent Roots JNIHandles 0,035 / 0,125 0,026 / 0,125 0,020 / 0,125 0,020 / 0,125 ms
      [981,394s][info][gc,stats ] Subphase: Concurrent Roots Setup 0,000 / 0,000 0,172 / 1,117 0,203 / 1,117 0,203 / 1,117 ms
      [981,395s][info][gc,stats ] Subphase: Concurrent Roots Teardown 0,000 / 0,000 0,000 / 0,001 0,000 / 0,001 0,000 / 0,001 ms
      [981,395s][info][gc,stats ] Subphase: Concurrent Weak Roots 3,988 / 7,926 3,306 / 7,926 2,279 / 7,926 2,279 / 7,926 ms
      [981,395s][info][gc,stats ] Subphase: Concurrent Weak Roots JNIWeakHandles 0,000 / 0,000 0,000 / 0,000 0,000 / 0,001 0,000 / 0,001 ms
      [981,395s][info][gc,stats ] Subphase: Concurrent Weak Roots StringTable 3,839 / 7,675 3,164 / 7,675 2,182 / 7,675 2,182 / 7,675 ms
      [981,395s][info][gc,stats ] Subphase: Concurrent Weak Roots VMWeakHandles 0,148 / 0,249 0,139 / 0,249 0,095 / 0,249 0,095 / 0,249 ms
      [981,395s][info][gc,stats ] Subphase: Pause Mark Try Complete 0,000 / 0,000 0,645 / 1,041 0,387 / 1,081 0,387 / 1,081 ms
      [981,395s][info][gc,stats ] Subphase: Pause Roots 10,502 / 15,535 0,545 / 15,535 0,236 / 15,535 0,236 / 15,535 ms
      [981,395s][info][gc,stats ] Subphase: Pause Roots CodeCache 0,000 / 0,000 0,000 / 0,000 0,000 / 0,000 0,000 / 0,000 ms
      [981,395s][info][gc,stats ] Subphase: Pause Roots JVMTIExport 0,001 / 0,001 0,001 / 0,001 0,001 / 0,001 0,001 / 0,001 ms
      [981,395s][info][gc,stats ] Subphase: Pause Roots JVMTIWeakExport 0,000 / 0,000 0,001 / 0,001 0,001 / 0,001 0,001 / 0,001 ms
      [981,395s][info][gc,stats ] Subphase: Pause Roots Management 0,002 / 0,006 0,002 / 0,006 0,002 / 0,007 0,002 / 0,007 ms
      [981,395s][info][gc,stats ] Subphase: Pause Roots ObjectSynchronizer 0,012 / 0,048 0,010 / 0,048 0,006 / 0,048 0,006 / 0,048 ms
      [981,395s][info][gc,stats ] Subphase: Pause Roots Setup 0,001 / 0,001 0,001 / 0,001 0,001 / 0,003 0,001 / 0,003 ms
      [981,395s][info][gc,stats ] Subphase: Pause Roots SystemDictionary 0,125 / 0,453 0,097 / 0,453 0,067 / 0,453 0,067 / 0,453 ms
      [981,395s][info][gc,stats ] Subphase: Pause Roots Teardown 0,001 / 0,001 0,001 / 0,004 0,004 / 0,019 0,004 / 0,019 ms
      [981,395s][info][gc,stats ] Subphase: Pause Roots Threads 10,312 / 15,355 0,689 / 15,355 0,271 / 15,355 0,271 / 15,355 ms
      [981,395s][info][gc,stats ] Subphase: Pause Roots Universe 0,047 / 0,078 0,034 / 0,078 0,023 / 0,078 0,023 / 0,078 ms
      [981,395s][info][gc,stats ] Subphase: Pause Weak Roots 0,002 / 0,002 0,001 / 0,003 0,000 / 0,010 0,000 / 0,010 ms
      [981,395s][info][gc,stats ] Subphase: Pause Weak Roots JFRWeak 0,001 / 0,001 0,001 / 0,001 0,001 / 0,007 0,001 / 0,007 ms
      [981,395s][info][gc,stats ] Subphase: Pause Weak Roots JVMTIWeakExport 0,000 / 0,000 0,001 / 0,001 0,001 / 0,001 0,001 / 0,001 ms
      [981,395s][info][gc,stats ] Subphase: Pause Weak Roots Setup 0,000 / 0,000 0,000 / 0,000 0,000 / 0,000 0,000 / 0,000 ms
      [981,395s][info][gc,stats ] Subphase: Pause Weak Roots Teardown 0,000 / 0,000 0,000 / 0,000 0,000 / 0,000 0,000 / 0,000 ms
      [981,395s][info][gc,stats ] System: Java Threads 0 / 0 58 / 69 53 / 69 53 / 69 threads
      [981,395s][info][gc,stats ] =========================================================================================================================================================

            pliden Per Liden (Inactive)
            stefank Stefan Karlsson
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved: