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

Serial GC misreports young GC time

    Details

    • Subcomponent:
      gc
    • Resolved In Build:
      b12

      Description

      Running a simple workload with Serial GC, and waiting it to enter Full GC:

      import java.util.*;

      public class AL {
          static List<Object> l;
          public static void main(String... args) throws Throwable {
              l = new ArrayList<>();
              for (int c = 0; c < 100_000_000; c++) {
                  l.add(new Object());
              }
              System.out.println(l.hashCode());
      System.in.read();
          }
      }

      $ ~/trunks/jdk-jdk/build/linux-x86_64-server-fastdebug/images/jdk/bin/java -XX:+UseSerialGC -Xlog:gc -Xlog:gc+start AL

      Current jdk/jdk prints:

      [12.597s][info][gc,start] GC(3) Pause Young (Allocation Failure)
      [15.954s][info][gc,start] GC(4) Pause Full (Allocation Failure)
      [28.502s][info][gc ] GC(4) Pause Full (Allocation Failure) 1594M->1337M(2130M) 12547.759ms
      [28.846s][info][gc ] GC(3) Pause Young (Allocation Failure) 1596M->1337M(3232M) 16249.227ms

      There are two problems:
       a) GC #3 appears "after" GC #4. "gc+start" does show it started in the correct order, but not everyone has that enabled;
       b) Full GC times are counted twice: "young" appears to take 16 seconds, and "full" takes 12 seconds. In reality, "young" finished before "full" started, so it took only ~3 seconds.

      The cause is that Full GC collection happens while we are still in Young GC scope. This proof-of-concept patch fixes it:
       http://cr.openjdk.java.net/~shade/8215221/webrev.01/

      ...and logs appears good:

      [13.057s][info][gc,start] GC(3) Pause Young (Allocation Failure)
      [16.488s][info][gc ] GC(3) Pause Young (Allocation Failure) 1596M->1594M(2130M) 3430.895ms
      [16.488s][info][gc,start] GC(4) Pause Full (Allocation Failure)
      [29.007s][info][gc ] GC(4) Pause Full (Allocation Failure) 1594M->1337M(2130M) 12519.642ms

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                shade Aleksey Shipilev
                Reporter:
                shade Aleksey Shipilev
              • Votes:
                0 Vote for this issue
                Watchers:
                3 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: