JDK-8209517 : com/sun/jdi/BreakpointWithFullGC.java fails with timeout
  • Type: Bug
  • Component: core-svc
  • Sub-Component: debugger
  • Affected Version: 12
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2018-08-14
  • Updated: 2020-08-27
  • Resolved: 2018-08-16
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
11.0.10-oracleFixed 12 b08Fixed
Related Reports
Relates :  
JDK-8209109 - [TEST] rewrite com/sun/jdi shell tests to java version - step1
Description
[jdb] main[1] bottom of loop
[jdb] Fatal error:
[jdb] Failed reading output of child java interpreter.
----------System.err:(18/1435)*----------
Java HotSpot(TM) 64-Bit Server VM warning: Option UseConcMarkSweepGC was deprecated in version 9.0 and will likely be removed in a future release.
java.lang.RuntimeException: waitForMsg timed out after 60 seconds, looking for '[a-zA-Z0-9_-][a-zA-Z0-9_-]*\\[[1-9][0-9]*\\] [ >]*$', in 1 lines
	at lib.jdb.Jdb.waitForMsg(Jdb.java:209)
	at lib.jdb.Jdb.command(Jdb.java:235)
	at BreakpointWithFullGC.runCases(BreakpointWithFullGC.java:91)
	at lib.jdb.JdbTest.run(JdbTest.java:51)
	at BreakpointWithFullGC.main(BreakpointWithFullGC.java:68)
	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:127)
	at java.base/java.lang.Thread.run(Thread.java:834)

JavaTest Message: Test threw exception: java.lang.RuntimeException: waitForMsg timed out after 60 seconds, looking for '[a-zA-Z0-9_-][a-zA-Z0-9_-]*\\[[1-9][0-9]*\\] [ >]*$', in 1 lines
Comments
Fix Request (11u) This backport improves testing and matches the codebases better (I see 11.0.10-oracle). Patch applies cleanly to 11u, affected com/sun/jdi tests pass in {fastdebug,release}. This bunch contains a rewrite and a few follow-ups: JDK-8209109, JDK-8209517, JDK-8209605, JDK-8203393.
25-08-2020
This was a regression introduced by JDK-8209109
22-08-2018
Was there a reason why this CR suddenly started to reproduce a lot?
22-08-2018
BTW, I think this bug belongs in core-svc/debugger instead of hotspot/svc. Please move it if you agree...
16-08-2018
The fix has been sent for review: http://cr.openjdk.java.net/~amenkov/sh2java/step1_regression/webrev/
15-08-2018
It's clear how to fix the issue, but the fix is not trivial I hope to send the fix for review today
15-08-2018
Looks like these failures are happening in every JDK12 CI tier3 job set so I'm bumping the priority from P4 -> P3. [~amenkov] - do you have an ETA for a fix or should we go ahead and ProblemList this test to give you time to work on this issue?
15-08-2018
Here's a snippet of the second log file: > cont [jdb] > top of loop [jdb] [19.713s][info][gc] GC(57) Pause Young (Normal) (G1 Evacuation Pause) 5M->5M(17M) 30.208ms [jdb] [19.772s][info][gc] GC(58) Pause Young (Normal) (G1 Evacuation Pause) 8M->8M(17M) 44.388ms [jdb] [19.802s][info][gc] GC(59) Pause Young (Concurrent Start) (G1 Evacuation Pause) 9M->9M(17M) 28.309ms [jdb] [19.802s][info][gc] GC(60) Concurrent Cycle [jdb] [19.826s][info][gc] GC(61) Pause Young (Normal) (G1 Evacuation Pause) 10M->10M(17M) 21.649ms [jdb] [19.883s][info][gc] GC(62) Pause Full (System.gc()) 11M->3M(14M) 22.186ms [jdb] [jdb] Breakpoint hit: "thread=main", BreakpointWithFullGCTarg.main(), line=60 bci=32 [jdb] 60 System.out.println("bottom of loop"); // @1 breakpoint [jdb] [jdb] main[1] [19.888s][info][gc] GC(60) Concurrent Cycle 85.284ms > quit [jdb] > top of loop [jdb] [19.713s][info][gc] GC(57) Pause Young (Normal) (G1 Evacuation Pause) 5M->5M(17M) 30.208ms [jdb] [19.772s][info][gc] GC(58) Pause Young (Normal) (G1 Evacuation Pause) 8M->8M(17M) 44.388ms [jdb] [19.802s][info][gc] GC(59) Pause Young (Concurrent Start) (G1 Evacuation Pause) 9M->9M(17M) 28.309ms [jdb] [19.802s][info][gc] GC(60) Concurrent Cycle [jdb] [19.826s][info][gc] GC(61) Pause Young (Normal) (G1 Evacuation Pause) 10M->10M(17M) 21.649ms [jdb] [19.883s][info][gc] GC(62) Pause Full (System.gc()) 11M->3M(14M) 22.186ms [jdb] [jdb] Breakpoint hit: "thread=main", BreakpointWithFullGCTarg.main(), line=60 bci=32 [jdb] 60 System.out.println("bottom of loop"); // @1 breakpoint [jdb] [jdb] main[1] [19.888s][info][gc] GC(60) Concurrent Cycle 85.284ms [jdb] Fatal error: [jdb] Failed reading output of child java interpreter. ----------System.err:(17/1288)*---------- java.lang.RuntimeException: waitForMsg timed out after 60 seconds, looking for '[a-zA-Z0-9_-][a-zA-Z0-9_-]*\\[[1-9][0-9]*\\] [ >]*$', in 1 lines at lib.jdb.Jdb.waitForMsg(Jdb.java:209) at lib.jdb.Jdb.command(Jdb.java:235) at BreakpointWithFullGC.runCases(BreakpointWithFullGC.java:91) at lib.jdb.JdbTest.run(JdbTest.java:51) at BreakpointWithFullGC.main(BreakpointWithFullGC.java:68) 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:127) at java.base/java.lang.Thread.run(Thread.java:834) JavaTest Message: Test threw exception: java.lang.RuntimeException: waitForMsg timed out after 60 seconds, looking for '[a-zA-Z0-9_-][a-zA-Z0-9_-]*\\[[1-9][0-9]*\\] [ >]*$', in 1 lines JavaTest Message: shutting down test STATUS:Failed.`main' threw exception: java.lang.RuntimeException: waitForMsg timed out after 60 seconds, looking for '[a-zA-Z0-9_-][a-zA-Z0-9_-]*\\[[1-9][0-9]*\\] [ >]*$', in 1 lines ----------rerun:(37/5203)*---------- For this failure instance, I think this is where it went wrong: [jdb] main[1] [19.888s][info][gc] GC(60) Concurrent Cycle 85.284ms > quit The "main[1]" and ">" prompts were separated by a logging line so the expected pattern match failed... For the first log file that Mikael linked to, I think this is where it went wrong: [jdb] main[1] bottom of loop > quit The "main[1]" and ">" prompts are separated by test output: "bottom of loop" so it looks like we have two different ways for this pattern match to fail that showed up in the same CI job set...
14-08-2018