JDK-8215221 : Serial GC misreports young GC time
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 13
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2018-12-11
  • Updated: 2019-07-25
  • Resolved: 2019-03-07
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 13
13 b12Fixed
Related Reports
Relates :  
Sub Tasks
JDK-8226475 :  
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

Comments
There seems to be little interest in backporting this to other releases, and the patch is not very simple apply. Dropping other affected-versions.
22-05-2019

RFR, attempt 2: http://mail.openjdk.java.net/pipermail/hotspot-gc-dev/2019-January/024658.html
24-01-2019

Original report mentioned that only Serial is affected; the reporter tried Serial, Parallel, CMS, G1. Parallel does not seem to have this problem in my tests, while I would expect it to share the code path. Yet, it seems to work just fine: [2.501s][info][gc,start] GC(2) Pause Young (Allocation Failure) [4.447s][info][gc ] GC(2) Pause Young (Allocation Failure) 1720M->1543M(2552M) 1945.671ms [4.650s][info][gc,start] GC(3) Pause Full (Ergonomics) [24.150s][info][gc ] GC(3) Pause Full (Ergonomics) 1543M->1304M(4911M) 19500.083ms
12-12-2018

Is this problem specific to Serial, or do other collectors have the same problem?
12-12-2018

RFR: http://mail.openjdk.java.net/pipermail/hotspot-gc-dev/2018-December/024293.html
11-12-2018