JDK-8151887 : com/sun/jdi/RedefineClearBreakpoint.sh failed with timeout
Type:Bug
Component:hotspot
Sub-Component:svc
Affected Version:9
Priority:P4
Status:Resolved
Resolution:Fixed
Submitted:2016-03-03
Updated:2016-05-23
Resolved:2016-03-22
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.
com/sun/jdi/RedefineClearBreakpoint.sh failing on Mac x64 and Sparc in nightly testing due to timeout.
Comments
I hit that problem while debugging an app with string concat running on fastdebug binaries.
It takes very long to step over a non-bound string concat. The problem I think is that IDE steps through all the code involved in string concat binding and j.l.i initialization and it's not fast enough in fastdebug build.
21-03-2016
Not seeing any difference with that flag on this test.
-XX:-ZapVMHandleArea has been found to reduce the time further (~2 seconds), but it's probably default in fastdebug builds for good reason.
17-03-2016
How does the test behave w/ -XX:-VerifyMethodHandles?
Heavy users of MethodHandles experience very serious performance hit from MH verification logic (which is turned on in fastdebug by default).
17-03-2016
I gave my patch to JDK-8152074[1] a spin with this test on fastdebug builds and see a substantial improvement:
Before:
real 0m48.739s
user 1m9.036s
sys 0m5.180s
After:
real 0m37.109s
user 0m55.216s
sys 0m5.168s
I wouldn't know if this is enough to keep the test from timing out, so leaving this bug untouched.
[1] http://mail.openjdk.java.net/pipermail/core-libs-dev/2016-March/039519.html
17-03-2016
Looking at the profile above, I wonder if the first init that calls into lots of java.lang.invoke/ISC Java code gets treated much longer in under debugger "step"? This simple trick of initializing that infra before we stepped into breakpoint, improves fastdebug performance 38 -> 21 seconds for me (2 seconds larger than a product build):
diff -r 92aaccaffea7 test/com/sun/jdi/RedefineClearBreakpoint.sh
--- a/test/com/sun/jdi/RedefineClearBreakpoint.sh Thu Mar 10 14:20:59 2016 -0500
+++ b/test/com/sun/jdi/RedefineClearBreakpoint.sh Wed Mar 16 18:05:06 2016 +0300
@@ -49,9 +49,12 @@
a=m(a);
}
+
+ String label = "$1";
public int m(int b){
int bb=89;
- System.out.println("$1 - constructor" + b); //@1 breakpoint
+ String method = label + " - constructor";
+ System.out.println(method + b); //@1 breakpoint
return b*b;
}
Even though we do another linkage at the same place under breakpoint, j.l.invoke is already initialized there.
16-03-2016
Playing with the timeout values I can get stack traces that are in other places than StringLatin1.charAt, so I think we are just (un)lucky to always see that one at the top of the stack - it's fairly common code...
16-03-2016
> But, it baffles me why the debugee was blocked at StringLatin1.charAt, choking the progress.
Yes, this is very strange - if things take a lot of time with ISC why would we always be hanging there when we timeout?
16-03-2016
For example, running com/sun/jdi/RedefineClearBreakpoint.sh with hs-rt product bits: 19 seconds.
Running with hs-rt fastdebug bits: 38 seconds, and we spend time at:
http://cr.openjdk.java.net/~shade/8151887/fastdebug-profile.txt
16-03-2016
Of course startup is important, that is why we have JDK-8086045, you can put your comments there. We know that java.lang.invoke right now initializes in around 50-100 ms in product builds. I wonder if we see what we see here is because the java.lang.invoke is even slower under fastdebug/jdb.
16-03-2016
I'd be more than happy to make that argument! Is startup cost suddenly not an issue for anyone? What is the impact for a product build? What happens in fastdebug that makes this so much worse?
16-03-2016
Linkage costs in java.lang.invoke infra are known to be high, especially in fastdebug builds. You can definitely argue your case in front of java.lang.invoke infra guys, and all the users of that infrastructure, including ISC, Lambdas, plus all the dynamic languages implementors on JVM. Or, we can be pragmatic, tweak up the test, and move on. The easiest way is to compile the test with -XDstringConcat=inline.
16-03-2016
If this kind of extreme slowdown "seems inevitable" then I would argue that the feature was not ready for integration!
16-03-2016
Most of these tests aren't testing string concatenation, that just something they need to do for logging - so replacing it with a lambda isn't possible.
16-03-2016
Yes, the initial linkage is known to be slow (*especially* in fastdebug builds), as it requires a lot of juggling in JDK/VM code; that seems inevitable, although we are looking into improving the initialization costs. BTW, this highlights another way to dissect the issue: replace String concat with lambda in the test, and it would probably fail in the similar way.
16-03-2016
I have been looking at a simliar failure over in JDK-7153107: com/sun/jdi/InterruptHangTest.java hits a timeout intermittently. Here is copy of some of my findings:
"
This started happening after the Indify String Concat (ISC) integration (JEP 280). The debuggee appears to be hung (from the debuggers point of view) while executing a string concatenation operation. The debugger signals the debuggee as hung if no step events are received for 20 seconds. It could be that with ISC things are just slower and so we hit this timeout more often and increasing the timeout would allow the test to pass.
Instrumenting the test case shows that stepping over the first string concatenation operation takes ~18 *seconds* on my laptop (as measured from the debugger). When compiled without ISC (-XDstringConcat=inline) the same operation takes ~10 *milliseconds*. These are both with a fastdebug version of the JVM.
"
16-03-2016
Not sure why it is assigned to me. FTR, I wasn't able to cleanly reproduce it on my Linux dev environment: the basic test runs in 19 seconds, adding a 1 second delay in generateConcreteBMHClass balloons the time to 34 seconds, and with 10 second delay it timeouts. But, I think this is a clear timeout: there is simply not enough time to link up all the callsites.
The observed test failure in this bug does not look a ISC (Indify String Concat) failure. It might be triggered by it, sure: the debugee stack dump shows we are blocked down from the initial linkage of invokedynamic coming from a string concatenation (note that it seems a very first init for ISC infra, as we are at StringConcatFactory::<clinit> and resolving some known MethodHandes to proceed). But, it baffles me why the debugee was blocked at StringLatin1.charAt, choking the progress.
JavaThread state: _thread_blocked
at java.lang.StringLatin1.charAt(StringLatin1.java:47)
at java.lang.String.charAt(String.java:686)
at jdk.internal.org.objectweb.asm.ByteVector.putUTF8(ByteVector.java:258)
...
at java.lang.invoke.StringConcatFactory.<clinit>(StringConcatFactory.java:193)
at jdk.internal.misc.Unsafe.ensureClassInitialized(Native Method)
...
at java.lang.invoke.MethodHandles$Lookup.linkMethodHandleConstant(MethodHandles.java:1817)
at java.lang.invoke.MethodHandleNatives.linkMethodHandleConstant(MethodHandleNatives.java:415)
at shtest.m(shtest.java:11)
I think that should be the actual question, and this seems to fall back to runtime issues. Dropping the assignment.
16-03-2016
Part of stack trace:
shtest.java:11
System.out.println("shtest - constructor" + b); //@1 breakpoint
StringConcatFactory.java:193
AccessController.doPrivileged((PrivilegedAction<Object>) () -> {
values[0] = System.getProperty("java.lang.invoke.stringConcat");
values[1] = Boolean.getBoolean("java.lang.invoke.stringConcat.cache");
values[2] = Boolean.getBoolean("java.lang.invoke.stringConcat.debug");
values[3] = System.getProperty("java.lang.invoke.stringConcat.dumpClasses");
return null;
});
BoundMethodHandle.java:694
mv.visitMethodInsn(INVOKEVIRTUAL, MH, "invokeBasic", makeSignature(types + btChar, false), false);
The problem could be irregularly reproduced if we insert a delay to generateConcreteBMHClass.
If we remove string concatenation from the test, we never come to stacktrace above so I think it's JEP 280 related issue.
15-03-2016
Copy stacktrace from the duplicate CR, just for a record
"main" #1 prio=5 os_prio=64 tid=0x00000001001d0000 nid=0x2 runnable [0xffffffff7d2f9000]
java.lang.Thread.State: RUNNABLE
JavaThread state: _thread_blocked
Thread: 0x00000001001d0000 [0x 2] State: _call_back _has_called_back 1 _at_poll_safepoint 0
JavaThread state: _thread_blocked
at java.lang.StringLatin1.charAt(StringLatin1.java:47)
at java.lang.String.charAt(String.java:686)
at jdk.internal.org.objectweb.asm.ByteVector.putUTF8(ByteVector.java:258)
at jdk.internal.org.objectweb.asm.ClassWriter.newUTF8(ClassWriter.java:1121)
at jdk.internal.org.objectweb.asm.ClassWriter.newNameTypeItem(ClassWriter.java:1591)
at jdk.internal.org.objectweb.asm.ClassWriter.newNameType(ClassWriter.java:1574)
at jdk.internal.org.objectweb.asm.ClassWriter.newMethodItem(ClassWriter.java:1436)
at jdk.internal.org.objectweb.asm.MethodWriter.visitMethodInsn(MethodWriter.java:917)
at java.lang.invoke.BoundMethodHandle$Factory.generateConcreteBMHClass(BoundMethodHandle.java:694)
at java.lang.invoke.BoundMethodHandle$Factory$1.apply(BoundMethodHandle.java:492)
at java.lang.invoke.BoundMethodHandle$Factory$1.apply(BoundMethodHandle.java:489)
at java.util.concurrent.ConcurrentHashMap.computeIfAbsent(ConcurrentHashMap.java:1711)
- locked <0x00000007517f0bb0> (a java.util.concurrent.ConcurrentHashMap$ReservationNode)
at java.lang.invoke.BoundMethodHandle$Factory.getConcreteBMHClass(BoundMethodHandle.java:488)
at java.lang.invoke.BoundMethodHandle$SpeciesData$1.apply(BoundMethodHandle.java:386)
at java.lang.invoke.BoundMethodHandle$SpeciesData$1.apply(BoundMethodHandle.java:383)
at java.util.concurrent.ConcurrentHashMap.computeIfAbsent(ConcurrentHashMap.java:1739)
- locked <0x0000000751765bb8> (a java.util.concurrent.ConcurrentHashMap$Node)
at java.lang.invoke.BoundMethodHandle$SpeciesData.get(BoundMethodHandle.java:383)
at java.lang.invoke.BoundMethodHandle$SpeciesData.extendWith(BoundMethodHandle.java:378)
at java.lang.invoke.LambdaFormEditor.newSpeciesData(LambdaFormEditor.java:396)
at java.lang.invoke.LambdaFormEditor.bindArgumentForm(LambdaFormEditor.java:459)
at java.lang.invoke.LambdaFormEditor.bindArgumentL(LambdaFormEditor.java:403)
at java.lang.invoke.BoundMethodHandle.bindArgumentL(BoundMethodHandle.java:99)
at java.lang.invoke.MethodHandle.bindArgumentL(MethodHandle.java:1421)
at java.lang.invoke.MethodHandle.bindTo(MethodHandle.java:1381)
at java.lang.invoke.MethodHandleImpl.makePairwiseConvertByEditor(MethodHandleImpl.java:218)
at java.lang.invoke.MethodHandleImpl.makePairwiseConvert(MethodHandleImpl.java:191)
at java.lang.invoke.MethodHandleImpl.makePairwiseConvert(MethodHandleImpl.java:358)
at java.lang.invoke.MethodHandle.asTypeUncached(MethodHandle.java:781)
at java.lang.invoke.MethodHandle.asType(MethodHandle.java:766)
at java.lang.invoke.Invokers.checkGenericType(Invokers.java:321)
at java.lang.invoke.LambdaForm$MH/248609774.invoke_MT(LambdaForm$MH)
at java.lang.invoke.CallSite.makeSite(CallSite.java:308)
at java.lang.invoke.MethodHandleNatives.linkCallSiteImpl(MethodHandleNatives.java:245)
at java.lang.invoke.MethodHandleNatives.linkCallSite(MethodHandleNatives.java:235)
at java.lang.invoke.StringConcatFactory.<clinit>(StringConcatFactory.java:193)
at jdk.internal.misc.Unsafe.ensureClassInitialized(Native Method)
at java.lang.invoke.DirectMethodHandle.shouldBeInitialized(DirectMethodHandle.java:306)
at java.lang.invoke.DirectMethodHandle.preparedLambdaForm(DirectMethodHandle.java:170)
at java.lang.invoke.DirectMethodHandle.make(DirectMethodHandle.java:88)
at java.lang.invoke.MethodHandles$Lookup.getDirectMethodCommon(MethodHandles.java:1726)
at java.lang.invoke.MethodHandles$Lookup.getDirectMethodNoSecurityManager(MethodHandles.java:1683)
at java.lang.invoke.MethodHandles$Lookup.getDirectMethodForConstant(MethodHandles.java:1868)
at java.lang.invoke.MethodHandles$Lookup.linkMethodHandleConstant(MethodHandles.java:1817)
at java.lang.invoke.MethodHandleNatives.linkMethodHandleConstant(MethodHandleNatives.java:415)
at shtest.m(shtest.java:11)
at shtest.<init>(shtest.java:6)
at shtest.main(shtest.java:16)
15-03-2016
What does the $1 get replaced with in the failing case?
It is hard to see how we make this transition:
at java.lang.invoke.MethodHandleNatives.linkMethodHandleConstant(MethodHandleNatives.java:415)
at shtest.m(shtest.java:11)
07-03-2016
$1 get replaced to shtest on writing. May be something goes wrong with this replacement. Stack trace comes from an aurora. See attachment.
07-03-2016
There are no lambda's in that code so how do we get that stacktrace? That said $1 is not a valid class name, so maybe it is confusing the lambda related code ??
07-03-2016
shtest.java is generated from within shell scripts:
public class $1 {
public $1() {
int a=23;
a=m(a);
}
public int m(int b){
int bb=89;
System.out.println("$1 - constructor" + b); //@1 breakpoint
return b*b;
}
public static void main(java.lang.String[] args) {
new $1();
int jj = 0; //@1 delete
}
}
I'm not able to reproduce it and didn't find anything indicating a *hotspot* bug. So I think it's a communication problem - both sides (jdb and debugee) is waiting for commands, everything else is blocked.
But it's not clear to me why all similar issues has exactly the same stacktrace (see JDK-8151211) containing ASM. So I leave one in my queue for further investigation.
07-03-2016
Has anyone been able to reproduce this? I'm unclear why this has been filed as a INTJDK issue.
I would suspect a method-handles initalization issue - perhaps combined with compact string changes.
Where does one find shtest.java?
07-03-2016
Relevant part of the log:
** Failure reason:
--DEBUG: jdb 68847 didn't responded to command in 30 secs: next
--Fail: jdb never responded to command: next
** jdb process is waiting for data to arrive either on socket or on TTY, all other threads are blocked.
** the only not-blocked thread of debugee is:
"JDWP Command Reader" #8 daemon prio=10 os_prio=31 tid=0x00007fd1b48f8000 nid=0x6603 runnable [0x0000000000000000]
java.lang.Thread.State: RUNNABLE
JavaThread state: _thread_in_native
Thread: 0x00007fd1b48f8000 [0x6603] State: _at_safepoint _has_called_back 0 _at_poll_safepoint 0
JavaThread state: _thread_in_native
** Conclusion: jdb lost communication channel with debugee and didn't send "next" command. Looks like an environment failure.
04-03-2016
I have removed the testbug tag. My intention of adding the tag was to analyze the testcase for any issues.
04-03-2016
Why is this bug tagged with 'testbug'? I see no comments here that
explain why this is a testbug.
04-03-2016
ILW = M (timeout) L (intermittent) H(no workaround) = P4
04-03-2016
No. Do not be fooled by this error message:
ERROR: native.files cannot be created : can't set 'app', because properties don't have 'native.files.app'.
jdk.test.jtreg.handler.value.InvalidValueException: can't set 'app', because properties don't have 'native.files.app'.
The observer stuff happens _after_ the failure has occurred.
JDK-8147452 Lacking native.files.app causes tests to fail with native.files cannot be created
is about the observer failure messages. And these messages DO NOT
cause the tests to fail. JDK-8147452 should not have been closed as
a duplicate JDK-8079218.
JDK-8079218 java/lang/Throwable/LocalizedMessage.java failed with interrupted
is about javac being interrupted during compilation. JDK-8079218 has _nothing_
to do with the observer failures and this bug (JDK-8151201) IS NOT a duplicate
of JDK-8079218. For this test failure, javac worked just fine.
This is weird... Here's the debuggee's main thread stack for the MacOS X failure:
"main" #1 prio=5 os_prio=31 tid=0x00007fd1b480b800 nid=0x1603 runnable [0x000000010a9f5000]
java.lang.Thread.State: RUNNABLE
JavaThread state: _thread_blocked
Thread: 0x00007fd1b480b800 [0x1603] State: _call_back _has_called_back 1 _at_poll_safepoint 0
JavaThread state: _thread_blocked
at java.lang.StringLatin1.charAt(StringLatin1.java:44)
at java.lang.String.charAt(String.java:686)
at jdk.internal.org.objectweb.asm.ByteVector.putUTF8(ByteVector.java:258)
at jdk.internal.org.objectweb.asm.ClassWriter.newUTF8(ClassWriter.java:1121)
at jdk.internal.org.objectweb.asm.MethodWriter.visitAnnotation(MethodWriter.java:557)
at java.lang.invoke.InvokerBytecodeGenerator.generateCustomizedCodeBytes(InvokerBytecodeGenerator.java:646)
at java.lang.invoke.InvokerBytecodeGenerator.generateCustomizedCode(InvokerBytecodeGenerator.java:602)
at java.lang.invoke.LambdaForm.compileToBytecode(LambdaForm.java:663)
at java.lang.invoke.DirectMethodHandle.makePreparedLambdaForm(DirectMethodHandle.java:246)
at java.lang.invoke.DirectMethodHandle.preparedLambdaForm(DirectMethodHandle.java:186)
at java.lang.invoke.DirectMethodHandle.preparedLambdaForm(DirectMethodHandle.java:175)
at java.lang.invoke.DirectMethodHandle.make(DirectMethodHandle.java:88)
at java.lang.invoke.DirectMethodHandle.make(DirectMethodHandle.java:108)
at java.lang.invoke.DirectMethodHandle.make(DirectMethodHandle.java:113)
at java.lang.invoke.Invokers.basicInvoker(Invokers.java:89)
at java.lang.invoke.LambdaForm$NamedFunction.<init>(LambdaForm.java:950)
at java.lang.invoke.LambdaForm$Name.<init>(LambdaForm.java:1307)
at java.lang.invoke.Invokers.callSiteForm(Invokers.java:379)
at java.lang.invoke.Invokers.linkToTargetMethod(Invokers.java:347)
at java.lang.invoke.MethodHandleNatives.linkCallSiteImpl(MethodHandleNatives.java:252)
at java.lang.invoke.MethodHandleNatives.linkCallSite(MethodHandleNatives.java:235)
at shtest.m(shtest.java:11)
at shtest.<init>(shtest.java:6)
at shtest.main(shtest.java:16)
And here's the stack for the debuggee's main thread in the Solaris SPARC failure:
"main" #1 prio=5 os_prio=64 tid=0x00000001001d0800 nid=0x2 runnable [0xffffffff7d0f9000]
java.lang.Thread.State: RUNNABLE
JavaThread state: _thread_blocked
Thread: 0x00000001001d0800 [0x 2] State: _call_back _has_called_back 1 _at_poll_safepoint 0
JavaThread state: _thread_blocked
at java.lang.StringLatin1.charAt(StringLatin1.java:47)
at java.lang.String.charAt(String.java:686)
at jdk.internal.org.objectweb.asm.ByteVector.putUTF8(ByteVector.java:258)
at jdk.internal.org.objectweb.asm.ClassWriter.newUTF8(ClassWriter.java:1121)
at jdk.internal.org.objectweb.asm.ClassWriter.visitSource(ClassWriter.java:716)
at java.lang.invoke.InvokerBytecodeGenerator.classFilePrologue(InvokerBytecodeGenerator.java:301)
at java.lang.invoke.InvokerBytecodeGenerator.generateCustomizedCodeBytes(InvokerBytecodeGenerator.java:643)
at java.lang.invoke.InvokerBytecodeGenerator.generateCustomizedCode(InvokerBytecodeGenerator.java:602)
at java.lang.invoke.LambdaForm.compileToBytecode(LambdaForm.java:663)
at java.lang.invoke.LambdaForm.prepare(LambdaForm.java:637)
at java.lang.invoke.MethodHandle.<init>(MethodHandle.java:459)
at java.lang.invoke.BoundMethodHandle.<init>(BoundMethodHandle.java:58)
at java.lang.invoke.BoundMethodHandle$Species_LL.<init>(Species_LL)
at java.lang.invoke.BoundMethodHandle$Species_LL.make(Species_LL)
at java.lang.invoke.LambdaForm$DMH/314265080.invokeStatic_L4_L(LambdaForm$DMH)
at java.lang.invoke.BoundMethodHandle$Species_L.copyWithExtendL(BoundMethodHandle.java:233)
at java.lang.invoke.MethodHandleImpl.makePairwiseConvertByEditor(MethodHandleImpl.java:228)
at java.lang.invoke.MethodHandleImpl.makePairwiseConvert(MethodHandleImpl.java:191)
at java.lang.invoke.MethodHandleImpl.makePairwiseConvert(MethodHandleImpl.java:358)
at java.lang.invoke.MethodHandle.asTypeUncached(MethodHandle.java:781)
at java.lang.invoke.MethodHandle.asType(MethodHandle.java:766)
at java.lang.invoke.Invokers.checkGenericType(Invokers.java:321)
at java.lang.invoke.LambdaForm$MH/248609774.invoke_MT(LambdaForm$MH)
at java.lang.invoke.CallSite.makeSite(CallSite.java:308)
at java.lang.invoke.MethodHandleNatives.linkCallSiteImpl(MethodHandleNatives.java:245)
at java.lang.invoke.MethodHandleNatives.linkCallSite(MethodHandleNatives.java:235)
at java.lang.invoke.StringConcatFactory.<clinit>(StringConcatFactory.java:193)
at jdk.internal.misc.Unsafe.ensureClassInitialized(Native Method)
at java.lang.invoke.DirectMethodHandle.shouldBeInitialized(DirectMethodHandle.java:306)
at java.lang.invoke.DirectMethodHandle.preparedLambdaForm(DirectMethodHandle.java:170)
at java.lang.invoke.DirectMethodHandle.make(DirectMethodHandle.java:88)
at java.lang.invoke.MethodHandles$Lookup.getDirectMethodCommon(MethodHandles.java:1726)
at java.lang.invoke.MethodHandles$Lookup.getDirectMethodNoSecurityManager(MethodHandles.java:1683)
at java.lang.invoke.MethodHandles$Lookup.getDirectMethodForConstant(MethodHandles.java:1868)
at java.lang.invoke.MethodHandles$Lookup.linkMethodHandleConstant(MethodHandles.java:1817)
at java.lang.invoke.MethodHandleNatives.linkMethodHandleConstant(MethodHandleNatives.java:415)
at shtest.m(shtest.java:11)
at shtest.<init>(shtest.java:6)
at shtest.main(shtest.java:16)
The thread dump request caught both of these failures just running regular
code in main(). Nothing special and nothing related to the debugee's code
itself... Could these two failures simply be timeouts due to an overloaded
machine?
03-03-2016
The timeout failure mode for com/sun/jdi/RedefineClearBreakpoint.sh
is not new. See:
JDK-8004127 TEST_BUG: some jdi tests fail intermittently (interrupted by timeout)
for timeout sightings on Windows; other JDI tests in that bug timed out
on other platforms
JDK-8058232 JDI regression tests hang at exit on Windows
for JDI test timeouts specifically for Windows
JDK-6980743 TEST_BUG: com/sun/jdi/CatchCaughtTest.sh failing on windows and Solaris
for JDI test timeouts on Windows using JPRT
Yes, both of these sightings are on non-Windows platforms which is why
I'm not recommending that we close this bug as a dup (yet).