Nashorn increase in eval duration over time

[Jan Bauer Nielsen]

Hi Hannes.

Yes, the second batch gets a new set of script engines.

The java version is 1.8.0_72-b15, so it should be pretty recent. We 
haven't tried any of the java 9 ea builds, since our production version 
of GlassFish won't run with this.

Jan

On 2016-03-14 17:44, Hannes Wallnoefer wrote:
> Hi Jan,
>
> This list is fine for reporting Nashorn related problems.
>
> Is it correct that the second batch of business logic is evaluated 
> into a completely new set of script engines? In that case I'm not sure 
> how the problem could be with Nashorn, since different script engines 
> should not share anything. So that could hint at a problem deeper down 
> in the implementation of method handles.
>
> If you are using JDK 8_25 (not sure I parse the version string 
> correctly) one thing you could try is to use a newer JDK 8 update 
> release. There are a few issues that have been fixed in later releases.
>
> Hannes
>
> Am 2016-03-10 um 13:13 schrieb Jan Bauer Nielsen:
>> First of all I'm sorry if this is not the right forum for this type 
>> of question, but I haven't been able to find a nashorn-user mailing 
>> list or anything like that.
>>
>> We have an enterprise application (using GlassFish 4.1 as application 
>> server) which sits in the middle of a processing pipeline receiving 
>> data messages from a JMS queue and applying business logic in the 
>> form of substantial (30.000+ lines) javascripts to said data. The 
>> business logic is user defined, varies on the type of input format, 
>> and as such is not known to us at application startup. The setup in 
>> question allows for 8 concurrent processor threads, where each thread 
>> evals into (and caches) one script engine per unique set of business 
>> logic (the cache is actually on the EJB level and not on the thread 
>> level).
>>
>> Submitting a batch requiring business-logic-x results in below eval 
>> times:
>>
>> [2016-03-10 09:15:41,756] [INFO] [p: thread-pool-1; w: 43] Module 
>> eval took 6540 ms
>> [2016-03-10 09:15:42,918] [INFO] [p: thread-pool-1; w: 39] Module 
>> eval took 7663 ms
>> [2016-03-10 09:15:44,188] [INFO] [p: thread-pool-1; w: 46] Module 
>> eval took 9000 ms
>> [2016-03-10 09:15:44,670] [INFO] [p: thread-pool-1; w: 42] Module 
>> eval took 9481 ms
>> [2016-03-10 09:15:44,920] [INFO] [p: thread-pool-1; w: 41] Module 
>> eval took 9681 ms
>> [2016-03-10 09:15:45,043] [INFO] [p: thread-pool-1; w: 40] Module 
>> eval took 9784 ms
>> [2016-03-10 09:15:45,196] [INFO] [p: thread-pool-1; w: 44] Module 
>> eval took 9944 ms
>> [2016-03-10 09:15:45,427] [INFO] [p: thread-pool-1; w: 45] Module 
>> eval took 10222 ms
>>
>> Subsequently submitting another batch requiring business-logic-y 
>> forcing more script engines to be created (simulated here by clearing 
>> cached script engines from application and resubmitting batch for 
>> business-logic-x) results in much worse performance:
>>
>> [2016-03-10 09:26:07,129] [INFO] [p: thread-pool-1; w: 31] Module 
>> eval took 226070 ms
>> [2016-03-10 09:26:14,760] [INFO] [p: thread-pool-1; w: 40] Module 
>> eval took 234753 ms
>> [2016-03-10 09:26:17,167] [INFO] [p: thread-pool-1; w: 26] Module 
>> eval took 230762 ms
>> [2016-03-10 09:26:22,174] [INFO] [p: thread-pool-1; w: 36] Module 
>> eval took 235614 ms
>> [2016-03-10 09:26:22,978] [INFO] [p: thread-pool-1; w: 30] Module 
>> eval took 238836 ms
>> [2016-03-10 09:26:28,909] [INFO] [p: thread-pool-1; w: 38] Module 
>> eval took 242011 ms
>> [2016-03-10 09:26:40,921] [INFO] [p: thread-pool-1; w: 32] Module 
>> eval took 252076 ms
>> [2016-03-10 09:26:50,700] [INFO] [p: thread-pool-1; w: 35] Module 
>> eval took 262625 ms
>>
>> We are not seeing anything out of the ordinary with regard to GC, 
>> apart from survivor space often being near 100% full before objects 
>> are moved to old-gen. Heap and code cache are nowhere near to being 
>> exhausted.
>>
>> Unfortunately we haven't been able to get java flight recorder to 
>> work with this GlassFish installation, but jvisualvm samples 
>> indicates that 80% of our time is being spent in 
>> java.lang.invoke.MethodHandleNatives.setCallSiteTargetNormal().
>>
>> We have tried running both single threaded and with a shared script 
>> engine creating separate script contexts, and although we are seeing 
>> much better performance in these cases, we are still seeing an 
>> increase in eval times nonetheless (in the shared engine case, the 
>> eval times of the second batch is a factor 10 less than the numbers 
>> above, but it is still a factor 5 larger than the initial batch).
>>
>> We are running on java build 25.72-b15.
>>
>> Any input as to what we might be doing wrong and possibly how to 
>> avoid it would be very much appreciated.
>>
>> This problem has actually forced us to remain on the Rhino script 
>> engine for the time being.
>>
>> Kind regards,
>>
>> Jan Bauer Nielsen
>> Software developer
>> DBC as
>> http://www.dbc.dk/english
>