TestClock_System.test_OffsetLimits() RuntimeException

[llxia]

jdk_time got excluded as part of the general exclude a while back via #10757.

Grinder
TEST: java/time/test/java/time/TestClock_System.java

00:03:45.036  test test.java.time.TestClock_System.test_ClockResolution(): success
00:03:45.036  *** Testing limits ***
00:03:45.036  test test.java.time.TestClock_System.test_OffsetLimits(): failure
00:03:45.036  java.lang.RuntimeException: System.currentTimeMillis()/1000 - MAX_OFFSET + 1: offset was not offlimit but was recomputed.
00:03:45.036  	at test.java.time.TestClock_System$SystemClockOffset.testWithOffset(TestClock_System.java:339)
00:03:45.036  	at test.java.time.TestClock_System$SystemClockOffset.testWithOffset(TestClock_System.java:305)
00:03:45.036  	at test.java.time.TestClock_System.test_OffsetLimits(TestClock_System.java:399)
00:03:45.036  	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
00:03:45.036  	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
00:03:45.036  	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
00:03:45.036  	at java.base/java.lang.reflect.Method.invoke(Method.java:572)
00:03:45.036  	at org.testng.internal.MethodInvocationHelper.invokeMethod(MethodInvocationHelper.java:132)
00:03:45.036  	at org.testng.internal.TestInvoker.invokeMethod(TestInvoker.java:599)
00:03:45.036  	at org.testng.internal.TestInvoker.invokeTestMethod(TestInvoker.java:174)
00:03:45.036  	at org.testng.internal.MethodRunner.runInSequence(MethodRunner.java:46)
00:03:45.036  	at org.testng.internal.TestInvoker$MethodInvocationAgent.invoke(TestInvoker.java:822)
00:03:45.036  	at org.testng.internal.TestInvoker.invokeTestMethods(TestInvoker.java:147)
00:03:45.036  	at org.testng.internal.TestMethodWorker.invokeTestMethods(TestMethodWorker.java:146)
00:03:45.036  	at org.testng.internal.TestMethodWorker.run(TestMethodWorker.java:128)
00:03:45.036  	at java.base/java.util.ArrayList.forEach(ArrayList.java:1541)
00:03:45.036  	at org.testng.TestRunner.privateRun(TestRunner.java:764)
00:03:45.036  	at org.testng.TestRunner.run(TestRunner.java:585)
00:03:45.036  	at org.testng.SuiteRunner.runTest(SuiteRunner.java:384)
00:03:45.036  	at org.testng.SuiteRunner.runSequentially(SuiteRunner.java:378)
00:03:45.036  	at org.testng.SuiteRunner.privateRun(SuiteRunner.java:337)
00:03:45.036  	at org.testng.SuiteRunner.run(SuiteRunner.java:286)
00:03:45.036  	at org.testng.SuiteRunnerWorker.runSuite(SuiteRunnerWorker.java:53)
00:03:45.036  	at org.testng.SuiteRunnerWorker.run(SuiteRunnerWorker.java:96)
00:03:45.036  	at org.testng.TestNG.runSuitesSequentially(TestNG.java:1218)
00:03:45.036  	at org.testng.TestNG.runSuitesLocally(TestNG.java:1140)
00:03:45.036  	at org.testng.TestNG.runSuites(TestNG.java:1069)
00:03:45.036  	at org.testng.TestNG.run(TestNG.java:1037)
00:03:45.036  	at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:102)
00:03:45.036  	at jdk.internal.reflect.GeneratedMethodAccessor35.invoke(Unknown Source)
00:03:45.036  	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
00:03:45.036  	at java.base/java.lang.reflect.Method.invoke(Method.java:572)
00:03:45.036  	at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:333)
00:03:45.036  	at java.base/java.lang.Thread.run(Thread.java:835)
00:03:45.036  *** Testing regular cases ***
00:03:45.036  Validating adjustment: 457851428
00:03:45.036  Validating adjustment: 1024458329533
00:03:45.036  Validating adjustment: -1023541634247
00:03:45.036  test test.java.time.TestClock_System.test_OffsetRegular(): success
00:03:45.036  test test.java.time.TestClock_System.test_systemUTC("Clock.systemUTC()#1", SystemClock[Z]): success
00:03:45.036  test test.java.time.TestClock_System.test_systemUTC("Clock.systemUTC()#2", SystemClock[Z]): success
00:03:45.036  test test.java.time.TestClock_System.test_systemUTC("Clock.system(ZoneOffset.UTC)#1", SystemClock[Z]): success
00:03:45.036  test test.java.time.TestClock_System.test_systemUTC("Clock.system(ZoneOffset.UTC)#2", SystemClock[Z]): success
00:03:45.036  test test.java.time.TestClock_System.test_toString(): success
00:03:45.036  test test.java.time.TestClock_System.test_withZone_same(): success
00:03:45.036  
00:03:45.036  ===============================================
00:03:45.036  java/time/test/java/time/TestClock_System.java
00:03:45.036  Total tests run: 9, Passes: 8, Failures: 1, Skips: 0
00:03:45.036  ===============================================
00:03:45.036  
00:03:45.036  STDERR:
00:03:45.036  java.lang.Exception: failures: 1
00:03:45.036  	at com.sun.javatest.regtest.agent.TestNGRunner.main(TestNGRunner.java:104)
00:03:45.036  	at jdk.internal.reflect.GeneratedMethodAccessor35.invoke(Unknown Source)
00:03:45.036  	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
00:03:45.036  	at java.base/java.lang.reflect.Method.invoke(Method.java:572)
00:03:45.036  	at com.sun.javatest.regtest.agent.MainActionHelper$AgentVMRunnable.run(MainActionHelper.java:333)
00:03:45.036  	at java.base/java.lang.Thread.run(Thread.java:835)
00:03:45.036  
00:03:45.036  JavaTest Message: Test threw exception: java.lang.Exception
00:03:45.036  JavaTest Message: shutting down test
00:03:45.036  
00:03:45.036  
00:03:45.036  TEST RESULT: Failed. Execution failed: `main' threw exception: java.lang.Exception: failures: 1
00:03:45.036  --------------------------------------------------
00:03:45.036  Test results: passed: 178; failed: 1
00:03:54.042  Report written to /home/jenkins/workspace/Grinder/aqa-tests/TKG/output_17317039363386/jdk_time_0/report/html/report.html
00:03:54.043  Results written to /home/jenkins/workspace/Grinder/aqa-tests/TKG/output_17317039363386/jdk_time_0/work
00:03:54.043  Error: Some tests failed or other problems occurred.
00:03:54.043  -----------------------------------
00:03:54.043  jdk_time_0_FAILED
00:03:54.043  -----------------------------------

[github-actions]

Issue Number: 20610
Status: Open
Recommended Components: comp:test, comp:vm, comp:gc

[pshipton]

@tajila fyi

[tajila]

@JasonFengJ9 Please take a look

[JasonFengJ9]

This test java/time/test/java/time/TestClock_System.java uses the field java.time.Clock$SystemClock.offset value via reflection to check if java.time.Clock.SystemClock.instant() caused offset recomputation when VM.getNanoTimeAdjustment(offsetInSeconds) return -1 that indicates the incoming offset is too far off the current time.

VM.getNanoTimeAdjustment(offsetInSeconds) invokes JVM_GetNanoTimeAdjustment() that returns -1 in a few corner cases.

openj9/runtime/j9vm/java11vmi.c

Lines 1743 to 1751 in 6b6242e

	if ((offsetNanoSeconds >= (currentTimeNano - TIME_LONG_MAX))
	&& (offsetNanoSeconds <= (currentTimeNano - TIME_LONG_MIN))
	) {
	result = currentTimeNano - offsetNanoSeconds;
	}
	}
	}
	return result;

VM.getNanoTimeAdjustment(offsetInSeconds) aims to get a nanosecond time stamp adjustment based on the incoming offsetInSeconds.
However the offsetInSeconds is often retrieved via System.currentTimeMillis() which uses j9time_current_time_millis() - > omrtime_current_time_millis(), JVM_GetNanoTimeAdjustment() uses j9time_current_time_nanos() -> omrtime_current_time_nanos(), and they have different time sources.

OpenJDK community discussed a similar time source issue at Enhance the system clock to nanosecond precision.

Currently trying a change to replace j9time_current_time_millis() with j9time_current_time_nanos()/1_000_000 for System.currentTimeMillis().