Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8177098

Nashorn's ScriptEngine.eval() increases minor GC times (JNI Weak Reference processing time)

XMLWordPrintable

      FULL PRODUCT VERSION :
      java version "1.8.0_121"
      Java(TM) SE Runtime Environment (build 1.8.0_121-b13)
      Java HotSpot(TM) 64-Bit Server VM (build 25.121-b13, mixed mode)


      ADDITIONAL OS VERSION INFORMATION :
      Linux mylaptop 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt20-1+deb8u4 (2016-02-29) x86_64 GNU/Linux

      A DESCRIPTION OF THE PROBLEM :
      When I repeatedly evaluate javascript using Nashorn's ScriptEngine, the garbage collection time starts to increase. Using "-XX:+PrintReferenceGC" revealed that "JNI Weak Reference" processing time is the only one which is steadily increasing, other numbers are fine.
      Even a full GC cannot help in this situation.

      For example, this is a line of gc.log after having run the sample code for 15 seconds:
      15.517: [GC (Allocation Failure) 15.517: [SoftReference, 0 refs, 0.0000601 secs]15.517: [WeakReference, 0 refs, 0.0000249 secs]15.518: [FinalReference, 0 refs, 0.0000661 secs]15.518: [PhantomReference, 0 refs, 0 refs, 0.0000272 secs]15.518: [JNI Weak Reference, 0.0031223 secs][PSYoungGen: 22048K->32K(22528K)] 25156K->3140K(91136K), 0.0046839 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

      And this is a line of gc.log after having run the sample code for 241 seconds:
      241.723: [GC (Allocation Failure) 241.724: [SoftReference, 0 refs, 0.0000404 secs]241.724: [WeakReference, 0 refs, 0.0000214 secs]241.724: [FinalReference, 0 refs, 0.0000204 secs]241.724: [PhantomReference, 0 refs, 0 refs, 0.0000252 secs]241.724: [JNI Weak Reference, 0.0330042 secs][PSYoungGen: 32832K->0K(33280K)] 35940K->3108K(101888K), 0.0343699 secs] [Times: user=0.04 sys=0.00, real=0.03 secs]

      Notice that "JNI Weak Reference" processing time increased from 0.0031223 secs secs to 0.0330042secs, i.e. 10x larger.
      Between these two samples (and after), the "JNI Weak Reference" processing time steadily increases.
      Not only minor GC times are affected, but also full GC times (i.e. any collection that performs JNI Weak Reference processing).

      I run 'jmap -histo:live' multiple times during the lifetime of the JVM, and there is no remarkable difference in the number of objects.

      Another related issue: the resident set size (RSS) of the java process is increasing at a rate of about 1 MB / second.


      STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
      Compile the java code below:

      import jdk.nashorn.api.scripting.NashornScriptEngineFactory;
      import javax.script.ScriptEngine;
      public class ReproduceBug {
         public static void main(String[] args) throws Exception {
            ScriptEngine engine = new NashornScriptEngineFactory().getScriptEngine();
            while (true) engine.eval("var x = 5;");
         }
      }

      And run it with the following args:
      java -Xmx100m -verbose:gc -XX:+PrintGCDetails -XX:+PrintReferenceGC -XX:+PrintGCTimeStamps ReproduceBug

      And notice on the stdout that "JNI Weak Reference" processing time is increasing.


      EXPECTED VERSUS ACTUAL BEHAVIOR :
      EXPECTED -
      "JNI Weak Reference" processing time should not increase.

      ACTUAL -
      "JNI Weak Reference" processing time is increasing at a constant rate.


      REPRODUCIBILITY :
      This bug can be reproduced always.

      ---------- BEGIN SOURCE ----------
      import jdk.nashorn.api.scripting.NashornScriptEngineFactory;
      import javax.script.ScriptEngine;
      public class ReproduceBug {
         public static void main(String[] args) throws Exception {
            ScriptEngine engine = new NashornScriptEngineFactory().getScriptEngine();
            while (true) engine.eval("var x = 5;");
         }
      }

      ---------- END SOURCE ----------

      CUSTOMER SUBMITTED WORKAROUND :
      If I create a new instance of NashornScriptEngineFactory every time, the issue is workarounded:

      import jdk.nashorn.api.scripting.NashornScriptEngineFactory;
      import javax.script.ScriptEngine;
      public class Workaround {
         public static void main(String[] args) throws Exception {
            while (true) {
               ScriptEngine engine = new NashornScriptEngineFactory().getScriptEngine();
               engine.eval("var x = 5;");
            }
         }
      }


        1. 8u121logfile.txt
          100 kB
        2. 9ea161out.txt
          270 kB
        3. JI9048111.java
          0.3 kB

            sdama Srinivas Dama (Inactive)
            webbuggrp Webbug Group
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated:
              Resolved: