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

G1 age table printout contains contents from previous GC

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: P2
    • Resolution: Fixed
    • Affects Version/s: 9
    • Fix Version/s: 9
    • Component/s: hotspot
    • Labels:
    • Subcomponent:
      gc
    • Resolved In Build:
      b137
    • Verification:
      Verified

      Description

      Has anyone noticed that in JDK 9 the age table in G1 is printed before the GC actually happens? This means that the age table information associated with each GC corresponds to the previous GC. Example:

      [2.382s][info][gc,start ] GC(0) Pause Young (G1 Evacuation Pause) (2.382s)
      [2.382s][info][gc,task ] GC(0) GC Workers: using 18 out of 18
      [2.382s][debug][gc,age ] GC(0) Desired survivor size 895483904 bytes, new threshold 6 (max threshold 6)
      ## No objects copied to the survivors?
      [2.383s][info ][gc,task ] GC(0) GC Workers: using 18 out of 18
      [2.415s][info ][gc,task ] GC(0) GC Workers: using 18 out of 18
      [2.415s][info ][gc,task ] GC(0) GC Workers: using 18 out of 18
      [2.416s][info ][gc,task ] GC(0) GC Workers: using 18 out of 18
      [2.417s][info ][gc,task ] GC(0) GC Workers: using 18 out of 18
      [2.417s][info ][gc,task ] GC(0) GC Workers: using 18 out of 18
      [2.417s][info ][gc,task ] GC(0) GC Workers: using 18 out of 18
      [2.418s][info ][gc,task ] GC(0) GC Workers: using 18 out of 18
      [2.419s][info ][gc,phases ] GC(0) Evacuate Collection Set: 32.1ms
      [2.419s][info ][gc,phases ] GC(0) Code Roots: 0.0ms
      [2.419s][info ][gc,phases ] GC(0) Clear Card Table: 1.5ms
      [2.419s][info ][gc,phases ] GC(0) Expand Heap After Collection: 0.0ms
      [2.419s][info ][gc,phases ] GC(0) Free Collection Set: 2.0ms
      [2.419s][info ][gc,phases ] GC(0) Merge Per-Thread State: 0.1ms
      [2.419s][info ][gc,phases ] GC(0) Other: 1.6ms
      [2.419s][info ][gc,heap ] GC(0) Eden regions: 2560->0(2553)
      [2.419s][info ][gc,heap ] GC(0) Survivor regions: 0->7(427)
      ## Yes, objects were copied to the survivors...
      [2.419s][info ][gc,heap ] GC(0) Old regions: 0->0
      [2.419s][info ][gc,heap ] GC(0) Humongous regions: 0->0
      [2.419s][info ][gc,metaspace ] GC(0) Metaspace: 6038K->6038K(1056768K)
      [2.419s][info ][gc ] GC(0) Pause Young (G1 Evacuation Pause) 10240M->26M(12288M) (2.382s, 2.419s) 37.309ms
      [2.419s][info ][gc,cpu ] GC(0) User=0.20s Sys=0.14s Real=0.03s
      [3.248s][info ][gc,start ] GC(1) Pause Young (G1 Evacuation Pause) (3.247s)
      [3.248s][info ][gc,task ] GC(1) GC Workers: using 18 out of 18
      [3.248s][debug][gc,age ] GC(1) Desired survivor size 895483904 bytes, new threshold 6 (max threshold 6)
      [3.248s][trace][gc,age ] GC(1) - age 1: 27243352 bytes, 27243352 total
      ## This is the age table of the previous GC...

      The reason for this seems to be that the age table is printed when the tenuring threshold is calculated from the age table (it should be done on a separate call IMHO), which in G1 is done before a GC.


      Reported by T. Printezis (http://mail.openjdk.java.net/pipermail/hotspot-gc-dev/2016-August/018743.html)

        Attachments

          Activity

            People

            Assignee:
            tschatzl Thomas Schatzl
            Reporter:
            tschatzl Thomas Schatzl
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Dates

              Created:
              Updated:
              Resolved: