Bug ID: JDK-8062308 b36 of 9 introduces regressions over b35 when running lyra

JDK-8062308 : b36 of 9 introduces regressions over b35 when running lyra

Type: Bug
Component: core-libs
Sub-Component: jdk.nashorn
Affected Version: 8u40,9

Priority: P2
Status: Resolved
Resolution: Fixed

Submitted: 2014-10-28
Updated: 2015-06-04
Resolved: 2014-11-06

Versions (Unresolved/Resolved/Fixed)

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 8	JDK 9
8u40Fixed	9 b39Fixed

Description

from the lyra dir:

mvn clean 
ant 

set DYLD_PATH correctly
export JAVA_HOME to a JDK9 build with a nashorn.jar that points to b35 or b36

 bin/avatar -ot -t 2 ../benchmarks/restjs/restjs.js 

Causes

com.oracle.avatar.js.ServerException: TypeError: Cannot call undefined in jar:file:/Users/marcus/src/avatar/closed/lyra/target/lib/avatar-js-0.10.32-SNAPSHOT.jar!/lib/net.js at line number 578
	at com.oracle.avatar.js.Server.run(Server.java:219)
	at com.oracle.avatar.core.EventThread.run(EventThread.java:215)
Caused by: javax.script.ScriptException: TypeError: Cannot call undefined in jar:file:/Users/marcus/src/avatar/closed/lyra/target/lib/avatar-js-0.10.32-SNAPSHOT.jar!/lib/net.js at line number 578
	at jdk.nashorn.api.scripting.NashornScriptEngine.throwAsScriptException(NashornScriptEngine.java:455)
	at jdk.nashorn.api.scripting.NashornScriptEngine.evalImpl(NashornScriptEngine.java:439)
	at jdk.nashorn.api.scripting.NashornScriptEngine.evalImpl(NashornScriptEngine.java:401)
	at jdk.nashorn.api.scripting.NashornScriptEngine.evalImpl(NashornScriptEngine.java:397)
	at jdk.nashorn.api.scripting.NashornScriptEngine.eval(NashornScriptEngine.java:147)
	at com.oracle.avatar.js.Server.eval(Server.java:475)
	at com.oracle.avatar.js.Server.access$1300(Server.java:66)
	at com.oracle.avatar.js.Server$SystemScriptRunner.run(Server.java:694)
	at com.oracle.avatar.js.Server.runSystemScript(Server.java:255)
	at com.oracle.avatar.js.Server.runEventLoop(Server.java:297)
	at com.oracle.avatar.js.Server.runUserScripts(Server.java:271)
	at com.oracle.avatar.js.Server.run(Server.java:214)
	... 1 more
