mozilla / rhino

Rhino is an open-source implementation of JavaScript written entirely in Java
https://rhino.github.io
Other
4.14k stars 846 forks source link

Rhino engine creates huge amount of classes during expression evaluation and causes tomcat to hang #374

Open rohan-jha opened 6 years ago

rohan-jha commented 6 years ago

Hi All, We are using Rhino engine for expression evaluation in our project. We are using the engine for very simple expression evaluations like:

'asd'=='asd' && true
! false && ! false && !false && ((true && ! false) && ('ee'=='ee'))

When we bring the tomcat server up, the server becomes unresponsive with even single user sometimes, but this happens intermittently. Upon investigating the thread dump, we got the following thread blocking other threads and causing the server to hang.

http-nio-8080-exec-18 
Stack Trace is: 
java.lang.Thread.State: RUNNABLE
at org.mozilla.javascript.gen._Unknown_source__503912.call(<Unknown source>)
at org.mozilla.javascript.gen._Unknown_source__503912.exec(<Unknown source>)
at org.mozilla.javascript.Context.evaluateReader(Context.java:1110)
at com.sun.phobos.script.javascript.RhinoScriptEngine.eval(RhinoScriptEngine.java:172)
at com.sun.phobos.script.javascript.RhinoScriptEngine.eval(RhinoScriptEngine.java:198)
at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:264)
at com.asps.parser.Parser.evaluateWithJs(Parser.java:373)
at com.asps.parser.Parser.eval(Parser.java:358)
at com.asps.parser.Parser.execute(Parser.java:98)
at com.asps.parser.Parser.getValues(Parser.java:266)
at com.asps.parser.Parser.execute(Parser.java:81)
at com.asps.parser.Parser.parse(Parser.java:43)
at com.asps.eval.Evaluator.eval(Evaluator.java:10)
at com.asps.functioneditor.service.ServiceUtil.testFunction(ServiceUtil.java:172)
at com.asps.functioneditor.service.ServiceUtil.run(ServiceUtil.java:80)
at com.asps.functioneditor.service.ServiceUtil.run(ServiceUtil.java:62)
at com.asps.functioneditor.service.ServiceUtil.run(ServiceUtil.java:62)
at com.asps.functioneditor.service.ServiceUtil.run(ServiceUtil.java:62)
at com.otx.collections.scripting.scripts.service.ScriptService.evaluateFunctionsForLoan(ScriptService.java:669)
at com.otx.collections.scripting.scriptRendering.util.ScriptRenderingUtil.evaluateWidgets(ScriptRenderingUtil.java:1455)
at com.otx.collections.scripting.scriptRendering.action.ProcessAccountID.evaluateWidgets(ProcessAccountID.java:748)
at com.otx.collections.scripting.scriptRendering.action.ProcessAccountID.evaluateWidgets(ProcessAccountID.java:717)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at ognl.OgnlRuntime.invokeMethod(OgnlRuntime.java:873)
- locked <0x0000000567bb4100> (a java.lang.reflect.Method)
at ognl.OgnlRuntime.callAppropriateMethod(OgnlRuntime.java:1539)
at ognl.ObjectMethodAccessor.callMethod(ObjectMethodAccessor.java:68)
at com.opensymphony.xwork2.ognl.accessor.XWorkMethodAccessor.callMethodWithDebugInfo(XWorkMethodAccessor.java:96)
at com.opensymphony.xwork2.ognl.accessor.XWorkMethodAccessor.callMethod(XWorkMethodAccessor.java:88)
at ognl.OgnlRuntime.callMethod(OgnlRuntime.java:1615)
at ognl.ASTMethod.getValueBody(ASTMethod.java:91)
at ognl.SimpleNode.evaluateGetValueBody(SimpleNode.java:212)
at ognl.SimpleNode.getValue(SimpleNode.java:258)
at ognl.Ognl.getValue(Ognl.java:467)
at ognl.Ognl.getValue(Ognl.java:431)
at com.opensymphony.xwork2.ognl.OgnlUtil$3.execute(OgnlUtil.java:351)
at com.opensymphony.xwork2.ognl.OgnlUtil.compileAndExecuteMethod(OgnlUtil.java:403)
at com.opensymphony.xwork2.ognl.OgnlUtil.callMethod(OgnlUtil.java:349)
at com.opensymphony.xwork2.DefaultActionInvocation.invokeAction(DefaultActionInvocation.java:436)
at com.opensymphony.xwork2.DefaultActionInvocation.invokeActionOnly(DefaultActionInvocation.java:291)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:252)
at org.apache.struts2.interceptor.debugging.DebuggingInterceptor.intercept(DebuggingInterceptor.java:253)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at com.opensymphony.xwork2.interceptor.DefaultWorkflowInterceptor.doIntercept(DefaultWorkflowInterceptor.java:177)
at com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:98)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at com.opensymphony.xwork2.validator.ValidationInterceptor.doIntercept(ValidationInterceptor.java:260)
at org.apache.struts2.interceptor.validation.AnnotationValidationInterceptor.doIntercept(AnnotationValidationInterceptor.java:73)
at com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:98)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at com.opensymphony.xwork2.interceptor.ConversionErrorInterceptor.doIntercept(ConversionErrorInterceptor.java:139)
at com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:98)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at com.opensymphony.xwork2.interceptor.ParametersInterceptor.doIntercept(ParametersInterceptor.java:133)
at com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:98)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at com.opensymphony.xwork2.interceptor.ParametersInterceptor.doIntercept(ParametersInterceptor.java:133)
at com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:98)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at com.opensymphony.xwork2.interceptor.StaticParametersInterceptor.intercept(StaticParametersInterceptor.java:192)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at org.apache.struts2.interceptor.MultiselectInterceptor.intercept(MultiselectInterceptor.java:69)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at org.apache.struts2.interceptor.DateTextFieldInterceptor.intercept(DateTextFieldInterceptor.java:115)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at org.apache.struts2.interceptor.CheckboxInterceptor.intercept(CheckboxInterceptor.java:88)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at org.apache.struts2.interceptor.FileUploadInterceptor.intercept(FileUploadInterceptor.java:246)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at com.opensymphony.xwork2.interceptor.ModelDrivenInterceptor.intercept(ModelDrivenInterceptor.java:99)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at com.opensymphony.xwork2.interceptor.ScopedModelDrivenInterceptor.intercept(ScopedModelDrivenInterceptor.java:139)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at com.opensymphony.xwork2.interceptor.ChainingInterceptor.intercept(ChainingInterceptor.java:155)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at com.opensymphony.xwork2.interceptor.PrepareInterceptor.doIntercept(PrepareInterceptor.java:174)
at com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:98)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at org.apache.struts2.interceptor.I18nInterceptor.intercept(I18nInterceptor.java:120)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at org.apache.struts2.interceptor.ServletConfigInterceptor.intercept(ServletConfigInterceptor.java:171)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at com.opensymphony.xwork2.interceptor.AliasInterceptor.intercept(AliasInterceptor.java:195)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at com.opensymphony.xwork2.interceptor.ExceptionMappingInterceptor.intercept(ExceptionMappingInterceptor.java:193)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at com.opensymphony.xwork2.interceptor.StaticParametersInterceptor.intercept(StaticParametersInterceptor.java:192)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at com.opensymphony.xwork2.interceptor.ParametersInterceptor.doIntercept(ParametersInterceptor.java:133)
at com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:98)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at org.apache.struts2.interceptor.CheckboxInterceptor.intercept(CheckboxInterceptor.java:88)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at com.otx.collections.common.interceptors.AuthenticateInterceptor.intercept(AuthenticateInterceptor.java:107)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at com.opensymphony.xwork2.interceptor.ExceptionMappingInterceptor.intercept(ExceptionMappingInterceptor.java:193)
at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247)
at org.apache.struts2.factory.StrutsActionProxy.execute(StrutsActionProxy.java:54)
at org.apache.struts2.dispatcher.Dispatcher.serviceAction(Dispatcher.java:564)
at org.apache.struts2.dispatcher.ExecuteOperations.executeAction(ExecuteOperations.java:81)
at org.apache.struts2.dispatcher.filter.StrutsPrepareAndExecuteFilter.doFilter(StrutsPrepareAndExecuteFilter.java:143)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:474)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79)
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:624)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:349)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:783)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:798)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1434)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
- locked <0x00000005676fc3c8> (a org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
Locked ownable synchronizers:
- <0x000000056314c120> (a java.util.concurrent.ThreadPoolExecutor$Worker)

Upon further investigation using java profilers, we saw that some 80-90k classes (not instances) are getting loaded from rhino engine, which is causing the server to reach max thread limit and hang. Classes getting creating almot infinetly are: org.mozilla.javascript.gen._Unknown_source__ org.mozilla.javascript.print Upon source code checkup "org.mozilla.javascript.gen" classes are getting created at Codegen.compile(). These evaluation takes milliseconds to compile initially but keeps on increasing as the classes are created and go up to minutes and hang completely.

Initially, we were using old Rhino version, which was giving above problem, following which we have upgraded the version to 1.7R5 and then to 1.7.7.2, but still getting the same issue. We are using jdk v1.8.0_121 to compile our code and tomcat v8.5.11 to deploy the code.

gbrail commented 6 years ago

In compiled mode — which is the default — every time you run a script Rhino compiles it to bytecode and then executes the compiled script. It is the most efficient execution mode for Rhino by far, even for a script that you only run once. (After it’s done, the bytecode will be garbage collected in that case.)

You can try running Rhino in interpreted mode by calling “setOptimizationLevel” on the Context class to -1. In interpreted mode Rhino does not generate any bytecode but it runs vastly slower. You can try this but I would be surprised if it fixed your problem.

By far your best performance would be to compile your JavaScript code once, then run the compiled scripts over and over again — that is always what you want to do in any kind of server.

So if you’re not running Rhino in an efficient way, I can imagine how bad script performance would affect the overall throughput and latency of your requests. But I don’t understand your comment to the effect that “80-90k classes are being created, which is causing the server to reach max thread limit and hang.”

Rhino doesn’t create threads. There’s no relation between the number of classes that are created and the number of threads your server is creating. Setting up thread pooling and tuning thread pools is out of scope for Rhino itself but it sounds to me like you need to look at that first.

On Thu, Dec 28, 2017 at 12:03 PM Rohan Kumar Jha notifications@github.com wrote:

Hi All, We are using Rhino engine for expression evaluation in our project. When we bring the tomcat server up, the server becomes unresponsive with even single user sometimes, but this happens intermittently. Upon investigating the thread dump, we got the following thread blocking other threads and causing the server to hang.

http-nio-8080-exec-18 Stack Trace is: java.lang.Thread.State: RUNNABLE at org.mozilla.javascript.gen._Unknown_source503912.call() at org.mozilla.javascript.gen._Unknown_source503912.exec() at org.mozilla.javascript.Context.evaluateReader(Context.java:1110) at com.sun.phobos.script.javascript.RhinoScriptEngine.eval(RhinoScriptEngine.java:172) at com.sun.phobos.script.javascript.RhinoScriptEngine.eval(RhinoScriptEngine.java:198) at javax.script.AbstractScriptEngine.eval(AbstractScriptEngine.java:264) at com.asps.parser.Parser.evaluateWithJs(Parser.java:373) at com.asps.parser.Parser.eval(Parser.java:358) at com.asps.parser.Parser.execute(Parser.java:98) at com.asps.parser.Parser.getValues(Parser.java:266) at com.asps.parser.Parser.execute(Parser.java:81) at com.asps.parser.Parser.parse(Parser.java:43) at com.asps.eval.Evaluator.eval(Evaluator.java:10) at com.asps.functioneditor.service.ServiceUtil.testFunction(ServiceUtil.java:172) at com.asps.functioneditor.service.ServiceUtil.run(ServiceUtil.java:80) at com.asps.functioneditor.service.ServiceUtil.run(ServiceUtil.java:62) at com.asps.functioneditor.service.ServiceUtil.run(ServiceUtil.java:62) at com.asps.functioneditor.service.ServiceUtil.run(ServiceUtil.java:62) at com.otx.collections.scripting.scripts.service.ScriptService.evaluateFunctionsForLoan(ScriptService.java:669) at com.otx.collections.scripting.scriptRendering.util.ScriptRenderingUtil.evaluateWidgets(ScriptRenderingUtil.java:1455) at com.otx.collections.scripting.scriptRendering.action.ProcessAccountID.evaluateWidgets(ProcessAccountID.java:748) at com.otx.collections.scripting.scriptRendering.action.ProcessAccountID.evaluateWidgets(ProcessAccountID.java:717) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at ognl.OgnlRuntime.invokeMethod(OgnlRuntime.java:873)

  • locked <0x0000000567bb4100> (a java.lang.reflect.Method) at ognl.OgnlRuntime.callAppropriateMethod(OgnlRuntime.java:1539) at ognl.ObjectMethodAccessor.callMethod(ObjectMethodAccessor.java:68) at com.opensymphony.xwork2.ognl.accessor.XWorkMethodAccessor.callMethodWithDebugInfo(XWorkMethodAccessor.java:96) at com.opensymphony.xwork2.ognl.accessor.XWorkMethodAccessor.callMethod(XWorkMethodAccessor.java:88) at ognl.OgnlRuntime.callMethod(OgnlRuntime.java:1615) at ognl.ASTMethod.getValueBody(ASTMethod.java:91) at ognl.SimpleNode.evaluateGetValueBody(SimpleNode.java:212) at ognl.SimpleNode.getValue(SimpleNode.java:258) at ognl.Ognl.getValue(Ognl.java:467) at ognl.Ognl.getValue(Ognl.java:431) at com.opensymphony.xwork2.ognl.OgnlUtil$3.execute(OgnlUtil.java:351) at com.opensymphony.xwork2.ognl.OgnlUtil.compileAndExecuteMethod(OgnlUtil.java:403) at com.opensymphony.xwork2.ognl.OgnlUtil.callMethod(OgnlUtil.java:349) at com.opensymphony.xwork2.DefaultActionInvocation.invokeAction(DefaultActionInvocation.java:436) at com.opensymphony.xwork2.DefaultActionInvocation.invokeActionOnly(DefaultActionInvocation.java:291) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:252) at org.apache.struts2.interceptor.debugging.DebuggingInterceptor.intercept(DebuggingInterceptor.java:253) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at com.opensymphony.xwork2.interceptor.DefaultWorkflowInterceptor.doIntercept(DefaultWorkflowInterceptor.java:177) at com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:98) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at com.opensymphony.xwork2.validator.ValidationInterceptor.doIntercept(ValidationInterceptor.java:260) at org.apache.struts2.interceptor.validation.AnnotationValidationInterceptor.doIntercept(AnnotationValidationInterceptor.java:73) at com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:98) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at com.opensymphony.xwork2.interceptor.ConversionErrorInterceptor.doIntercept(ConversionErrorInterceptor.java:139) at com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:98) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at com.opensymphony.xwork2.interceptor.ParametersInterceptor.doIntercept(ParametersInterceptor.java:133) at com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:98) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at com.opensymphony.xwork2.interceptor.ParametersInterceptor.doIntercept(ParametersInterceptor.java:133) at com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:98) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at com.opensymphony.xwork2.interceptor.StaticParametersInterceptor.intercept(StaticParametersInterceptor.java:192) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at org.apache.struts2.interceptor.MultiselectInterceptor.intercept(MultiselectInterceptor.java:69) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at org.apache.struts2.interceptor.DateTextFieldInterceptor.intercept(DateTextFieldInterceptor.java:115) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at org.apache.struts2.interceptor.CheckboxInterceptor.intercept(CheckboxInterceptor.java:88) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at org.apache.struts2.interceptor.FileUploadInterceptor.intercept(FileUploadInterceptor.java:246) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at com.opensymphony.xwork2.interceptor.ModelDrivenInterceptor.intercept(ModelDrivenInterceptor.java:99) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at com.opensymphony.xwork2.interceptor.ScopedModelDrivenInterceptor.intercept(ScopedModelDrivenInterceptor.java:139) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at com.opensymphony.xwork2.interceptor.ChainingInterceptor.intercept(ChainingInterceptor.java:155) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at com.opensymphony.xwork2.interceptor.PrepareInterceptor.doIntercept(PrepareInterceptor.java:174) at com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:98) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at org.apache.struts2.interceptor.I18nInterceptor.intercept(I18nInterceptor.java:120) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at org.apache.struts2.interceptor.ServletConfigInterceptor.intercept(ServletConfigInterceptor.java:171) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at com.opensymphony.xwork2.interceptor.AliasInterceptor.intercept(AliasInterceptor.java:195) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at com.opensymphony.xwork2.interceptor.ExceptionMappingInterceptor.intercept(ExceptionMappingInterceptor.java:193) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at com.opensymphony.xwork2.interceptor.StaticParametersInterceptor.intercept(StaticParametersInterceptor.java:192) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at com.opensymphony.xwork2.interceptor.ParametersInterceptor.doIntercept(ParametersInterceptor.java:133) at com.opensymphony.xwork2.interceptor.MethodFilterInterceptor.intercept(MethodFilterInterceptor.java:98) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at org.apache.struts2.interceptor.CheckboxInterceptor.intercept(CheckboxInterceptor.java:88) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at com.otx.collections.common.interceptors.AuthenticateInterceptor.intercept(AuthenticateInterceptor.java:107) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at com.opensymphony.xwork2.interceptor.ExceptionMappingInterceptor.intercept(ExceptionMappingInterceptor.java:193) at com.opensymphony.xwork2.DefaultActionInvocation.invoke(DefaultActionInvocation.java:247) at org.apache.struts2.factory.StrutsActionProxy.execute(StrutsActionProxy.java:54) at org.apache.struts2.dispatcher.Dispatcher.serviceAction(Dispatcher.java:564) at org.apache.struts2.dispatcher.ExecuteOperations.executeAction(ExecuteOperations.java:81) at org.apache.struts2.dispatcher.filter.StrutsPrepareAndExecuteFilter.doFilter(StrutsPrepareAndExecuteFilter.java:143) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:474) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79) at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:624) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:349) at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:783) at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:798) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1434) at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
  • locked <0x00000005676fc3c8> (a org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) at java.lang.Thread.run(Thread.java:745) Locked ownable synchronizers:
  • <0x000000056314c120> (a java.util.concurrent.ThreadPoolExecutor$Worker)

