JDK-8164124 : [BACKOUT] G1 does not implement millis_since_last_gc which is needed by RMI GC
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 9
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2016-08-16
  • Updated: 2020-09-01
  • Resolved: 2016-08-22
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 9
9 b134Fixed
Related Reports
Duplicate :  
JDK-8164018 - "clock going backwards" warning is confusing sun/tools/jstatd tests
Duplicate :  
JDK-8164404 - Backout change for 8071770 which implements millis_since_last_gc()
Relates :  
JDK-8071770 - G1 does not implement millis_since_last_gc which is needed by RMI GC
Relates :  
JDK-8164482 - [REDO] G1 does not implement millis_since_last_gc which is needed by RMI GC
Sub Tasks
JDK-8164329 :  
Problem list sun/rmi/runtime/Log/6409194/NoConsoleOutput.java on windows due to JDK-8164124 - Resolved
JDK-8164589 :  
Remove sun/rmi/runtime/Log/6409194/NoConsoleOutput.java from ProblemList - Resolved
Description
jlong G1CollectedHeap::millis_since_last_gc() {

This: jlong now = os::elapsed_counter() / NANOSECS_PER_MILLISEC;

Should be: jlong now = os::javaTimeNanos() / NANOSECS_PER_MILLISEC;




RULE "sun/tools/jstatd/TestJstatdExternalRegistry.java" Exception java.lang.RuntimeException: No or invalid headline found, expected: [S0 S1 E O M CCS YGC YGCT FGC FGCT GCT]: expected true, was false 
RULE "sun/tools/jstatd/TestJstatdDefaults.java" Exception java.lang.RuntimeException: No or invalid headline found, expected: [S0 S1 E O M CCS YGC YGCT FGC FGCT GCT]: expected true, was false 
RULE "sun/tools/jstatd/TestJstatdPort.java" Exception java.lang.RuntimeException: No or invalid headline found, expected: [S0 S1 E O M CCS YGC YGCT FGC FGCT GCT]: expected true, was false 
RULE "sun/tools/jstatd/TestJstatdPortAndServer.java" Exception java.lang.RuntimeException: No or invalid headline found, expected: [S0 S1 E O M CCS YGC YGCT FGC FGCT GCT]: expected true, was false 
RULE "sun/tools/jstatd/TestJstatdServer.java" Exception java.lang.RuntimeException: No or invalid headline found, expected: [S0 S1 E O M CCS YGC YGCT FGC FGCT GCT]: expected true, was false 

RULE "sun/tools/jstatd/TestJstatdExternalRegistry.java" Exception java.lang.RuntimeException: Invalid number of data columns: [[...][warning][gc], Detected, clock, going, backwards., Milliseconds, since, last, GC, would, be, ..., returning, zero, instead., ..., ..., ..., ..., ..., ..., ..., ..., ..., ..., ...]: expected ... to equal ... 
RULE "sun/tools/jstatd/TestJstatdServer.java" Exception java.lang.RuntimeException: Invalid number of data columns: [[...][warning][gc], Detected, clock, going, backwards., Milliseconds, since, last, GC, would, be, ..., returning, zero, instead., ..., ..., ..., ..., ..., ..., ..., ..., ..., ..., ...]: expected ... to equal ... 
RULE "sun/tools/jstatd/TestJstatdDefaults.java" Exception java.lang.RuntimeException: Invalid number of data columns: [[...][warning][gc], Detected, clock, going, backwards., Milliseconds, since, last, GC, would, be, ..., returning, zero, instead., ..., ..., ..., ..., ..., ..., ..., ..., ..., ..., ...]: expected ... to equal ... 
RULE "sun/tools/jstatd/TestJstatdPort.java" Exception java.lang.RuntimeException: Invalid number of data columns: [[...][warning][gc], Detected, clock, going, backwards., Milliseconds, since, last, GC, would, be, ..., returning, zero, instead., ..., ..., ..., ..., ..., ..., ..., ..., ..., ..., ...]: expected ... to equal ... 
RULE "sun/tools/jstatd/TestJstatdPortAndServer.java" Exception java.lang.RuntimeException: Invalid number of data columns: [[...][warning][gc], Detected, clock, going, backwards., Milliseconds, since, last, GC, would, be, ..., returning, zero, instead., ..., ..., ..., ..., ..., ..., ..., ..., ..., ..., ...]: expected ... to equal ... 

RULE "sun/tools/jstatd/TestJstatdPort.java" Exception java.lang.RuntimeException: Output does not match the pattern [...][warning][gc] Detected clock going backwards. Milliseconds since last GC would be ... returning zero instead. ... Jps: expected true, was false
Comments
Yes Stefan: jlong now = os::elapsed_counter() / NANOSECS_PER_MILLISEC is an incorrect time conversion. The correct form is as above: double now = TimeHelper::counter_to_millis(os::elapsed_counter()); or even just: double now = os::elapsedTime(); However it is important to verify that all timestamps the G1 code interacts with are using the same timing code. Other GC code uses javaTimeNanos() - which is fine in itself but you can't compare timestamps from the two different sources.
18-08-2016
Does this look right now? jlong G1CollectedHeap::millis_since_last_gc() { double now = TimeHelper::counter_to_millis(os::elapsed_counter()); const G1Analytics* analytics = _g1_policy->analytics(); double last = analytics->last_known_gc_end_time_sec(); jlong ret_val = (jlong) (now - (last * 1000)); if (ret_val < 0) {
17-08-2016
Isn't the problem that: os::elapsed_counter() / NANOSECS_PER_MILLISEC; uses NANOSECS_PER_MILLISEC instead of the platform dependent os::elapsed_frequency() ? We use os::elapsed_counter() throughout our GCs. The following helper functions are used to convert into millis: double TimeHelper::counter_to_seconds(jlong counter) { double freq = (double) os::elapsed_frequency(); return counter / freq; } double TimeHelper::counter_to_millis(jlong counter) { return counter_to_seconds(counter) * 1000.0; }
17-08-2016
Need to verify what time source G1 uses throughout. If it always uses elapsed_counter() that would be consistent but the values being reported as milliseconds would not be accurate. It should be using os::javaTimeNanos() or os::elapsed_time()
17-08-2016