Performance issues

Michel Krämer michel at undercouch.de
Thu Feb 20 04:13:25 PST 2014 

Dear Sundar,

Here's the minimal example:
http://storage.spamihilator.com/public.php?service=files&t=23b6d2e601bca81d461c26c050c0669c&download

Just unzip the file and run the following command:

java -Xmx1024M -cp . MinimalExample

It runs the complete test suite. Some tests fail, but that's OK. Here 
are my timings:

Rhino (JDK7):

Total time: 394.80 secs
Time construct: 0.38 secs
Time parse: 25.07 secs
Time run: 368.71 secs
747 of 758 tests successful.

Nashorn:

Total time: 1168.16 secs
Time construct: 3.25 secs
Time parse: 309.84 secs
Time run: 853.91 secs
747 of 758 tests successful.

The tests are slower than before because there's only one thread. In 
citeproc-java multiple threads are used instead. However, the 
performance difference is still quite noticeable. Nashorn is almost 3 
times slower. It takes a lot more time to parse the JavaScript and also 
execution time is longer.

Hope this helps!

Michel


Am 20.02.2014 09:30, schrieb A. Sundararajan:
> I was trying to do proper comparison and get to the actual difference
> between the two implementations being compared. Only then we could
> narrow down and suggest/investigate options.
>
> Btw, you can trace callsite misses by -tcs (or --trace-callsites) option
> of 'jjs' tool. The same option can also be specified by the System
> property "nashorn.args". For example:
>
>      jjs -tcs myscript.js
>      java -Dnashorn.args=-tcs -jar MyJar.jar
>
> All command line options supported can be seen from
>
>      jjs -xhelp
>
> Looking forward to your minimal example.
>
> Thanks
> -Sundar
>
>
> On Thursday 20 February 2014 01:52 PM, Michel Krämer wrote:
>> OK. I understand that the code base is too large to debug. I thought
>> you could just tell me some magic parameter to trace down callsite
>> misses or whatever *LOL* but it seems to be more complicated.
>>
>> I'll try to compile a minimal example executing the javascript code,
>> in order to rule out everything related to the way Nashorn is called.
>> I'll get back to you.
>>
>> Thanks!
>> Michel
>>
>>
>> Am 20.02.2014 09:15, schrieb A. Sundararajan:
>>> Since I can't clean/run on jdk7 - nor don't understand the code base
>>> much, I suggest you do the following (when I try to figure out ways to
>>> clean /build/run at my end).
>>>
>>> * You can use javax.script.Invocable interface's methods to invoke
>>> specific functions rather than doing 'eval' of function/method calls.
>>>
>>> * You can also call specific object methods by invokeMethod method.
>>>
>>> * To have proper comparison, we should do Json as string and eval in
>>> both cases or have Scriptable-like access + call method in nashorn. If
>>> the former is not possible,  I suggest go through
>>> https://wiki.openjdk.java.net/display/Nashorn/Nashorn+jsr223+engine+notes
>>>
>>>
>>> * Because of string json and eval-for-method, there are lot more evals
>>> with nashorn/javax.script. Yes - that is the same with
>>> rhino+jdk7+javax.script. But unfortunately I couldn't run that mode at
>>> my end (yet).
>>>
>>> * It is possible to access construct object and put properties in it by
>>> ScriptObjectMirror/Bindings/JSObject interface on every script object
>>>
>>> Thanks
>>> -Sundar
>>>
>>>
>>> On Thursday 20 February 2014 01:40 PM, Michel Krämer wrote:
>>>> Hi!
>>>>
>>>> Replacing RhinoJsonBuilder by StringJsonBuilder will not work. The way
>>>> Rhino is run either directly or through the Script API is just too
>>>> different.
>>>>
>>>> I checked the line the first error occured in (build.gradle:230). It
>>>> seems you can just remove everything from line 210 to the end of the
>>>> file. It should still run and the error might probably be gone.
>>>>
>>>> There are other possibilities to run the test suite, but there more
>>>> complicated. Let's try this one first.
>>>>
>>>> Cheers,
>>>> Michel
>>>>
>>>>
>>>> Am 20.02.2014 08:32, schrieb A. Sundararajan:
>>>>> Hi Michel,
>>>>>
>>>>> Nope. Doesn't seem to help. BTW, I did clean last time too - didn't do
>>>>> git clean. But this time I did that as well.
>>>>>
>>>>> I thought I'll do this and check
>>>>>
>>>>> diff --git
>>>>> a/src/main/java/de/undercouch/citeproc/script/RhinoScriptRunner.java
>>>>> index d2524d2..21a5281 100644
>>>>> ---
>>>>> a/src/main/java/de/undercouch/citeproc/script/RhinoScriptRunner.java
>>>>> +++
>>>>> b/src/main/java/de/undercouch/citeproc/script/RhinoScriptRunner.java
>>>>> @@ -31,6 +31,7 @@ import org.mozilla.javascript.Wrapper;
>>>>>
>>>>>   import de.undercouch.citeproc.helper.CSLUtils;
>>>>>   import de.undercouch.citeproc.helper.json.JsonBuilder;
>>>>> +import de.undercouch.citeproc.helper.json.StringJsonBuilder;
>>>>>
>>>>>   /**
>>>>>    * Executes JavaScript scripts using Mozilla Rhino
>>>>> @@ -204,7 +205,8 @@ public class RhinoScriptRunner extends
>>>>> AbstractScriptRunner
>>>>>
>>>>>          @Override
>>>>>          public JsonBuilder createJsonBuilder() {
>>>>> -               return new RhinoJsonBuilder(scope, this);
>>>>> +                return new StringJsonBuilder(this);
>>>>> +               // return new RhinoJsonBuilder(scope, this);
>>>>>          }
>>>>>
>>>>>
>>>>> Basically making sure both nashorn and rhino use the same json
>>>>> mechanism
>>>>> (rhino json builder uses Scriptable - just wanted to see how far that
>>>>> difference contributes).
>>>>>
>>>>>
>>>>> When I did clean and re-build - this time with jdk8,
>>>>>
>>>>> I got this:
>>>>>
>>>>> Using script runner: Mozilla Rhino 1.7 release 4 2012 06 18
>>>>> :runTestSuite FAILED
>>>>>
>>>>> FAILURE: Build failed with an exception.
>>>>>
>>>>> * Where:
>>>>> Build file '/home/sundar/src/citeproc-java/build.gradle' line: 128
>>>>>
>>>>> * What went wrong:
>>>>> Execution failed for task ':runTestSuite'.
>>>>>  > java.util.concurrent.ExecutionException:
>>>>> java.lang.IllegalArgumentException: Could not update items
>>>>>
>>>>> * Try:
>>>>> Run with --stacktrace option to get the stack trace. Run with
>>>>> --info or
>>>>> --debug option to get more log output.
>>>>>
>>>>> BUILD FAILED
>>>>>
>>>>> Total time: 3 mins 35.962 secs
>>>>>
>>>>> If there is anyway to avoid gradle dependency and run it straight -
>>>>> say
>>>>> by 'ant' or some such, it would be very useful.
>>>>>
>>>>> Thanks
>>>>> -Sundar
>>>>>
>>>>> On Thursday 20 February 2014 12:00 PM, Michel Krämer wrote:
>>>>>> Dear Sundar,
>>>>>>
>>>>>> Thanks for your help. I see that you familiarized yourself with the
>>>>>> code already. I appreciate that very much!
>>>>>>
>>>>>> You're right, when you run it in 'rhino' mode it will use code
>>>>>> optimized for Rhino. However, you're also right, it should use JDK7's
>>>>>> embedded Rhino when you run it in 'jre' mode under JDK7.
>>>>>>
>>>>>> I've never seen this error message before. citeproc-java itself does
>>>>>> not use any logging mechanism, but I know that Gradle does. So, the
>>>>>> error must have something to do with Gradle or the particular Gradle
>>>>>> version you're running. Is there another Gradle version already
>>>>>> installed on your system? Please make sure to run the gradlew script
>>>>>> in the project's root directory. It automatically downloads the right
>>>>>> Gradle version. Also make sure to run `./gradlew clean' or even `git
>>>>>> clean -fdx', just in case.
>>>>>>
>>>>>> I hope this helps. Please tell me if the problem persists.
>>>>>>
>>>>>> Thanks,
>>>>>> Michel
>>>>>>
>>>>>>
>>>>>> Am 20.02.2014 04:36, schrieb A. Sundararajan:
>>>>>>> Hi,
>>>>>>>
>>>>>>> Thanks for writing to us.
>>>>>>>
>>>>>>> Two things:
>>>>>>>
>>>>>>> 1) 'rhino' mode uses Rhino's API directly (Context ..). For
>>>>>>> nashorn, it
>>>>>>> uses 'javax.script' engine API. I thought may be on jdk7, I could
>>>>>>> run
>>>>>>> 'jre' mode and try jdk7's embedded rhino based javax.script engine.
>>>>>>> After clean and re-run test with jdk7 results in
>>>>>>>
>>>>>>>
>>>>>>> FAILURE: Build failed with an exception.
>>>>>>>
>>>>>>> * Where:
>>>>>>> Build file '/home/sundar/src/citeproc-java/build.gradle' line: 230
>>>>>>>
>>>>>>> * What went wrong:
>>>>>>> A problem occurred evaluating root project 'citeproc-java'.
>>>>>>>  >
>>>>>>> org.slf4j.spi.LocationAwareLogger.log(Lorg/slf4j/Marker;Ljava/lang/String;ILjava/lang/String;[Ljava/lang/Object;Ljava/lang/Throwable;)V
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>> * Try:
>>>>>>> Run with --stacktrace option to get the stack trace. Run with
>>>>>>> --info or
>>>>>>> --debug option to get more log output.
>>>>>>>
>>>>>>> BUILD FAILED
>>>>>>>
>>>>>>> With jdk8, 'jre' and 'rhino' mode run fine
>>>>>>>
>>>>>>> 2) Json handling for rhino uses RhinoJsonBuilder which uses
>>>>>>> Scriptable
>>>>>>> of Rhino. For nashorn, it uses 'string json builder' - which
>>>>>>> presumably
>>>>>>> involves more string handling?
>>>>>>>
>>>>>>> If you can tell me how to run with jdk7, then perhaps we can have
>>>>>>> proper
>>>>>>> comparison. 'jre' mode on jdk7 with rhino javax.script engine and
>>>>>>> 'jre'
>>>>>>> mode on jdk8  with nashorn javax.script engine.
>>>>>>>
>>>>>>> Thanks
>>>>>>> -Sundar
>>>>>>>
>>>>>>>
>>>>>>> On Wednesday 19 February 2014 09:09 PM, Michel Krämer wrote:
>>>>>>>> Hi folks,
>>>>>>>>
>>>>>>>> I'm experiencing very drastic performance issues with Nashorn
>>>>>>>> (JDK 8
>>>>>>>> b129) compared to Rhino. My script takes almost 13 minutes
>>>>>>>> instead of
>>>>>>>> 16 seconds! I hope you guys can tell me what's going on here.
>>>>>>>>
>>>>>>>> I've recently tested citeproc-java
>>>>>>>> (https://github.com/michel-kraemer/citeproc-java) under JDK8 in
>>>>>>>> order
>>>>>>>> to make sure it keeps running flawlessly when the next Java version
>>>>>>>> comes out. citeproc-java uses citeproc-js under the hood which is a
>>>>>>>> rather large JavaScript library consisting of one file of about 540
>>>>>>>> KB, 13.500 lines of code
>>>>>>>> (https://bitbucket.org/fbennett/citeproc-js/wiki/Home).
>>>>>>>>
>>>>>>>> Previously I used Rhino to execute the JavaScript and it worked
>>>>>>>> quite
>>>>>>>> well. There is a test suite consisting of 758 tests. Running this
>>>>>>>> suite takes about 16 seconds (JavaScript compiled to byte code)
>>>>>>>> or 46
>>>>>>>> secs (interpreted JavaScript). However, if I try to run the same
>>>>>>>> test
>>>>>>>> suite with Oracle Nashorn it takes 12.5 minutes! (see timings
>>>>>>>> below)
>>>>>>>>
>>>>>>>> This is a very drastic performance drop and I was very surprised to
>>>>>>>> see this. Is there some way to debug Nashorn in order to find out
>>>>>>>> what
>>>>>>>> is actually going on here?
>>>>>>>>
>>>>>>>> Timings on my computer (i5-3570K, 3.4 GHz, 4 cores, 16 GB RAM):
>>>>>>>>
>>>>>>>> Rhino 1.7R4 (JavaScript compiled to byte code):
>>>>>>>> 16.176 secs
>>>>>>>>
>>>>>>>> Rhino 1.7R3 (bundled w/ JDK 7, interpreted JavaScript):
>>>>>>>> 45.970 secs
>>>>>>>>
>>>>>>>> Nashorn (JDK 8 b129):
>>>>>>>> 754.266 secs
>>>>>>>>
>>>>>>>> Steps to reproduce (no prerequisites other than JDK8):
>>>>>>>>
>>>>>>>> git clone https://github.com/michel-kraemer/citeproc-java.git
>>>>>>>> cd citeproc-java
>>>>>>>> ./gradlew runTestSuite -PscriptRunnerType=rhino
>>>>>>>> ./gradlew runTestSuite -PscriptRunnerType=jre
>>>>>>>>
>>>>>>>> Cheers,
>>>>>>>> Michel
>>>>>>>
>>>>>>>
>>>>>
>>>>>
>>>
>>>
>
>

More information about the nashorn-dev mailing list