Explosions in calls to MutableCallSite.setTarget

[Benjamin Sieffert]

Hi again,

we're now trying this out with java 8 and have been seeing similar
behaviour. The difference in comparison to java 7 is that we're also seeing
LambdaForms in the "hanging" thread's stack traces and a second possible
stack trace appeared.

In the meantime, we also discovered that a full GC (we're using CMS in case
that's relevant) will abort the erronous behaviour and revert our
application back to its normal (healthy) state. I suspect that this has got
something to do with certain nmethods / classes being collected. Maybe it's
interesting to note that we're also making use of JRuby in this
application. Anyway, the moment we start running all the javascript through
nashorn, there is (of course) a very noticable surge in code cache size and
number of loaded classes. A full gc, when run, will then bring them
noticably down. So, talking about permgen/metaspace in general, while our
application is running we're seeing them rise steadily, brought down again
every so often (every dozen or so minutes) by a full gc. Interestingly, in
the case of our threads all being busy with those setTarget()-calls,
permgen/metaspace population will almost stop growing. Hence it might take
a full gc even longer to take place, sadly, and prolong the problem.


trace samples for your consumption:
JVM: Java HotSpot(TM) 64-Bit Server VM (25.0-b48, mixed mode) Java: version
1.8.0-ea, vendor Oracle Corporation

1.
at java.lang.invoke.MethodHandleNatives.setCallSiteTargetNormal(Native
Method)
at java.lang.invoke.CallSite.setTargetNormal(CallSite.java:245)
at java.lang.invoke.MutableCallSite.setTarget(MutableCallSite.java:154)
at
jdk.internal.dynalink.support.AbstractRelinkableCallSite.initialize(AbstractRelinkableCallSite.java:115)
at jdk.internal.dynalink.DynamicLinker.link(DynamicLinker.java:184)
at
jdk.nashorn.internal.runtime.linker.Bootstrap.bootstrap(Bootstrap.java:126)
at
java.lang.invoke.LambdaForm$DMH/272755642.invokeStatic_LLLI_L(LambdaForm$DMH)
... (omitting a few invocations of LambdaForm methods)
at java.lang.invoke.LambdaForm$MH/839784351.invoke_MT(LambdaForm$MH)
at java.lang.invoke.CallSite.makeSite(CallSite.java:283)
at
java.lang.invoke.MethodHandleNatives.linkCallSite(MethodHandleNatives.java:294)
at jdk.nashorn.internal.scripts.Script$\^eval\_._L196(<eval>:231)

2.
at sun.misc.Unsafe.defineAnonymousClass(Native Method)
at
java.lang.invoke.InvokerBytecodeGenerator.loadAndInitializeInvokerClass(InvokerBytecodeGenerator.java:262)
at
java.lang.invoke.InvokerBytecodeGenerator.loadMethod(InvokerBytecodeGenerator.java:250)
at
java.lang.invoke.InvokerBytecodeGenerator.generateCustomizedCode(InvokerBytecodeGenerator.java:509)
at java.lang.invoke.LambdaForm.compileToBytecode(LambdaForm.java:454)
at java.lang.invoke.LambdaForm.checkInvocationCounter(LambdaForm.java:634)
... (omitting a few invocations of LambdaForm methods)
at java.lang.invoke.LambdaForm$LFI/1682860686.interpret_L(LambdaForm$LFI)
at java.lang.invoke.LambdaForm$MH/1997512181.linkToCallSite(LambdaForm$MH)
at jdk.nashorn.internal.scripts.Script$\^eval\_._L196(<eval>:232)


If you could use more information regarding this problem, please let me
know.
Best regards


2013/9/7 A. Sundararajan <sundararajan.athijegannathan at oracle.com>

> Hi,
>
> Thanks for writing to us. Yes - Nashorn jdk7 is more of what we'd say
> "experimental".
>
> There have been changes in jsr292/jdk as well as in nashorn with the
> latest jdk8 codebase. Please use nashorn in jdk8 pre-release snapshots.
>
> If the issue you are seeing is reproduced with jdk8, please file a bug or
> send us the details (in this list) and we'll file a bug.
>
> Thanks
> -Sundar
>
>
> On Friday 06 September 2013 07:14 PM, Benjamin Sieffert wrote:
>
>> Hi everyone,
>>
>> we're still eager users of nashorn around here and while doing some
>> profiling stumpled upon a kind of weird behaviour, where there are periods
>> almost our complete CPU is consumed by calls to setTarget /
>> setTargetNormal
>> on java.lang.invoke.Callsite.
>>
>> What we do in our code is to initialize a few hundred script engines and
>> let each run a javascript that returns a js-object once. Then we store
>> this
>> returned js-object and call a certain method on it in massive scale. There
>> is some amount of accessing java objects this javascript.
>>
>> As we initialize the script engines, there is of course a noticable surge
>> on cpu load, as the javascript gets compiled and optimized. But this dies
>> down within a few minutes and we see a very good performance, until
>> suddenly our threads start to get very very busy with the already
>> mentioned
>> calls so setTarget(). This will die down after a while, too, but happen
>> again after seemingly random periods.
>>
>> Looking at the exact stack trace, it's:
>> at java.lang.invoke.**MethodHandleNatives.**
>> setCallSiteTargetNormal(Native
>> Method)
>> java.lang.invoke.CallSite.**setTargetNormal(CallSite.java:**270)
>> java.lang.invoke.**MutableCallSite.setTarget(**MutableCallSite.java:154)
>>
>> I have to admit that we are still using the jdk7-backport, though, which
>> has not been updated since July. Possibly this is a problem already fixed
>> in the jdk8 branch. If so, keep up the good work! :) If not, I'd gladly
>> take any input on what might cause this problem and what we might do to
>> counteract it.
>>
>> Best regards
>> Benjamin
>>
>
>


-- 
Benjamin Sieffert
metrigo GmbH
Sternstr. 106
20357 Hamburg

Geschäftsführer: Christian Müller, Tobias Schlottke, Philipp Westermeyer
Die Gesellschaft ist eingetragen beim Registergericht Hamburg
Nr. HRB 120447.