Upon further investigation using java profilers, we saw that some 80-90k classes (not instances) are getting loaded from rhino engine, which is causing the server to reach max thread limit and hang. Classes getting creating almot infinetly are: org.mozilla.javascript.gen.Unknown_source_ org.mozilla.javascript.print Upon source code checkup "org.mozilla.javascript.gen" classes are getting created at Codegen.compile().

Initially, we were using old Rhino version, which was giving above problem, following which we have upgraded the version to 1.7R5 and then to 1.7.7.2, but still getting the same issue.

— You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub https://github.com/mozilla/rhino/issues/374, or mute the thread https://github.com/notifications/unsubscribe-auth/AAf0a7dH0d_n5042ga37SQ6Z171La15Oks5tE8nCgaJpZM4ROfUf .

sachdevk commented 6 years ago

Hi Greg

Thanks for your response. Let me summarize the issue again.

http-nio-8080-exec-200 - priority:5 - threadId:0x00007feaa82bf800 - nativeId:0x2715 - state:RUNNABLE stackTrace: java.lang.Thread.State: RUNNABLE at java.lang.ClassLoader.defineClass1(Native Method) at java.lang.ClassLoader.defineClass(ClassLoader.java:763) at org.mozilla.javascript.DefiningClassLoader.defineClass(DefiningClassLoader.java:27) at org.mozilla.javascript.optimizer.Codegen.defineClass(Codegen.java:130) at org.mozilla.javascript.optimizer.Codegen.createScriptObject(Codegen.java:85)

