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