JDK-8205540 : test/hotspot/jtreg/vmTestbase/nsk/jdb/trace/trace001/trace001.java fails with Debuggee did not exit after 15 commands
  • Type: Bug
  • Component: core-svc
  • Sub-Component: debugger
  • Affected Version: 11
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2018-06-22
  • Updated: 2022-07-11
  • Resolved: 2018-06-24
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 11 JDK 12 JDK 8 Other
11 b20Fixed 12Fixed 8u301Fixed na,openjdk8u332Resolved
Related Reports
Duplicate :  
JDK-8205562 - vmTestbase/nsk/stress/strace tests failing with unexpected method name
Relates :  
JDK-8202788 - Explicitly reclaim cached thread-local direct buffers at thread exit
Relates :  
JDK-8202788 - Explicitly reclaim cached thread-local direct buffers at thread exit
Relates :  
JDK-8205562 - vmTestbase/nsk/stress/strace tests failing with unexpected method name
Sub Tasks
JDK-8205561 :  
problem list vmTestbase/nsk/jdb/trace/trace001/trace001.java - Resolved
Description
Extract from the log:

Sending command: cont
reply[0]: > 
reply[1]: Method entered: "thread=Thread-0", jdk.internal.misc.Unsafe.compareAndSetInt(), line=-1 bci=-1
reply[2]: 
reply[3]: Thread-0[1] 
Sending command: cont
reply[0]: > 
reply[1]: Method exited: return value = true, "thread=Thread-0", jdk.internal.misc.Unsafe.compareAndSetInt(), line=-1 bci=-1
reply[2]: 
reply[3]: Thread-0[1] 
Sending command: quit
# ERROR: Caught unexpected exception while executing the test: nsk.share.Failure: Debuggee did not exit after 15 <cont> commands
The following stacktrace is for failure analysis.
nsk.share.TestFailure: Caught unexpected exception while executing the test: nsk.share.Failure: Debuggee did not exit after 15 <cont> commands
	at nsk.share.Log.logExceptionForFailureAnalysis(Log.java:428)
	at nsk.share.Log.complain(Log.java:399)
	at nsk.share.jdb.JdbTest.failure(JdbTest.java:74)
	at nsk.share.jdb.JdbTest.runTest(JdbTest.java:158)
	at nsk.jdb.trace.trace001.trace001.run(trace001.java:81)
	at nsk.jdb.trace.trace001.trace001.main(trace001.java:74)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at PropertyResolvingWrapper.main(PropertyResolvingWrapper.java:104)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:115)
	at java.base/java.lang.Thread.run(Thread.java:834)
nsk.share.Failure: Debuggee did not exit after 15 <cont> commands
	at nsk.share.jdb.Jdb.contToExit(Jdb.java:862)
	at nsk.jdb.trace.trace001.trace001.runCases(trace001.java:117)
	at nsk.share.jdb.JdbTest.runTest(JdbTest.java:149)
	at nsk.jdb.trace.trace001.trace001.run(trace001.java:81)
	at nsk.jdb.trace.trace001.trace001.main(trace001.java:74)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at PropertyResolvingWrapper.main(PropertyResolvingWrapper.java:104)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base/java.lang.reflect.Method.invoke(Method.java:566)
	at com.sun.javatest.regtest.agent.MainWrapper$MainThread.run(MainWrapper.java:115)
	at java.base/java.lang.Thread.run(Thread.java:834)