Thanks Khem

gbrail commented 6 years ago

It’d be interesting to see your whole stack trace since again, Rhino isn’t creating those threads.

If your scripts are indeed so small and you can’t pre-compile them then you might want to try running Rhino in interpreted mode and see how that affects your performance.

On Wed, Jan 3, 2018 at 4:52 AM sachdevk notifications@github.com wrote:

Hi Greg

Thanks for your response. Let me summarize the issue again.

  • Expressions that we are evaluating are really simple e.g. 'asd'=='asd' && true So code looks something like ScriptEngineManager m = new ScriptEngineManager(); engine.eval(strEval); strEval is dynamically populated with above simple expressions.

**- Sometimes when we start the server and everything works perfectly and there are absolutely no issues on any front(performance or otherwise) and we are absolutely happy with RhinoEngine.

-

Some other times post the re-start the response time of engine.eval keeps increasing. It starts with few milli seconds and eventually goes up to seconds.**

Profiler tells us that when the library is not working correctly, thousands of following classes are in the JVM metaspace. org.mozilla.javascript.gen._Unknown_source__35279 org.mozilla.javascript.gen.print_35280 No such classes are seen in Profiler snapshot when the library runs fine as possibly these classes get created and GCed immediately so there is no residue. It seems to me that somewhere the compiled class which got created for evaluating the expression has some byte code issues and hence JVM is stuck on functions related to the Class.

During the times when problem exists, majority of threads are here. As all threads are stuck here so thread pool keeps going up. http-nio-8080-exec-197 - priority:5 - threadId:0x00007fea9c296000 - nativeId:0x2712 - state:RUNNABLE stackTrace: java.lang.Thread.State: RUNNABLE at java.lang.Class.getDeclaredConstructors0(Native Method) at java.lang.Class.privateGetDeclaredConstructors(Class.java:2671) at java.lang.Class.getConstructor0(Class.java:3075) at java.lang.Class.newInstance(Class.java:412) at org.mozilla.javascript.optimizer.Codegen.createScriptObject(Codegen.java:89)

http-nio-8080-exec-200 - priority:5 - threadId:0x00007feaa82bf800 - nativeId:0x2715 - state:RUNNABLE stackTrace: java.lang.Thread.State: RUNNABLE at java.lang.ClassLoader.defineClass1(Native Method) at java.lang.ClassLoader.defineClass(ClassLoader.java:763) at org.mozilla.javascript.DefiningClassLoader.defineClass(DefiningClassLoader.java:27) at org.mozilla.javascript.optimizer.Codegen.defineClass(Codegen.java:130) at org.mozilla.javascript.optimizer.Codegen.createScriptObject(Codegen.java:85)

Thanks Khem

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/mozilla/rhino/issues/374#issuecomment-354972764, or mute the thread https://github.com/notifications/unsubscribe-auth/AAf0a0UTnhXaU9ToEjlMftbLoI8O78SMks5tG03PgaJpZM4ROfUf .

