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

G1 Full GC always performs heap verification after JDK-8269295

XMLWordPrintable

    • gc
    • b06
    • b07
    • Verified

      I get the impression that G1 veriffication got turned on by default?

      Before the change:
      [1.418s][info][gc,task ] GC(7) Using 1 workers of 48 for full compaction
      [1.418s][info][gc,start ] GC(7) Pause Full (System.gc())
      [1.418s][info][gc,phases,start] GC(7) Phase 1: Mark live objects
      [1.424s][info][gc,phases ] GC(7) Phase 1: Mark live objects 5.746ms
      [1.424s][info][gc,phases,start] GC(7) Phase 2: Prepare for compaction
      [1.425s][info][gc,phases ] GC(7) Phase 2: Prepare for compaction 0.720ms
      [1.425s][info][gc,phases,start] GC(7) Phase 3: Adjust pointers
      [1.428s][info][gc,phases ] GC(7) Phase 3: Adjust pointers 3.534ms
      [1.428s][info][gc,phases,start] GC(7) Phase 4: Compact heap
      [1.429s][info][gc,phases ] GC(7) Phase 4: Compact heap 0.536ms
      [1.430s][info][gc ] GC(7) Pause Full (System.gc()) 3M->3M(160M) 11.715ms
      [1.430s][info][gc,heap ] GC(7) Eden regions: 1->0(1)
      [1.430s][info][gc,heap ] GC(7) Survivor regions: 0->0(0)
      [1.430s][info][gc,heap ] GC(7) Old regions: 1->1
      [1.430s][info][gc,heap ] GC(7) Archive regions: 2->2
      [1.430s][info][gc,heap ] GC(7) Humongous regions: 0->0
      [1.430s][info][gc,metaspace ] GC(7) Metaspace: 14041K(14272K)->14041K(14272K) NonClass: 12686K(12800K)->12686K(12800K) Class: 1355K(1472K)->1355K(1472K)
      [1.430s][info][gc,cpu ] GC(7) User=0.03s Sys=0.00s Real=0.01s

      After the change:

      [1.968s][info][gc,task ] GC(7) Using 1 workers of 48 for full compaction
      [1.968s][info][gc,start ] GC(7) Pause Full (System.gc())
      [1.968s][info][gc,verify,start] GC(7) Verifying Before GC
      [2.006s][info][gc,verify ] GC(7) Verifying Before GC 38.124ms
      [2.006s][info][gc,phases,start] GC(7) Phase 1: Mark live objects
      [2.012s][info][gc,phases ] GC(7) Phase 1: Mark live objects 5.912ms
      [2.012s][info][gc,phases,start] GC(7) Phase 2: Prepare for compaction
      [2.013s][info][gc,phases ] GC(7) Phase 2: Prepare for compaction 0.723ms
      [2.013s][info][gc,phases,start] GC(7) Phase 3: Adjust pointers
      [2.016s][info][gc,phases ] GC(7) Phase 3: Adjust pointers 3.399ms
      [2.016s][info][gc,phases,start] GC(7) Phase 4: Compact heap
      [2.017s][info][gc,phases ] GC(7) Phase 4: Compact heap 0.549ms
      [2.018s][info][gc,verify,start] GC(7) Verifying After GC
      [2.057s][info][gc,verify ] GC(7) Verifying After GC 38.438ms
      [2.057s][info][gc ] GC(7) Pause Full (System.gc()) 3M->3M(160M) 88.347ms
      [2.057s][info][gc,heap ] GC(7) Eden regions: 1->0(1)
      [2.057s][info][gc,heap ] GC(7) Survivor regions: 0->0(0)
      [2.057s][info][gc,heap ] GC(7) Old regions: 1->1
      [2.057s][info][gc,heap ] GC(7) Archive regions: 2->2
      [2.057s][info][gc,heap ] GC(7) Humongous regions: 0->0
      [2.057s][info][gc,metaspace ] GC(7) Metaspace: 14060K(14336K)->14060K(14336K) NonClass: 12706K(12864K)->12706K(12864K) Class: 1354K(1472K)->1354K(1472K)
      [2.057s][info][gc,cpu ] GC(7) User=0.10s Sys=0.00s Real=0.09s

      We run this test with -Xlog:gc*
      Is it the intent that verification runs at INFO level or using gc* is caveat emptor? It could be a surprise to add this relatively long phase.

            tschatzl Thomas Schatzl
            ecaspole Eric Caspole
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: