Nashorn increase in eval duration over time

Wed Mar 16 10:43:48 UTC 2016

Jan,

This definitely looks like a bug in the implementation of method 
handles. I've filed a bug:

https://bugs.openjdk.java.net/browse/JDK-8151981

If there is any information you can add please do so, it will make 
finding and fixing the problem easier.

Hannes

Am 2016-03-14 um 18:16 schrieb 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
>>
>