sachdevk commented 6 years ago

Thanks Greg for the response.

We kind of cracked it just few minutes ago. We have following three libraries in our WEB-INF/lib. js.jar js-engine.jar rhino-script-engine-1.1.1 Out of this rhino-script-engine-1.1.1 and js-engine.jar are actually conflicting implementations which actually map to same shortname of the engine. So when we call m.getEngineByName("rhino") anyone of the them can be returned. Whenever it returns the one from js-engine.jar which is actually an implemention from com.sun.phobos.script.javascript.RhinoScriptEngine, it doesn't work. At some other time post restart the engine picked up could be de.christophkraemer.rhino.javascript.RhinoScriptEngine and then it works. So that is why the restart seemed to decide everything. So removing either js-engine.jar or rhino-script-engine-1.1.1 solves the problem. So individually both libraries are fine but when we have them both in the web-in/lib it becomes a problem.

Do you know in JDK1.8/Tomcat 8.5 on what basis the rhino engine will get picked up(timestamp, alphabetically). Because if nothing has changed on the server then it should pick up the same one every time(right or wrong). It was fine if it picks up the wrong one or the right one every time but the randomness is what killed us in tying to get to the root cause. If you know it will help us with the root cause. We know the fix for now.

gbrail commented 6 years ago

Sorry -- I don't know enough about how script engine evaluation works and I suspect it's nondeterministic and could depend on anything from hash algorithms on different JVMs to the order in which your filesystem presents the results of a directory list...

