From ca229694dc036210ad9e7ae2fc32134720b48d1b Mon Sep 17 00:00:00 2001 From: BrynCooke Date: Thu, 2 Mar 2017 19:07:28 +0000 Subject: [PATCH 1/5] TINKERPOP-1644 Improve script compilation syncronisation Script compilation is synchronised. Script compilation times are placed in to logs. Failed scripts will not be recompiled. Scripts that take over 5 seconds to compile are logged as a warning. --- CHANGELOG.asciidoc | 4 ++ .../jsr223/GremlinGroovyScriptEngine.java | 57 +++++++++++++++++-- 2 files changed, 56 insertions(+), 5 deletions(-) diff --git a/CHANGELOG.asciidoc b/CHANGELOG.asciidoc index 8cc2adccf90..837da4d9017 100644 --- a/CHANGELOG.asciidoc +++ b/CHANGELOG.asciidoc @@ -26,6 +26,10 @@ image::https://raw.githubusercontent.com/apache/tinkerpop/master/docs/static/ima TinkerPop 3.2.5 (Release Date: NOT OFFICIALLY RELEASED YET) ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +* Script compilation is synchronised. +* Script compilation times are placed in to logs. +* Failed scripts will not be recompiled. +* Scripts that take over 5 seconds to compile are logged as a warning. * Split `ComputerVerificationStrategy` into two strategies: `ComputerVerificationStrategy` and `ComputerFinalizationStrategy`. * Removed `HasTest.g_V_hasId_compilationEquality` from process test suite as it makes too many assumptions about provider compilation. * Deprecated `CustomizerProvider` infrastructure. diff --git a/gremlin-groovy/src/main/java/org/apache/tinkerpop/gremlin/groovy/jsr223/GremlinGroovyScriptEngine.java b/gremlin-groovy/src/main/java/org/apache/tinkerpop/gremlin/groovy/jsr223/GremlinGroovyScriptEngine.java index 1fb2efcf5e0..a8365a269b0 100644 --- a/gremlin-groovy/src/main/java/org/apache/tinkerpop/gremlin/groovy/jsr223/GremlinGroovyScriptEngine.java +++ b/gremlin-groovy/src/main/java/org/apache/tinkerpop/gremlin/groovy/jsr223/GremlinGroovyScriptEngine.java @@ -56,6 +56,8 @@ import org.codehaus.groovy.runtime.MetaClassHelper; import org.codehaus.groovy.runtime.MethodClosure; import org.codehaus.groovy.util.ReferenceBundle; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; import javax.script.Bindings; import javax.script.CompiledScript; @@ -93,6 +95,7 @@ public class GremlinGroovyScriptEngine extends GroovyScriptEngineImpl implements DependencyManager, AutoCloseable, GremlinScriptEngine { + private static final Logger log = LoggerFactory.getLogger(GremlinGroovyScriptEngine.class); /** * An "internal" key for sandboxing the script engine - technically not for public use. */ @@ -153,6 +156,7 @@ protected Map initialValue() { * Script to generated Class map. */ private ManagedConcurrentValueMap classMap = new ManagedConcurrentValueMap<>(ReferenceBundle.getSoftBundle()); + private ManagedConcurrentValueMap failedClassMap = new ManagedConcurrentValueMap<>(ReferenceBundle.getSoftBundle()); /** * Global closures map - this is used to simulate a single global functions namespace @@ -529,13 +533,56 @@ public T getInterface(final Object thiz, final Class clazz) { return makeInterface(thiz, clazz); } + private Class getScriptClassFromMap(String script) throws CompilationFailedException { + CompilationFailedException exception = failedClassMap.get(script); + if(exception != null) { + throw exception; + } + return classMap.get(script); + + } + Class getScriptClass(final String script) throws CompilationFailedException { - Class clazz = classMap.get(script); - if (clazz != null) return clazz; + Class clazz = getScriptClassFromMap(script); + if (clazz != null) { + return clazz; + } + synchronized (this) { + clazz = getScriptClassFromMap(script); + if (clazz != null) { + return clazz; + } - clazz = loader.parseClass(script, generateScriptName()); - classMap.put(script, clazz); - return clazz; + long start = System.currentTimeMillis(); + try { + clazz = loader.parseClass(script, generateScriptName()); + long time = System.currentTimeMillis() - start; + if(time > 5000) { + //We warn if a script took longer than a few seconds. Repeatedly seeing these warnings is a sign that something is wrong. + //Scripts with a large numbers of parameters often trigger this and should be avoided. + log.warn("Script compilation {} took {}ms", script, time); + } + else { + log.debug("Script compilation {} took {}ms", script, time); + } + + + } + catch(CompilationFailedException t) { + long finish = System.currentTimeMillis(); + log.error("Script compilation FAILED {} took {}ms {}", script, finish - start, t); + failedClassMap.put(script, t); + throw t; + } + catch(Throwable t) { + long finish = System.currentTimeMillis(); + log.error("Script compilation FAILED with throwable {} took {}ms {}", script, finish - start, t); + throw t; + } + classMap.put(script, clazz); + + return clazz; + } } boolean isCached(final String script) { From 7200ef30b7928b1ee50fe665159bac20974c592a Mon Sep 17 00:00:00 2001 From: BrynCooke Date: Tue, 7 Mar 2017 16:54:58 +0000 Subject: [PATCH 2/5] TINKERPOP-1644 Use future instead of maintaining a separate map of failures. --- .../jsr223/GremlinGroovyScriptEngine.java | 69 +++++++------------ 1 file changed, 26 insertions(+), 43 deletions(-) diff --git a/gremlin-groovy/src/main/java/org/apache/tinkerpop/gremlin/groovy/jsr223/GremlinGroovyScriptEngine.java b/gremlin-groovy/src/main/java/org/apache/tinkerpop/gremlin/groovy/jsr223/GremlinGroovyScriptEngine.java index a8365a269b0..67275f8e1b2 100644 --- a/gremlin-groovy/src/main/java/org/apache/tinkerpop/gremlin/groovy/jsr223/GremlinGroovyScriptEngine.java +++ b/gremlin-groovy/src/main/java/org/apache/tinkerpop/gremlin/groovy/jsr223/GremlinGroovyScriptEngine.java @@ -79,6 +79,8 @@ import java.util.Map; import java.util.ServiceLoader; import java.util.Set; +import java.util.concurrent.CompletableFuture; +import java.util.concurrent.Future; import java.util.concurrent.atomic.AtomicLong; import java.util.regex.Pattern; import java.util.stream.Collectors; @@ -155,8 +157,7 @@ protected Map initialValue() { /** * Script to generated Class map. */ - private ManagedConcurrentValueMap classMap = new ManagedConcurrentValueMap<>(ReferenceBundle.getSoftBundle()); - private ManagedConcurrentValueMap failedClassMap = new ManagedConcurrentValueMap<>(ReferenceBundle.getSoftBundle()); + private ManagedConcurrentValueMap> classMap = new ManagedConcurrentValueMap<>(ReferenceBundle.getSoftBundle()); /** * Global closures map - this is used to simulate a single global functions namespace @@ -533,56 +534,38 @@ public T getInterface(final Object thiz, final Class clazz) { return makeInterface(thiz, clazz); } - private Class getScriptClassFromMap(String script) throws CompilationFailedException { - CompilationFailedException exception = failedClassMap.get(script); - if(exception != null) { - throw exception; - } - return classMap.get(script); - - } - Class getScriptClass(final String script) throws CompilationFailedException { - Class clazz = getScriptClassFromMap(script); - if (clazz != null) { - return clazz; - } - synchronized (this) { - clazz = getScriptClassFromMap(script); + Future clazz = classMap.get(script); + + long start = System.currentTimeMillis(); + try { if (clazz != null) { - return clazz; + return clazz.get(); } - long start = System.currentTimeMillis(); - try { - clazz = loader.parseClass(script, generateScriptName()); - long time = System.currentTimeMillis() - start; - if(time > 5000) { - //We warn if a script took longer than a few seconds. Repeatedly seeing these warnings is a sign that something is wrong. - //Scripts with a large numbers of parameters often trigger this and should be avoided. - log.warn("Script compilation {} took {}ms", script, time); - } - else { - log.debug("Script compilation {} took {}ms", script, time); - } - + clazz = CompletableFuture.supplyAsync(() -> loader.parseClass(script, generateScriptName())); + classMap.put(script, clazz); + return clazz.get(); - } - catch(CompilationFailedException t) { + } catch (Exception e) { + if (e.getCause() instanceof CompilationFailedException) { long finish = System.currentTimeMillis(); - log.error("Script compilation FAILED {} took {}ms {}", script, finish - start, t); - failedClassMap.put(script, t); - throw t; + log.error("Script compilation FAILED {} took {}ms {}", script, finish - start, e.getCause()); + throw (CompilationFailedException) e.getCause(); + } else { + throw new AssertionError("Unexpected exception when compiling script", e); } - catch(Throwable t) { - long finish = System.currentTimeMillis(); - log.error("Script compilation FAILED with throwable {} took {}ms {}", script, finish - start, t); - throw t; + } finally { + long time = System.currentTimeMillis() - start; + if (time > 5000) { + //We warn if a script took longer than a few seconds. Repeatedly seeing these warnings is a sign that something is wrong. + //Scripts with a large numbers of parameters often trigger this and should be avoided. + log.warn("Script compilation {} took {}ms", script, time); + } else { + log.debug("Script compilation {} took {}ms", script, time); } - classMap.put(script, clazz); - - return clazz; } + } boolean isCached(final String script) { From 198564449127b96bf1a4d5c1284ebd4e321bc60a Mon Sep 17 00:00:00 2001 From: BrynCooke Date: Wed, 8 Mar 2017 12:24:46 +0000 Subject: [PATCH 3/5] TINKERPOP-1644 Use Caffeine cache --- gremlin-groovy/pom.xml | 5 ++ .../jsr223/GremlinGroovyScriptEngine.java | 75 +++++++++++-------- 2 files changed, 48 insertions(+), 32 deletions(-) diff --git a/gremlin-groovy/pom.xml b/gremlin-groovy/pom.xml index 511952aee49..474b458fb16 100644 --- a/gremlin-groovy/pom.xml +++ b/gremlin-groovy/pom.xml @@ -70,6 +70,11 @@ limitations under the License. jbcrypt 0.4 + + com.github.ben-manes.caffeine + caffeine + 2.3.1 + org.slf4j diff --git a/gremlin-groovy/src/main/java/org/apache/tinkerpop/gremlin/groovy/jsr223/GremlinGroovyScriptEngine.java b/gremlin-groovy/src/main/java/org/apache/tinkerpop/gremlin/groovy/jsr223/GremlinGroovyScriptEngine.java index 67275f8e1b2..51850adb3bc 100644 --- a/gremlin-groovy/src/main/java/org/apache/tinkerpop/gremlin/groovy/jsr223/GremlinGroovyScriptEngine.java +++ b/gremlin-groovy/src/main/java/org/apache/tinkerpop/gremlin/groovy/jsr223/GremlinGroovyScriptEngine.java @@ -18,6 +18,9 @@ */ package org.apache.tinkerpop.gremlin.groovy.jsr223; +import com.github.benmanes.caffeine.cache.CacheLoader; +import com.github.benmanes.caffeine.cache.Caffeine; +import com.github.benmanes.caffeine.cache.LoadingCache; import groovy.grape.Grape; import groovy.lang.Binding; import groovy.lang.Closure; @@ -80,6 +83,8 @@ import java.util.ServiceLoader; import java.util.Set; import java.util.concurrent.CompletableFuture; +import java.util.concurrent.ExecutionException; +import java.util.concurrent.Executor; import java.util.concurrent.Future; import java.util.concurrent.atomic.AtomicLong; import java.util.regex.Pattern; @@ -154,17 +159,44 @@ protected Map initialValue() { } }; + private GremlinGroovyClassLoader loader; + /** * Script to generated Class map. */ - private ManagedConcurrentValueMap> classMap = new ManagedConcurrentValueMap<>(ReferenceBundle.getSoftBundle()); + private LoadingCache> classMap = Caffeine.newBuilder().softValues().build(new CacheLoader>() { + @Override + public Future load(String script) throws Exception { + long start = System.currentTimeMillis(); + try { + return CompletableFuture.supplyAsync(() -> loader.parseClass(script, generateScriptName()), command -> command.run()); + } catch (Exception e) { + if (e.getCause() instanceof CompilationFailedException) { + long finish = System.currentTimeMillis(); + log.error("Script compilation FAILED {} took {}ms {}", script, finish - start, e.getCause()); + throw (CompilationFailedException) e.getCause(); + } else { + throw new AssertionError("Unexpected exception when compiling script", e); + } + } finally { + long time = System.currentTimeMillis() - start; + if (time > 5000) { + //We warn if a script took longer than a few seconds. Repeatedly seeing these warnings is a sign that something is wrong. + //Scripts with a large numbers of parameters often trigger this and should be avoided. + log.warn("Script compilation {} took {}ms", script, time); + } else { + log.debug("Script compilation {} took {}ms", script, time); + } + } + } + + }); /** * Global closures map - this is used to simulate a single global functions namespace */ private ManagedConcurrentValueMap globalClosures = new ManagedConcurrentValueMap<>(ReferenceBundle.getHardBundle()); - private GremlinGroovyClassLoader loader; private AtomicLong counter = new AtomicLong(0L); @@ -420,7 +452,7 @@ private void internalReset() { // must clear the local cache here because the classloader has been reset. therefore, classes previously // referenced before that might not have evaluated might cleanly evaluate now. - classMap.clear(); + classMap.invalidateAll(); globalClosures.clear(); final Set toReuse = new HashSet<>(artifactsToUse); @@ -535,41 +567,20 @@ public T getInterface(final Object thiz, final Class clazz) { } Class getScriptClass(final String script) throws CompilationFailedException { - Future clazz = classMap.get(script); - - long start = System.currentTimeMillis(); try { - if (clazz != null) { - return clazz.get(); - } - - clazz = CompletableFuture.supplyAsync(() -> loader.parseClass(script, generateScriptName())); - classMap.put(script, clazz); - return clazz.get(); - - } catch (Exception e) { - if (e.getCause() instanceof CompilationFailedException) { - long finish = System.currentTimeMillis(); - log.error("Script compilation FAILED {} took {}ms {}", script, finish - start, e.getCause()); - throw (CompilationFailedException) e.getCause(); - } else { - throw new AssertionError("Unexpected exception when compiling script", e); - } - } finally { - long time = System.currentTimeMillis() - start; - if (time > 5000) { - //We warn if a script took longer than a few seconds. Repeatedly seeing these warnings is a sign that something is wrong. - //Scripts with a large numbers of parameters often trigger this and should be avoided. - log.warn("Script compilation {} took {}ms", script, time); - } else { - log.debug("Script compilation {} took {}ms", script, time); - } + return classMap.get(script).get(); + } catch (ExecutionException e) { + throw ((CompilationFailedException)e.getCause()); + } catch (InterruptedException e) { + //This should never happen as the future should completed before it is returned to the us. + throw new AssertionError(); } + } boolean isCached(final String script) { - return classMap.get(script) != null; + return classMap.getIfPresent(script) != null; } Object eval(final Class scriptClass, final ScriptContext context) throws ScriptException { From d50a484481e69025e5fe7230e5b55ac8e9533691 Mon Sep 17 00:00:00 2001 From: BrynCooke Date: Wed, 8 Mar 2017 13:23:30 +0000 Subject: [PATCH 4/5] TINKERPOP-1644 Fix exception handling. --- .../jsr223/GremlinGroovyScriptEngine.java | 33 +++++++++---------- 1 file changed, 16 insertions(+), 17 deletions(-) diff --git a/gremlin-groovy/src/main/java/org/apache/tinkerpop/gremlin/groovy/jsr223/GremlinGroovyScriptEngine.java b/gremlin-groovy/src/main/java/org/apache/tinkerpop/gremlin/groovy/jsr223/GremlinGroovyScriptEngine.java index 51850adb3bc..2151a82a076 100644 --- a/gremlin-groovy/src/main/java/org/apache/tinkerpop/gremlin/groovy/jsr223/GremlinGroovyScriptEngine.java +++ b/gremlin-groovy/src/main/java/org/apache/tinkerpop/gremlin/groovy/jsr223/GremlinGroovyScriptEngine.java @@ -168,26 +168,25 @@ protected Map initialValue() { @Override public Future load(String script) throws Exception { long start = System.currentTimeMillis(); - try { - return CompletableFuture.supplyAsync(() -> loader.parseClass(script, generateScriptName()), command -> command.run()); - } catch (Exception e) { - if (e.getCause() instanceof CompilationFailedException) { + + return CompletableFuture.supplyAsync(() -> { + try { + return loader.parseClass(script, generateScriptName()); + } catch (CompilationFailedException e) { long finish = System.currentTimeMillis(); log.error("Script compilation FAILED {} took {}ms {}", script, finish - start, e.getCause()); - throw (CompilationFailedException) e.getCause(); - } else { - throw new AssertionError("Unexpected exception when compiling script", e); - } - } finally { - long time = System.currentTimeMillis() - start; - if (time > 5000) { - //We warn if a script took longer than a few seconds. Repeatedly seeing these warnings is a sign that something is wrong. - //Scripts with a large numbers of parameters often trigger this and should be avoided. - log.warn("Script compilation {} took {}ms", script, time); - } else { - log.debug("Script compilation {} took {}ms", script, time); + throw e; + } finally { + long time = System.currentTimeMillis() - start; + if (time > 5000) { + //We warn if a script took longer than a few seconds. Repeatedly seeing these warnings is a sign that something is wrong. + //Scripts with a large numbers of parameters often trigger this and should be avoided. + log.warn("Script compilation {} took {}ms", script, time); + } else { + log.debug("Script compilation {} took {}ms", script, time); + } } - } + }, command -> command.run()); } }); From c3d0319e1a62409543b6e3458acad72ff117a008 Mon Sep 17 00:00:00 2001 From: BrynCooke Date: Wed, 8 Mar 2017 13:26:31 +0000 Subject: [PATCH 5/5] TINKERPOP-1644 Fix exception handling. --- .../gremlin/groovy/jsr223/GremlinGroovyScriptEngine.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/gremlin-groovy/src/main/java/org/apache/tinkerpop/gremlin/groovy/jsr223/GremlinGroovyScriptEngine.java b/gremlin-groovy/src/main/java/org/apache/tinkerpop/gremlin/groovy/jsr223/GremlinGroovyScriptEngine.java index 2151a82a076..cadc3b095c6 100644 --- a/gremlin-groovy/src/main/java/org/apache/tinkerpop/gremlin/groovy/jsr223/GremlinGroovyScriptEngine.java +++ b/gremlin-groovy/src/main/java/org/apache/tinkerpop/gremlin/groovy/jsr223/GremlinGroovyScriptEngine.java @@ -174,7 +174,7 @@ public Future load(String script) throws Exception { return loader.parseClass(script, generateScriptName()); } catch (CompilationFailedException e) { long finish = System.currentTimeMillis(); - log.error("Script compilation FAILED {} took {}ms {}", script, finish - start, e.getCause()); + log.error("Script compilation FAILED {} took {}ms {}", script, finish - start, e); throw e; } finally { long time = System.currentTimeMillis() - start;