JDK-8210220 : [AOT] jdwp test cases are failing with error # ERROR: TEST FAILED: Cought IOException while receiving event packet: # ERROR: java.net.SocketTimeoutException: Read timed out
Type:Bug
Component:hotspot
Sub-Component:compiler
Affected Version:10,11,12
Priority:P3
Status:Resolved
Resolution:Fixed
Submitted:2018-08-30
Updated:2019-12-03
Resolved:2018-09-13
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.
All listed tests passed with next fix:
diff -r 1ddf9a99e4ad src/hotspot/share/aot/aotCodeHeap.cpp
--- a/src/hotspot/share/aot/aotCodeHeap.cpp
+++ b/src/hotspot/share/aot/aotCodeHeap.cpp
@@ -298,7 +298,10 @@
void AOTCodeHeap::publish_aot(const methodHandle& mh, AOTMethodData* method_data, int code_id) {
// The method may be explicitly excluded by the user.
// Or Interpreter uses an intrinsic for this method.
- if (CompilerOracle::should_exclude(mh) || !AbstractInterpreter::can_be_compiled(mh)) {
+ // Or method has breakpoints.
+ if (CompilerOracle::should_exclude(mh) ||
+ !AbstractInterpreter::can_be_compiled(mh) ||
+ (mh->number_of_breakpoints() > 0)) {
return;
}
12-09-2018
The issue is that we load AOT klasses and their methods only during klass initialization - just before it calls <clinit>.
It seems it is allowed to set breakpoint before that - klass needs to be loaded only.
The solution is to check method()->number_of_breakpoints() before registering AOT method for it.
12-09-2018
Test class indeed is loaded before breakpoint:
[0.639s][info ][class,load ] javasoft.sqe.tests.vm.jdwp.ObjectReference.InvokeMethod.invokemeth001a$TestedObjectClass source: file:/export/kvn/jck_bugs/8210220/JCK-runtime-11/classes/
=== called flush_dependents_on_method() ===
javasoft.sqe.tests.vm.jdwp.ObjectReference.InvokeMethod.invokemeth001a$TestedObjectClass::run
12-09-2018
We do deoptimize registerd (active) aot methods on the moment breakpoint is set. But for some reasons test class TestedObjectClass and its aot methods are loaded after that:
[0.603s][trace][aot,class,load] found javasoft.sqe.tests.vm.jdwp.ObjectReference.InvokeMethod.invokemeth001a in solibs/libjcktestvm3.so for classloader 0x7febec64d840 tid=0x00007febec01d000
603 1 aot[ 1] javasoft.sqe.tests.vm.jdwp.ObjectReference.InvokeMethod.invokemeth001a.<init>()V
603 2 aot[ 1] javasoft.sqe.tests.vm.jdwp.ObjectReference.InvokeMethod.invokemeth001a.runIt([Ljava/lang/String;Ljava/io/PrintStream;)I
603 3 aot[ 1] javasoft.sqe.tests.vm.jdwp.ObjectReference.InvokeMethod.invokemeth001a.<clinit>()V
603 4 aot[ 1] javasoft.sqe.tests.vm.jdwp.ObjectReference.InvokeMethod.invokemeth001a.main([Ljava/lang/String;)V
=== called flush_dependents_on_method() ===
=== found aot methods for deoptimization ===
646 1 aot[ 1] javasoft.sqe.tests.vm.jdwp.ObjectReference.InvokeMethod.invokemeth001a.<init>()V made not entrant
646 2 aot[ 1] javasoft.sqe.tests.vm.jdwp.ObjectReference.InvokeMethod.invokemeth001a.runIt([Ljava/lang/String;Ljava/io/PrintStream;)I made not entrant
646 3 aot[ 1] javasoft.sqe.tests.vm.jdwp.ObjectReference.InvokeMethod.invokemeth001a.<clinit>()V made not entrant
646 4 aot[ 1] javasoft.sqe.tests.vm.jdwp.ObjectReference.InvokeMethod.invokemeth001a.main([Ljava/lang/String;)V made not entrant
=== exit flush_dependents_on_method() ===
[0.647s][trace][aot,class,load] found javasoft.sqe.tests.vm.jdwp.ObjectReference.InvokeMethod.invokemeth001a$TestedObjectClass in solibs/libjcktestvm3.so for classloader 0x7febec64d840 tid=0x00007febec01d000
647 5 aot[ 1] javasoft.sqe.tests.vm.jdwp.ObjectReference.InvokeMethod.invokemeth001a$TestedObjectClass.<init>()V
647 6 aot[ 1] javasoft.sqe.tests.vm.jdwp.ObjectReference.InvokeMethod.invokemeth001a$TestedObjectClass.pubm(I)I
647 7 aot[ 1] javasoft.sqe.tests.vm.jdwp.ObjectReference.InvokeMethod.invokemeth001a$TestedObjectClass.privm(I)I
647 8 aot[ 1] javasoft.sqe.tests.vm.jdwp.ObjectReference.InvokeMethod.invokemeth001a$TestedObjectClass.protm(I)I
647 9 aot[ 1] javasoft.sqe.tests.vm.jdwp.ObjectReference.InvokeMethod.invokemeth001a$TestedObjectClass.run()V
647 10 aot[ 1] javasoft.sqe.tests.vm.jdwp.ObjectReference.InvokeMethod.invokemeth001a$TestedObjectClass.m(I)I
12-09-2018
For some reasons we don't deoptimize aot methods when debugger sets break point in java methods.
12-09-2018
Looks like vm/jdwp/Method/IsObsolete/isobsolete002/ crash is covered by JDK-8210256.
I will concentrate on hang in vm/jdwp/ClassType/NewInstance/newinst001 test.
11-09-2018
Main thread is waiting:
"main" #1 prio=5 os_prio=0 cpu=570.15ms elapsed=723.45s allocated=2141K defined_classes=1067 tid=0x00007f2ba801c800 nid=0x4d726 in Object.wait() [0x00007f2bb18ba000]
java.lang.Thread.State: TIMED_WAITING (on object monitor)
JavaThread state: _thread_blocked
Thread: 0x00007f2ba801c800 [0x4d726] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
JavaThread state: _thread_blocked
at java.lang.Object.wait(java.base@11-internal/Native Method)
- waiting on <0x0000000457b844d8> (a java.util.Vector)
at javasoft.sqe.jck.lib.jpda.common.MsgSwitchIOPipe.readHandledMsg(MsgSwitchIOPipe.java:86)
- waiting to re-lock in wait() <0x0000000457b844d8> (a java.util.Vector)
at javasoft.sqe.jck.lib.jpda.common.MsgSwitchIOPipe.readln(MsgSwitchIOPipe.java:76)
at javasoft.sqe.jck.lib.jpda.common.DebugeeArgumentHandler.waitForDebuggerPrepared(DebugeeArgumentHandler.java:425)
at javasoft.sqe.jck.lib.jpda.jdwp.DebuggeeLoader.createDebuggeeInstance(DebuggeeLoader.java:72)
at javasoft.sqe.jck.lib.jpda.jdwp.DebuggeeLoader.run(DebuggeeLoader.java:30)
at javasoft.sqe.jck.lib.jpda.jdwp.DebuggeeLoader.main(DebuggeeLoader.java:19)
11-09-2018
I only next thead (with 'jstack') which run:
"MessageClient" #28 prio=5 os_prio=0 cpu=1.33ms elapsed=509.96s allocated=392B defined_classes=0 tid=0x00007f2ba8794000 nid=0x4d73d runnable [0x00007f2b4107a000]
java.lang.Thread.State: RUNNABLE
JavaThread state: _thread_in_native
Thread: 0x00007f2ba8794000 [0x4d73d] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
JavaThread state: _thread_in_native
at java.net.SocketInputStream.socketRead0(java.base@11-internal/Native Method)
at java.net.SocketInputStream.socketRead(java.base@11-internal/SocketInputStream.java:115)
at java.net.SocketInputStream.read(java.base@11-internal/SocketInputStream.java:168)
at java.net.SocketInputStream.read(java.base@11-internal/SocketInputStream.java:140)
at java.io.BufferedInputStream.fill(java.base@11-internal/BufferedInputStream.java:252)
at java.io.BufferedInputStream.read(java.base@11-internal/BufferedInputStream.java:271)
- locked <0x000000045751dcd8> (a java.io.BufferedInputStream)
at java.io.DataInputStream.readByte(java.base@11-internal/DataInputStream.java:270)
at com.sun.jck.lib.MessageClient.run(MessageClient.java:114)
at java.lang.Thread.run(java.base@11-internal/Thread.java:834)
11-09-2018
I tried to reproduce it and only next 2 tests were run:
Passed: vm/jdwp/Method/IsObsolete/isobsolete002/isobsolete002.html
Passed: vm/jdwp/ClassType/NewInstance/newinst001/newinst001.html
They passed with one java.base AOT library (rameshbase.so).
Tests failed with additional libjcktestvm3.so AOT lib:
Test Method.IsObsolete.isobsolete002a crashed in AOT compiled method:
A 6 javasoft.sqe.tests.vm.jdwp.Method.IsObsolete.isobsolete002b.testedMethod(I)V (11 bytes) @ 0x00007f88ddd19914 [0x00007f88ddd198a0+0x0000000000000074]
j javasoft.sqe.tests.vm.jdwp.Method.IsObsolete.isobsolete002a.runIt([Ljava/lang/String;Ljava/io/PrintStream;)I+53
j javasoft.sqe.jck.lib.jpda.jdwp.DebuggeeTest.run([Ljava/lang/String;Ljava/io/PrintStream;)I+67
And ClassType.NewInstance.newinst001a hangs and I am still do not know where.
11-09-2018
Okay, thanks for verification.
Vladimir, I'm assigning this to you. Please take a look or re-assign. Thanks!
31-08-2018
Hi Tobias,
I have cross verified by re-running tests, there were no hs_err files.
VM is still running
root 130990 130869 4 15:55 pts/3 00:00:00 /scratch/export/home/aginfra/Desktop/ramesh/jdk-11/bin/java -XX:+UnlockDiagnosticVMOptions -XX:+UseAOTStrictLoading -XX:AOTLibrary=solibs/rameshbase.so,solibs/libjcktestvm3.so -XX:+PrintAOT --add-modules=java.base,java.datatransfer,java.instrument,java.logging,java.management,java.management.rmi,java.naming,java.prefs,java.rmi,java.scripting,java.se,java.security.jgss,java.security.sasl,java.xml,java.xml.crypto --add-exports=java.xml.crypto/org.jcp.xml.dsig.internal.dom=ALL-UNNAMED -Djdk.attach.allowAttachSelf=true -Xfuture -agentlib:jdwp=server=y,transport=dt_socket,address=llg00fyn.uk.oracle.com:54600,suspend=n -classpath /scratch/export/home/aginfra/Desktop/ramesh/JCK-runtime-11/classes::/scratch/export/home/aginfra/Desktop/ramesh/JCK-runtime-11/lib/extensions/JCK-extensions.jar:/scratch/export/home/aginfra/Desktop/ramesh/JCK-runtime-11/lib/extensions/JCK-extensions.jar -Djava.security.policy=/scratch/export/home/aginfra/Desktop/ramesh/JCK-runtime-11/lib/jck.policy javasoft.sqe.jck.lib.jpda.jdwp.DebuggeeLoader -waittime=1200 -msgSwitch=llg00fyn:26355 -componentName=ClassType.InvokeMethod.invokemeth001 -debuggeeName=ClassType.InvokeMethod.invokemeth001a
root 130902 130869 6 15:55 pts/3 00:00:01 /scratch/export/home/aginfra/Desktop/ramesh/jdk-11/bin/java -Xss1m -Xms32m -Xmx512m -cp /scratch/export/home/aginfra/Desktop/ramesh/JCK-runtime-11/lib/javatest.jar:/scratch/export/home/aginfra/Desktop/ramesh/JCK-runtime-11/classes:/scratch/export/home/aginfra/Desktop/ramesh/JCK-runtime-11/lib/jtjck.jar:/scratch/export/home/aginfra/Desktop/ramesh/JCK-runtime-11/lib/extensions/JCK-extensions.jar -Djava.security.policy=/scratch/export/home/aginfra/Desktop/ramesh/JCK-runtime-11/lib/jck.policy -Djavatest.security.allowPropertiesAccess=true com.sun.javatest.agent.AgentMain -passivePort 17295
[root@llg00fyn ramesh]# netstat | grep 54600
tcp 0 0 llg00fyn.uk.oracl:54600 llg00fyn.uk.oracl:62338 ESTABLISHED
tcp6 0 0 llg00fyn.uk.oracl:62338 llg00fyn.uk.oracl:54600 ESTABLISHED
Also i can see log info
DEBUGEE PASSED.
30-08-2018
Okay, thanks. Have you checked if the debuggee VM is still running (maybe there is even an hs_err file)? Maybe it crashed and that's why the debugger VM times out.
30-08-2018
Ramesh, could you please provide more information? Is the exception thrown because there is really a timeout (execution with AOT code is slower?) or is there another root cause hiding behind that exception (debuggee VM crashed)?
Pre-ILW = Incorrect execution (exception thrown), with AOT compiled code, don't use AOT = HLM = P3