JDK-8164018 : "clock going backwards" warning is confusing sun/tools/jstatd tests
  • Type: Bug
  • Component: core-svc
  • Sub-Component: tools
  • Affected Version: 9
  • Priority: P4
  • Status: Closed
  • Resolution: Duplicate
  • OS: windows
  • Submitted: 2016-08-15
  • Updated: 2016-08-19
  • Resolved: 2016-08-17
Related Reports
Duplicate :  
Duplicate :  
Relates :  
Relates :  
Relates :  
Description
A new warning was recently introduced in the GC system by JDK-8071770: 

[4.144s][warning][gc] Detected clock going backwards. Milliseconds since last GC would be -3828. returning zero instead.

This seems to happen frequently when running the sun/tools/jstatd tests on windows machines. The tests are matching output from the JVM and fail when they see this message.

We should investigate why the warning happens, and the tests should be updated to ignore it.


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
I blame a confusing UI. When you click Close and choose "duplicates" and pick an issue, the bug isn't closed as Duplicate, but as Fixed by default.
17-08-2016

Leaving the test alone and fixing the cause seems the better approach here.
17-08-2016

Should be easy to change the tests to ignore lines with [warning][gc] in them.
16-08-2016

JDK-8071770 appears to be broken to me - using a counter as a time value. Can these tests be easily updated to exclude warnings from their parsing logic? Should this not be an integration blocker - though JDK-8071770 may have already escaped the test failures will also appear if executed in PIT/Promotion testing ?
16-08-2016