JDK-7178361 : G1: Make sure that PrintGC and PrintGCDetails use the same timing for the GC pause
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: hs24
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • OS: generic
  • CPU: generic
  • Submitted: 2012-06-20
  • Updated: 2013-09-18
  • Resolved: 2012-07-24
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 7 JDK 8 Other
7u40Fixed 8Fixed hs24Fixed
Description
-XX:+PrintGC and -XX:+PrintGCDetails use different timers to track the G1 collection pauses.

It turns out that the timing used by -XX:+PrintGCDetails only covers part of the pause.

Running SPECjbb2005 I got GC pause logging like this:

PrintGCDetails:           13 ms
PrtinGC:                  57 ms
PrintSafepointStatistics: 61 ms 

The PrintSafepointStatistics is as close to the actual pause as we can get. PrintGC does not cover the whole pause but is fairly close. PrintGCDetails is missing a large part of the pause.

To analyze G1 performance we normally run with PrintGCDetails, so it is important that this information is correct.

Comments
EVALUATION http://hg.openjdk.java.net/hsx/hotspot-emb/hotspot/rev/922993931b3d
24-07-2012

EVALUATION http://hg.openjdk.java.net/hsx/hotspot-gc/hotspot/rev/922993931b3d
12-07-2012