Type specialization / recompilation of functions using "arguments"

[Hannes Wallnöfer]

Thanks for the additional information. The fact that this happens only in interactive mode explains this, because in interactive mode, each line of input is compiled as a separate tiny script. When a script is first executed, its callsites are linked to method handles, and that is the output you’re seeing. So the output only means a new callsite is linked, not that the target function is recompiled. 

Do you see much overhead from this linking operations? Of course first time linking of a callsite is rather expensive, so it makes sense to try reusing scripts instead of creating new ones.

Please let me know if this does not fully explain the behavior you observe or if you have further questions.

Hannes

> Am 05.09.2016 um 14:58 schrieb Axel Faust <axel.faust.g at googlemail.com>:
> 
> Hello Hannes,
> 
> I have repeated the tests with build 9-ea+134 on my new Windows 10 work laptop. Comand line is just "jjs --log=recompile:finest" The behaviour with recompilation can still be observed.
> Additionally I packaged the test script inside a JS file to be executed as "jjs --log=recompile:finest recomp-test.js" and the behaviour you outlined in the comment (without any excessive recompilation) can be observed.
> 
> So far I could only force the behaviour with JJS interactive mode, but I have also observed the recompilation for functions using "arguments" in this way during sampling (via jvisualvm) of my Alfresco-Nashorn integration running on JDK 8u71. It affects "classes" created by a "declare"-module, specifically the constructor (https://github.com/AFaust/alfresco-nashorn-script-engine/blob/master/repository/src/main/resources/de/axelfaust/alfresco/nashorn/repo/_base/declare.js#L328) is recompiled on every invocation (at least in JDK 8u71 and verified through debugging).
> 
> Regards
> Axel
> 
> 
> On 2 September 2016 at 14:58, Hannes Wallnöfer <hannes.wallnoefer at oracle.com> wrote:
> Hi Axel,
> 
> I tried to reproduce the bug with a recent JDK 9 build but did not get any of the additional/unexpected recompilation messages you described. You can see my output here:
> 
> https://bugs.openjdk.java.net/browse/JDK-8164477?focusedCommentId=13996757&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-13996757
> 
> If you still do see the additional messages please let us know the exact JDK version and command line flags you use.
> 
> Thanks,
> Hannes
> 
> 
> > Am 19.08.2016 um 16:49 schrieb Jim Laskey (Oracle) <james.laskey at oracle.com>:
> >
> > Axel,
> >
> > I’ve created a bug to track.  May be slow to process because of vacations and JDK9 long march.
> >
> > https://bugs.openjdk.java.net/browse/JDK-8164477
> >
> > Cheers,
> >
> > — Jim
> >
> >
> >> On Aug 19, 2016, at 11:41 AM, Axel Faust <axel.faust.g at googlemail.com> wrote:
> >>
> >> Hello,
> >>
> >> in my ongoing project to implement an alternative scripting integration to
> >> the ECM platform Alfresco using Nashorn, I recently ran into a performance
> >> issue due to constructor / function recompilation due to type
> >> specialization, particularly if the constructor / function in question is
> >> accessing the "arguments" object.
> >>
> >> I have tried to simplify this with a test and used "jjs
> >> --log=recompile:finest" to run it.
> >>
> >> Consider the following script:
> >>
> >> function testArguments() { print(JSON.stringify(arguments)); }
> >> // simple call tests
> >> testArguments('test1'); // first access => 2x "parameter type
> >> specialization"
> >> testArguments('test1'); // identical parameter => no recompilation
> >> testArguments('test2'); // identical param type, different value =>
> >> "parameter type specialization"
> >> testArguments('test3'); // identical param type, different value =>
> >> "parameter type specialization"
> >> // iterative call test
> >> for (var i = 0; i < 1000; i++) { testArguments('test' + i); } // identical
> >> param type, different values => only one "parameter type specialization"
> >>
> >>
> >> Now I don't quite understand why script function "testArguments" needs to
> >> be recompiled on each call with the same parameter type but different
> >> value, and how this is not required when executed within a loop structure.
> >> The latter is interesting on another level, since a test script for my
> >> Alfresco-Nashorn integration is running an array-forEach loop where the
> >> called function is being recompiled on every iteration, while replacing the
> >> for-loop in the test script above with an array-forEach (pre-filled)
> >> behaves exactly the same as the for-loop with only a single recompilation.
> >> Additionally, in the integration test script I even see recompilations for
> >> identical values (in subsequent runs of the same script).
> >>
> >> Now having a single recompilation wouldn't be so bad, but continous
> >> recompilation hurts quite a bit. Unfortunately this affects quite a central
> >> piece in my integration project and thus causes significant overhead via
> >> ClassLoader.defineClass, Class.getDeclaredFields and method handle / call
> >> site handling operations that result from the recompilation. Each run of my
> >> integration-specific test script adds ~10 CompiledFunction instances to the
> >> ScriptFunctionData.code list for the same function (all with apparently
> >> identical call site types and invokers, at least judging from
> >> toString-representations). The persistent code cache doesn't seem to be
> >> used at all as RecompilableScriptFunctionData.getBest calls
> >> compileTypeSpecialization in a way that disables its use.
> >>
> >> Is this behaviour something that should be considered "expected" or is it a
> >> "real" performance bug? If it is expected, is there a general
> >> recommendation not to use functions that access arguments for
> >> performance-critical code?
> >> (I tested with JDK 8u71 and JDK 9 ea+125 - behaviour is the same except JDK
> >> 9 provides deoptimization log output on 1st call)
> >>
> >> Regards
> >> Axel Faust
> >
> 
>