JDK-8165849 : Confusing ergonomics log output when the time spent for the young regions exceeds pause time
  • Type: Enhancement
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 9
  • Priority: P4
  • Status: Closed
  • Resolution: Fixed
  • Submitted: 2016-09-12
  • Updated: 2018-12-10
  • Resolved: 2018-12-10
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.
Other
tbd_majorFixed
Related Reports
Relates :  
JDK-8213890 - Implementation of JEP 344: Abortable Mixed Collections for G1
Description
When G1 prints ergonomics output for collection set construction, if the time required for the young gen regions exceeds the total pause time, the next few messages about taking old gen regions anyways is slightly confusing:

Example:

1)  27637.171: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 163660, predicted base time: 52.60 ms, remaining time: 247.40 ms, target pause time: 300.00 ms]
2)  27637.171: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 1454 regions, survivors: 82 regions, predicted young region time: 2834.32 ms]
3)  27637.171: [G1Ergonomics (CSet Construction) finish adding old regions to CSet, reason: predicted time is too high, predicted time: 6.91 ms, remaining time: 0.00 ms, old: 202 regions, min: 202 regions]
4)  27637.171: [G1Ergonomics (CSet Construction) added expensive regions to CSet, reason: old CSet region num not reached min, old: 202 regions, expensive: 202 regions, min: 202 regions, remaining time: 0.00 ms]
5) 27637.171: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 1454 regions, survivors: 82 regions, old: 202 regions,
predicted pause time: 3003.89 ms, target pause time: 300.00 ms]

In log message 3, ergonomics mentions that it finished adding old gen regions, not mentioning whether it actually added anything or not.

Maybe it could say it did not add 202 regions, which is the minimum desired number, or combine messages 3 and 4, so that it does not read "did not add old regions" followed by "added expensive regions".

Also "expensive regions" adds another term that is never explained anywhere.
Comments
This issue was addressed in JEP 344. The new log looks like this: [50,752s][debug][gc,ergo,cset ] GC(18) Start adding old regions for mixed gc. min 3 regions, max 32 regions, time remaining 170,59ms, optional threshold 34,12ms [50,752s][debug][gc,ergo,cset ] GC(18) Finish adding old regions to CSet (predicted time is too high). [50,752s][debug][gc,ergo,cset ] GC(18) Finish choosing CSet regions old: 3, optional: 0, predicted old time: 754,74ms, predicted optional time: 0,00ms, time remaining: 0,00 [50,752s][debug][gc,ergo,cset ] GC(18) CSet contains 3 old regions that were added although the predicted time was too high.
10-12-2018