Waiting for jdb exits
jdb normally exited
Comments
Fix Request (8u) A clean backport for parity with Oracle 8u321.
17-11-2021
8u backport: has dependency on JDK-8202788
09-08-2021
URL: http://hg.openjdk.java.net/jdk/jdk/rev/7348c41ca46d User: plevart Date: 2018-06-24 08:43:12 +0000
24-06-2018
@Peter Yes, I think it would be a good idea to make that change. Although the test is flawed and should not be making assumptions on the number of method calls done during thread exit, I think your fix should still be done. Without it class loading and a clinit are executed on thread exit, and in general that doesn't sound like a good thing to do. The fact that it gets the test working again is just an added bonus. I have tested it and it does seem to be fixing the test. Please CC me on any code review you send out. You can push the fix using this CR.
23-06-2018
@Chris: "I'm not sure why a thread that doesn't use thread locals has to trigger this overhead on thread exit. " This overhead is caused precisely to determine if the exiting thread actually uses thread locals or not. The ThreadLocal.isPresent() method is the following: boolean isPresent() { Thread t = Thread.currentThread(); ThreadLocalMap map = getMap(t); return map != null && map.getEntry(this) != null; } ...if exiting thread doesn't use thread locals, it's 'threadLocals' field will be null and the method will bail-out before map.getEntry(this) is called. But if that is too much (in particular the TerminatingThreadLocal.<clinit> with REGISTRY construction), the following patch in Thread would delay TerminatingThreadLocal.<clinit> until the 1st thread that actually uses thread locals, exits... --- src/java.base/share/classes/java/lang/Thread.java (revision 50737:ada9735476b28afa2e41803817cbdb608576f8c7) +++ src/java.base/share/classes/java/lang/Thread.java (revision 50737+:ada9735476b2+) @@ -840,7 +840,7 @@ * a chance to clean up before it actually exits. */ private void exit() { - if (TerminatingThreadLocal.REGISTRY.isPresent()) { + if (threadLocals != null && TerminatingThreadLocal.REGISTRY.isPresent()) { TerminatingThreadLocal.threadTerminated(); } if (group != null) { Would that help silence the test? If yes, I can quickly prepare the RFR on core-libs-dev and push the change...
23-06-2018
I think this change in Thread.java for JDK-8202788 is the problem: private void exit() { + if (TerminatingThreadLocal.REGISTRY.isPresent()) { + TerminatingThreadLocal.threadTerminated(); + } TerminatingThreadLocal.<clinit> is always triggered because of this. So you probably only get a bunch of extra method calls on the first method exit, but subsequent ones will still get the isPresent() call.
23-06-2018
The end of the test log where the 15 "cont" commands are being done looks like this: ending command: cont reply[0]: > reply[1]: Method entered: "thread=Thread-0", jdk.internal.misc.TerminatingThreadLocal.<clinit>(), line=98 bci=0 reply[2]: reply[3]: Thread-0[1] Sending command: cont reply[0]: > reply[1]: Method entered: "thread=Thread-0", jdk.internal.misc.TerminatingThreadLocal$1.<init>(), line=99 bci=0 reply[2]: reply[3]: Thread-0[1] Sending command: cont reply[0]: > reply[1]: Method entered: "thread=Thread-0", jdk.internal.misc.Unsafe.getAndAddInt(), line=2,337 bci=0 reply[2]: reply[3]: Thread-0[1] Sending command: cont reply[0]: > reply[1]: Method entered: "thread=Thread-0", jdk.internal.misc.Unsafe.getIntVolatile(), line=-1 bci=-1 reply[2]: reply[3]: Thread-0[1] Sending command: cont reply[0]: > reply[1]: Method exited: return value = 1253254570, "thread=Thread-0", jdk.internal.misc.Unsafe.getIntVolatile(), line=-1 bci=-1 reply[2]: reply[3]: Thread-0[1] Sending command: cont reply[0]: > reply[1]: Method entered: "thread=Thread-0", jdk.internal.misc.Unsafe.weakCompareAndSetInt(), line=1,409 bci=0 reply[2]: reply[3]: Thread-0[1] Sending command: cont reply[0]: > reply[1]: Method entered: "thread=Thread-0", jdk.internal.misc.Unsafe.compareAndSetInt(), line=-1 bci=-1 reply[2]: reply[3]: Thread-0[1] Sending command: cont reply[0]: > reply[1]: Method exited: return value = true, "thread=Thread-0", jdk.internal.misc.Unsafe.compareAndSetInt(), line=-1 bci=-1 reply[2]: reply[3]: Thread-0[1] Sending command: quit # ERROR: Caught unexpected exception while executing the test: nsk.share.Failure: Debuggee did not exit after 15 <cont> commands Notice the jdk.internal.misc.TerminatingThreadLocal.<clinit>() reference. One of the changes that is new in jdk-911 is JDK-8202788 "Explicitly reclaim cached thread-local direct buffers at thread exit". My guess is we just have more method calls on thread exit now, so the test needs more "cont" commands before exiting. The test is calling: jdb.contToExit(CHECKED_METHODS.length*threads.length*2 + 3); And it is Jdb.contToExit() which is producing the error message. I think the "+3" is just to allow for some additional methodexit/enter events that normally happen on method exit, but now we have a lot more. We may just need to bump this number, but the test remains fragile in that case. A better solution would be fore the test to issue "cont" commands until it sees all the methodenter/exit events that it expects to see, although looking at the test it's not really setup to work this way. Lastly, maybe JDK-8202788 should be rethought. I'm not sure why a thread that doesn't use thread locals has to trigger this overhead on thread exit.
23-06-2018
These are all -Xcomp runs. I wonder if JDK-8188778 is back and -Xcomp + String Indy is getting us again.
22-06-2018