On Wed, Jan 3, 2018 at 5:41 AM, sachdevk notifications@github.com wrote:

Thanks Greg for the response.

We kind of cracked it just few minutes ago. We have following three libraries in our WEB-INF/lib. js.jar js-engine.jar rhino-script-engine-1.1.1 Out of this rhino-script-engine-1.1.1 and js-engine.jar are actually conflicting implementations which actually map to same shortname of the engine. So when we call m.getEngineByName("rhino") anyone of the them can be returned. Whenever it returns the one from js-engine.jar which is actually an implemention from com.sun.phobos.script.javascript.RhinoScriptEngine, it doesn't work. At some other time post restart the engine picked up could be de.christophkraemer.rhino.javascript.RhinoScriptEngine and then it works. So that is why the restart seemed to decide everything. So removing either js-engine.jar or rhino-script-engine-1.1.1 solves the problem. So individually both libraries are fine but when we have them both in the web-in/lib it becomes a problem.

Do you know in JDK1.8/Tomcat 8.5 on what basis the rhino engine will get picked up(timestamp, alphabetically). Because if nothing has changed on the server then it should pick up the same one every time(right or wrong). It was fine if it picks up the wrong one or the right one every time but the randomness is what killed us in tying to get to the root cause. If you know it will help us with the root cause. We know the fix for now.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/mozilla/rhino/issues/374#issuecomment-355014231, or mute the thread https://github.com/notifications/unsubscribe-auth/AAf0a91IgsZIjyZ5K_lJSNaIDTUNGIKeks5tG4OdgaJpZM4ROfUf .