Caused by: jar:file:/Users/marcus/src/avatar/closed/lyra/target/lib/avatar-js-0.10.32-SNAPSHOT.jar!/lib/net.js:578 TypeError: Cannot call undefined
	at jdk.nashorn.internal.runtime.ECMAErrors.error(ECMAErrors.java:57)
	at jdk.nashorn.internal.runtime.ECMAErrors.typeError(ECMAErrors.java:213)
	at jdk.nashorn.internal.runtime.ECMAErrors.typeError(ECMAErrors.java:185)
	at jdk.nashorn.internal.runtime.ECMAErrors.typeError(ECMAErrors.java:172)
	at jdk.nashorn.internal.runtime.Undefined.lookupTypeError(Undefined.java:128)
	at jdk.nashorn.internal.runtime.Undefined.lookup(Undefined.java:100)
	at jdk.nashorn.internal.runtime.linker.NashornLinker.getGuardedInvocation(NashornLinker.java:102)
	at jdk.nashorn.internal.runtime.linker.NashornLinker.getGuardedInvocation(NashornLinker.java:94)
	at jdk.internal.dynalink.support.CompositeTypeBasedGuardingDynamicLinker.getGuardedInvocation(CompositeTypeBasedGuardingDynamicLinker.java:176)
	at jdk.internal.dynalink.support.CompositeGuardingDynamicLinker.getGuardedInvocation(CompositeGuardingDynamicLinker.java:124)
	at jdk.internal.dynalink.support.LinkerServicesImpl.getGuardedInvocation(LinkerServicesImpl.java:149)
	at jdk.internal.dynalink.DynamicLinker.relink(DynamicLinker.java:233)
	at jdk.nashorn.internal.scripts.Script$Recompilation$359$1AAAAA$net$cu1$restOf.L:1(jar:file:/Users/marcus/src/avatar/closed/lyra/target/lib/avatar-js-0.10.32-SNAPSHOT.jar!/lib/net.js:578)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:625)
	at jdk.nashorn.internal.scripts.Script$Recompilation$45$4681$init.L:65$compile$run(/com/oracle/avatar/js/init.js:134)
	at jdk.nashorn.javaadapters.java.security.PrivilegedAction.run(Unknown Source)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.lang.invoke.MethodHandleImpl$BindCaller$T/431778633.invoke_V(MethodHandleImpl.java:1100)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at jdk.nashorn.internal.scripts.Script$Recompilation$53$4515$init.L:65$compile(/com/oracle/avatar/js/init.js:131)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at jdk.nashorn.internal.scripts.Script$Recompilation$184$3252A$init.L:65$require(/com/oracle/avatar/js/init.js:97)
	at jdk.nashorn.internal.scripts.Script$Recompilation$235$1AAAAA$tty$cu1$restOf.L:1(jar:file:/Users/marcus/src/avatar/closed/lyra/target/lib/avatar-js-0.10.32-SNAPSHOT.jar!/lib/tty.js:24)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:625)
	at jdk.nashorn.internal.scripts.Script$Recompilation$45$4681$init.L:65$compile$run(/com/oracle/avatar/js/init.js:134)
	at jdk.nashorn.javaadapters.java.security.PrivilegedAction.run(Unknown Source)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.lang.invoke.MethodHandleImpl$BindCaller$T/431778633.invoke_V(MethodHandleImpl.java:1100)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at jdk.nashorn.internal.scripts.Script$Recompilation$53$4515$init.L:65$compile(/com/oracle/avatar/js/init.js:131)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at jdk.nashorn.internal.scripts.Script$Recompilation$184$3252A$init.L:65$require(/com/oracle/avatar/js/init.js:97)
	at jdk.nashorn.internal.scripts.Script$Recompilation$228$6581I$process$cu1$restOf.L:1$wrapStdOutputStream(jar:file:/Users/marcus/src/avatar/closed/lyra/target/lib/avatar-js-0.10.32-SNAPSHOT.jar!/lib/process.js:186)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:625)
	at jdk.nashorn.internal.scripts.Script$Recompilation$198$8550$process.L:1$get-1(jar:file:/Users/marcus/src/avatar/closed/lyra/target/lib/avatar-js-0.10.32-SNAPSHOT.jar!/lib/process.js:239)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:625)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at jdk.nashorn.internal.runtime.UserAccessorProperty.invokeGetterAccessor(UserAccessorProperty.java:289)
	at jdk.nashorn.internal.scripts.Script$Recompilation$197$1AAAAA$console$cu1$restOf.L:1(jar:file:/Users/marcus/src/avatar/closed/lyra/target/lib/avatar-js-0.10.32-SNAPSHOT.jar!/lib/console.js:107)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:625)
	at jdk.nashorn.internal.scripts.Script$Recompilation$45$4681$init.L:65$compile$run(/com/oracle/avatar/js/init.js:134)
	at jdk.nashorn.javaadapters.java.security.PrivilegedAction.run(Unknown Source)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.lang.invoke.MethodHandleImpl$BindCaller$T/431778633.invoke_V(MethodHandleImpl.java:1100)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at jdk.nashorn.internal.scripts.Script$Recompilation$53$4515$init.L:65$compile(/com/oracle/avatar/js/init.js:131)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at jdk.nashorn.internal.scripts.Script$Recompilation$184$3252A$init.L:65$require(/com/oracle/avatar/js/init.js:97)
	at jdk.nashorn.internal.scripts.Script$Recompilation$187$2787$init$cu1$restOf.L:65(/com/oracle/avatar/js/init.js:185)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:625)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:625)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:625)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:625)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at jdk.nashorn.internal.scripts.Script$Recompilation$8$init$cu1$restOf.:program(/com/oracle/avatar/js/init.js:65)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:625)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at java.lang.invoke.LambdaForm.interpret_L(LambdaForm.java:664)
	at jdk.nashorn.internal.runtime.ScriptFunctionData.invoke(ScriptFunctionData.java:636)
	at jdk.nashorn.internal.runtime.ScriptFunction.invoke(ScriptFunction.java:229)
	at jdk.nashorn.internal.runtime.ScriptRuntime.apply(ScriptRuntime.java:387)
	at jdk.nashorn.api.scripting.NashornScriptEngine.evalImpl(NashornScriptEngine.java:437)
	... 11 more



This does not happen with b35

Comments

Marking as noreg-hard as it only manifests itself as a race condition with a certain probability of occurring.
06-11-2014
As Hannes correctly suspected, so it seems like indeed GlobalConstants is the race condition culprit. Disabling it makes Lyra start up successfully every time. I'm thinking of how can we keep this functionality. Constant linkage with no guard creates a binding of Class representing script code and a specific Global. While it produces nice performance improvements, it also causes incorrect operation once the Class is shared between Globals. Again, as Hannes suggested, we could invalidate the switch points and disable the functionality as soon as the 2nd Global is created in a Context. However, it needs to be noted that even the current implementation of the feature seems problematic, as we're keeping a single instance as a static field in the Global class, so it'll end up being shared across Contexts (since the Global class will exist in the extensions class loader, there'll be only one per JVM, so the static in Global will be truly, well, global).
04-11-2014
Here's one where the property maps are the same, but one says "undefined" for the property, while the other says "function": Defined __defineGetter__, type: function, this=class jdk.nashorn.internal.objects.Global@7de4d1e3, Object=class jdk.nashorn.internal.objects.NativeObject$Constructor@3b3e69e5, Object.prototype=class jdk.nashorn.internal.objects.NativeObject$Prototype@39b03b2, Object.prototype.map=class jdk.nashorn.internal.runtime.PropertyMap@29956f4c Defined __defineGetter__, type: undefined, this=class jdk.nashorn.internal.objects.Global@3dfdd56b, Object=class jdk.nashorn.internal.objects.NativeObject$Constructor@360b060d, Object.prototype=class jdk.nashorn.internal.objects.NativeObject$Prototype@39b03b2, Object.prototype.map=class jdk.nashorn.internal.runtime.PropertyMap@29956f4c
03-11-2014
Further adding the identity of the Object.prototype property map shows, e.g: Defined __defineGetter__, type: function, this=class jdk.nashorn.internal.objects.Global@5100939a, Object=class jdk.nashorn.internal.objects.NativeObject$Constructor@515dd3d7, Object.prototype=class jdk.nashorn.internal.objects.NativeObject$Prototype@6c252aa2, Object.prototype.map=class jdk.nashorn.internal.runtime.PropertyMap@c11027c Defined __defineGetter__, type: function, this=class jdk.nashorn.internal.objects.Global@137c13b6, Object=class jdk.nashorn.internal.objects.NativeObject$Constructor@515dd3d7, Object.prototype=class jdk.nashorn.internal.objects.NativeObject$Prototype@2713a6e4, Object.prototype.map=class jdk.nashorn.internal.runtime.PropertyMap@5d5f428f Now, sometimes it'll show the same maps, sometime different ones. Sometimes both have "type: function", sometimes one will have "type: undefined" etc.
03-11-2014
Expanding the diagnostic printout to various identities we get: Defined __defineGetter__, type: undefined, this=class jdk.nashorn.internal.objects.Global@32ef5b2, Object=class jdk.nashorn.internal.objects.NativeObject$Constructor@474a0c24, Object.prototype=class jdk.nashorn.internal.objects.NativeObject$Prototype@75b0c974 Defined __defineGetter__, type: function, this=class jdk.nashorn.internal.objects.Global@324c1e4b, Object=class jdk.nashorn.internal.objects.NativeObject$Constructor@474a0c24, Object.prototype=class jdk.nashorn.internal.objects.NativeObject$Prototype@75b0c974 Obviously, we have different globals in the two different threads, but they manipulate the same Object and same Object.prototype. That seems wrong.
03-11-2014
TL;DR: we seem to have a race condition in multithreaded use of Nashorn. Runtime type prediction reduced the number of recompilations thus made the race condition more likely to occur. Long version: The only use of runtime type prediction for an immediately invoked function expression that occurs with this system is in mozilla_compat.js:52, which is defining "importPackage". However, the error in net.js:578 happens with an invocation of __defineGetter__ instead, which is itself defined a bit afterwards, in mozilla_compat:113. I have added diagnostic printout to mozilla_compat.js print("Defined __defineGetter__; type: " + (typeof Object.prototype.__defineGetter__)); and am seeing: Defined __defineGetter__; type: function Defined __defineGetter__; type: undefined <--- this is wrong I checked, and it turns out the two initializations of mozilla_compat.js happen on two different threads ("restjs.0" and "restjs.1"). Sometimes the first line will print "undefined", and the second will print "function". Sometimes both print "function" and the system happily starts up. Sometimes both print "function" and the system still fails to start up. Looks very much like a race condition. Further attested by the fact that if I start it with "bin/avatar -ot -t 1" (one thread), then it also happily starts up. Investigating further��
03-11-2014
This is the offending code in TypeEvaluator. Commenting it out fixes everything else if (expr instanceof CallNode) { // Currently, we'll only try to guess the return type of immediately invoked function expressions with no // parameters, that is (function() { ... })(). We could do better, but these are all heuristics and we can // gradually introduce them as needed. An easy one would be to do the same for .call(this) idiom. final CallNode callExpr = (CallNode)expr; final Expression fnExpr = callExpr.getFunction(); if (fnExpr instanceof FunctionNode) { final FunctionNode fn = (FunctionNode)fnExpr; if (callExpr.getArgs().isEmpty()) { final RecompilableScriptFunctionData data = compiler.getScriptFunctionData(fn.getId()); if (data != null) { final Type returnType = Type.typeFor(data.getReturnType(EMPTY_INVOCATION_TYPE, runtimeScope)); if (returnType == Type.BOOLEAN) { // We don't have optimistic booleans. In fact, optimistic call sites getting back boolean // currently deoptimize all the way to Object. return Type.OBJECT; } assert returnType == Type.INT \|\| returnType == Type.LONG \|\| returnType == Type.NUMBER \|\| returnType == Type.OBJECT; return returnType; } } }
29-10-2014
Confirmed. The very same problems happen in late 8u40 builds, and backing off to changeset: 1003:ef1e5e03e03e user: attila date: Wed Oct 15 16:00:21 2014 +0200 summary: 8060241: Immediately invoked function expressions cause lot of deoptimization still crashes. hg update -r 1002 and rebuild and we are fine though. Obviously this is the problematic change, as it has the same behavior in the backport.
28-10-2014
The culprit appears to be this change: changeset: 1062:6e9a98b55502 user: attila date: Wed Oct 15 16:00:21 2014 +0200 summary: 8060241: Immediately invoked function expressions cause lot of deoptimization I took a JDK1.9.0 build 36, unpacked it, set it as JAVA_HOME, deleted jre/lib/ext/nashorn.jar, symlinked my idk9/nashorn/dist/nashorn.jar to jre/lib/ext/nashorn.jar (now empty) in the JDK and kept restarting the avatar server cd closed/lyra bin/avatar -ot -t 2 ../benchmarks/restjs/restjs.js -jfr working my way through changes with hg update -r <changenumber> and rebuilding the nashorn.jar Everything was broken until I got to 1061, where things started to work again. Updating to 1062 broke it once more. Thus, there seems to be a pretty strong indication that 1062 is the culprit.
28-10-2014