sachdevk commented 6 years ago

Ok.. Thanks for the help..

A-Herzog commented 5 years ago

May I can help about this. I have experienced the same problem in some project. Not Rhino is creating so many classes, but rhino-js-engine. In RhinoScriptEngine.java there is a static string printSource. Each time a compiled script is executed, this string is compiled again and added to the scope. (Yes, on each execution of the compiled script the string is compiled to a new class.) See RhinoScriptEngine.getRuntimeScope(ScriptContext ctxt); If the scope is cached, Rhito gets faster by factor 30:

The test case: Javascript code was var value=0; for (var i=0;i<10;i++) value+=connect.increment(i); value; with bindings.put("connect",new ConnectDummyObj()) and

public class ConnectDummyObj {
    public int increment(final int value) {
        return value+1;
    }
}

Adding this

private ThreadLocal<Map<ScriptContext,Scriptable>> scopeCache=new ThreadLocal<Map<ScriptContext,Scriptable>>() {
    @Override
    protected Map<ScriptContext,Scriptable> initialValue() {
        return new HashMap<>();
    }
};

to RhinoScriptEngine and then

Map<ScriptContext,Scriptable> map=scopeCache.get();
Scriptable cachedScope=map.get(ctxt);
if (cachedScope!=null) return cachedScope;

Scriptable newScope = new ExternalScriptable(ctxt, indexedProps);
map.put(ctxt,newScope); 

to RhinoScriptEngine.getRuntimeScope(ScriptContext ctxt) solves the problem for me. I'm not sure if the caching is done correctly but it works even in a multi threaded environment for me perfectly.

Maybe rhino-js-engine could be added some day to rhino itself for better maintainance?

There are also some performance problems in rhino itself, for example functions like callFunc(Object param) {callFuncInt(new Object[]{param});} which keeps the garbage collector busy (due to many short living Object[1] objects to be removed). I will have a closer look at this as soon as I get rhino to run in source mode outside the jar (still having some module problems).

sachdevk commented 5 years ago

What you mentioned could have not been the problem. But we found that the following solves the issue.

Following libraries present in WEB-INF/lib are conflicting and competing libraries js-engine.jar rhino-1.1.jar

If both the libraries are present and during server startup if the classes in js-engine.jar get loaded in JVM first then due to some internal clash the application becomes progressively slow as the time passes. If rhino-1.1.jar is picked up at startup time then everything works fine.

js-engine.jar was removed and post this we didn't experience any issues.

A-Herzog commented 5 years ago

js-engine.jar is used to make rhino available via the Java scripting API. If you remove js-engine.jar and you request a Javascript engine object via ScriptEngineManager, you will get a nashorn engine (as long as nashorn is integrated into Java). So of cource there won't be any org.mozilla.javascript classes anymore.

sachdevk commented 5 years ago

Yeah that's the reason problem started coming only since we upgraded to JDK8 which has nashhorn as the default.

p-bakker commented 3 years ago

Are there any actionable items left from this case?

Maybe some optimizations from comment https://github.com/mozilla/rhino/issues/374#issuecomment-451573202 to go into out Script Engine wrapper?

Otherwise I think we can close this case