diff --git a/bin/jmeter.properties b/bin/jmeter.properties index bac04e85bc9..df62a7a41e5 100644 --- a/bin/jmeter.properties +++ b/bin/jmeter.properties @@ -1235,6 +1235,11 @@ view.results.tree.renderers_order=.RenderAsText,.RenderAsRegexp,.RenderAsBoundar # Used by JSR-223 elements # Size of compiled scripts cache #jsr223.compiled_scripts_cache_size=100 +# Configurable options on the compiled scripts cache, overrides the jsr223.compiled_scripts_cache_size property +# See com.github.benmanes.caffeine.cache.Caffeine API for details +jsr223.compiled_scripts_cache_spec=maximumSize=100,recordStats +# How many entries to show in the JSR223 cache report (if enabled, i.e. > 0) +#jsr223.statsReportsTop=5 #--------------------------------------------------------------------------- # Classpath configuration diff --git a/src/bom-thirdparty/build.gradle.kts b/src/bom-thirdparty/build.gradle.kts index 4d54c9168c7..19afa8a052d 100644 --- a/src/bom-thirdparty/build.gradle.kts +++ b/src/bom-thirdparty/build.gradle.kts @@ -47,7 +47,7 @@ dependencies { api("com.fasterxml.jackson.core:jackson-databind:2.16.1") api("com.fifesoft:rsyntaxtextarea:3.3.4") api("com.formdev:svgSalamander:1.1.4") - api("com.github.ben-manes.caffeine:caffeine:2.9.3") + api("com.github.ben-manes.caffeine:caffeine:3.1.8") api("com.github.weisj:darklaf-core:2.7.3") api("com.github.weisj:darklaf-extensions-rsyntaxarea:0.3.4") api("com.github.weisj:darklaf-property-loader:2.7.3") diff --git a/src/core/src/main/java/org/apache/jmeter/util/JSR223TestElement.java b/src/core/src/main/java/org/apache/jmeter/util/JSR223TestElement.java index c41e9f755a5..35d5d9ebc5f 100644 --- a/src/core/src/main/java/org/apache/jmeter/util/JSR223TestElement.java +++ b/src/core/src/main/java/org/apache/jmeter/util/JSR223TestElement.java @@ -22,7 +22,8 @@ import java.io.IOException; import java.io.Serializable; import java.nio.file.Files; -import java.util.Properties; +import java.util.*; +import java.util.concurrent.ConcurrentHashMap; import java.util.function.Function; import javax.script.Bindings; @@ -40,18 +41,18 @@ import org.apache.jmeter.threads.JMeterContextService; import org.apache.jmeter.threads.JMeterVariables; import org.apache.jorphan.util.JOrphanUtils; -import org.apache.jorphan.util.StringUtilities; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import com.github.benmanes.caffeine.cache.Cache; import com.github.benmanes.caffeine.cache.Caffeine; +import com.github.benmanes.caffeine.cache.stats.CacheStats; /** * Base class for JSR223 Test elements */ public abstract class JSR223TestElement extends ScriptingTestElement - implements Serializable, TestStateListener + implements Serializable, TestStateListener { private static final long serialVersionUID = 233L; @@ -59,11 +60,12 @@ public abstract class JSR223TestElement extends ScriptingTestElement /** * Cache of compiled scripts */ - private static final Cache COMPILED_SCRIPT_CACHE = - Caffeine - .newBuilder() - .maximumSize(JMeterUtils.getPropDefault("jsr223.compiled_scripts_cache_size", 100)) - .build(); + private static Cache COMPILED_SCRIPT_CACHE; + + /** + * Used for locking cache initialization + */ + private static final Object lock = new Object(); /** * Lambdas can't throw checked exceptions, so we wrap cache loading failure with a runtime one. @@ -79,11 +81,26 @@ public synchronized Throwable fillInStackTrace() { } } - /** If not empty then script in ScriptText will be compiled and cached */ + /** If JSR223 element has checkbox 'Cache compile' checked then script in ScriptText will be compiled and cached */ private String cacheKey = ""; - /** md5 of the script, used as an unique key for the cache */ - private ScriptCacheKey scriptMd5; + /** Used as an unique key for the cache */ + private ScriptCacheKey scriptCacheKey; + + /** + * Holders for stats computation + */ + private static final Map computeScriptCacheKeyCounts = new ConcurrentHashMap<>(); + private static final Map computeScriptCacheKeyTimes = new ConcurrentHashMap<>(); + private static final Map getCompiledScriptCounts = new ConcurrentHashMap<>(); + private static final Map getCompiledScriptTimes = new ConcurrentHashMap<>(); + private static final Map fullRunTimes = new ConcurrentHashMap<>(); + private static final Map keys2Names = new ConcurrentHashMap<>(); + + /** + * Nanoseconds to milliseconds conversion factor + */ + private static final double ns2ms = 1_000_000.0; /** * Initialization On Demand Holder pattern @@ -99,7 +116,7 @@ private LazyHolder() { * @return ScriptEngineManager singleton */ public static ScriptEngineManager getInstance() { - return LazyHolder.INSTANCE; + return LazyHolder.INSTANCE; } protected JSR223TestElement() { @@ -125,7 +142,7 @@ protected ScriptEngine getScriptEngine() throws ScriptException { */ private String getScriptLanguageWithDefault() { String lang = getScriptLanguage(); - if (StringUtilities.isNotEmpty(lang)) { + if (lang != null && !lang.isEmpty()) { return lang; } return DEFAULT_SCRIPT_LANGUAGE; @@ -183,13 +200,13 @@ protected Object processFileOrScript(ScriptEngine scriptEngine, final Bindings p } populateBindings(bindings); String filename = getFilename(); - File scriptFile = new File(filename); // Hack: bsh-2.0b5.jar BshScriptEngine implements Compilable but throws // "java.lang.Error: unimplemented" boolean supportsCompilable = scriptEngine instanceof Compilable && !"bsh.engine.BshScriptEngine".equals(scriptEngine.getClass().getName()); // NOSONAR // $NON-NLS-1$ try { - if (StringUtilities.isNotEmpty(filename)) { + if (filename != null && !filename.isEmpty()) { + File scriptFile = new File(filename); if (!scriptFile.isFile()) { throw new ScriptException("Script file '" + scriptFile.getAbsolutePath() + "' is not a file for JSR223 element named: " + getName()); @@ -203,31 +220,53 @@ protected Object processFileOrScript(ScriptEngine scriptEngine, final Bindings p return scriptEngine.eval(fileReader, bindings); } } - CompiledScript compiledScript; - ScriptCacheKey newCacheKey = - ScriptCacheKey.ofFile(getScriptLanguage(), scriptFile.getAbsolutePath(), scriptFile.lastModified()); - compiledScript = getCompiledScript(newCacheKey, key -> { + computeScriptCacheKey(scriptFile); + CompiledScript compiledScript = getCompiledScript(scriptCacheKey, key -> { try (BufferedReader fileReader = Files.newBufferedReader(scriptFile.toPath())) { return ((Compilable) scriptEngine).compile(fileReader); } catch (IOException | ScriptException e) { + if (logger.isDebugEnabled()) { + logger.debug("Cache missed access: for file script: '{}' for element named: '{}'", scriptFile.getAbsolutePath(), getName()); + } throw new ScriptCompilationInvocationTargetException(e); } }); return compiledScript.eval(bindings); } + String script = getScript(); - if (StringUtilities.isNotEmpty(script)) { - if (supportsCompilable && - !ScriptingBeanInfoSupport.FALSE_AS_STRING.equals(cacheKey)) { - computeScriptMD5(script); - CompiledScript compiledScript = getCompiledScript(scriptMd5, key -> { - try { - return ((Compilable) scriptEngine).compile(script); - } catch (ScriptException e) { - throw new ScriptCompilationInvocationTargetException(e); + if (script != null && !script.isEmpty()) { + if (supportsCompilable) { + long start = System.nanoTime(); + try { + if (!ScriptingBeanInfoSupport.FALSE_AS_STRING.equals(cacheKey)) { + computeScriptCacheKey(script); + CompiledScript compiledScript = getCompiledScript(scriptCacheKey, key -> { + try { + return ((Compilable) scriptEngine).compile(script); + } catch (ScriptException e) { + if (logger.isDebugEnabled()) { + logger.debug("Cache missed access: failed compile of JSR223 element named: '{}'", getName()); + } + throw new ScriptCompilationInvocationTargetException(e); + } + }); + return compiledScript.eval(bindings); + } else { + computeScriptCacheKey(script.hashCode()); + //simulate a cache miss when JSR223 'Cache compiled script if available' is unchecked to have better view of cache usage + COMPILED_SCRIPT_CACHE.get(scriptCacheKey, k -> { + return null; + }); + if (logger.isDebugEnabled()) { + logger.debug("Cache missed access: 'Cache compile' is unchecked for JSR223 element named: '{}'", getName()); + } + return scriptEngine.eval(script, bindings); } - }); - return compiledScript.eval(bindings); + } finally { + Double duration = (double) ((System.nanoTime() - start) / ns2ms); //in ms + fullRunTimes.merge(scriptCacheKey, duration, Double::sum); + } } else { return scriptEngine.eval(script, bindings); } @@ -236,7 +275,7 @@ protected Object processFileOrScript(ScriptEngine scriptEngine, final Bindings p } } catch (ScriptException ex) { Throwable rootCause = ex.getCause(); - if(isStopCondition(rootCause)) { + if (isStopCondition(rootCause)) { throw (RuntimeException) ex.getCause(); } else { throw ex; @@ -248,6 +287,7 @@ private static CompiledScript getCompiledScript( T newCacheKey, Function compiler ) throws IOException, ScriptException { + long start = System.nanoTime(); try { CompiledScript compiledScript = COMPILED_SCRIPT_CACHE.get(newCacheKey, compiler); if (compiledScript == null) { @@ -265,6 +305,10 @@ private static CompiledScript getCompiledScript( throw (ScriptException) cause; } throw e; + } finally { + Double duration = (double) ((System.nanoTime() - start) / ns2ms); //in ms + getCompiledScriptCounts.merge(newCacheKey, 1L, Long::sum); + getCompiledScriptTimes.merge(newCacheKey, duration, Double::sum); } } @@ -274,7 +318,7 @@ private static CompiledScript getCompiledScript( * @throws ScriptException if compilation fails */ public boolean compile() - throws ScriptException, IOException { + throws ScriptException, IOException { String lang = getScriptLanguageWithDefault(); ScriptEngine scriptEngine = getInstance().getEngineByName(lang); boolean supportsCompilable = scriptEngine instanceof Compilable @@ -305,27 +349,70 @@ public boolean compile() } /** - * compute MD5 if it is null + * compute MD5 of a script if null + */ + private void computeScriptCacheKey(String script) { + long start = System.nanoTime(); + try { + if (scriptCacheKey == null) { + // compute the md5 of the script if needed + scriptCacheKey = ScriptCacheKey.ofString(DigestUtils.md5Hex(script)); + keys2Names.put(scriptCacheKey, getName()); + } + } finally { + Double duration = (double) ((System.nanoTime() - start) / ns2ms); + computeScriptCacheKeyCounts.merge(scriptCacheKey, 1L, Long::sum); + computeScriptCacheKeyTimes.merge(scriptCacheKey, duration, Double::sum); + } + } + + /** + * compute cache key for a file based script if null */ - private void computeScriptMD5(String script) { - // compute the md5 of the script if needed - if(scriptMd5 == null) { - scriptMd5 = ScriptCacheKey.ofString(DigestUtils.md5Hex(script)); + private void computeScriptCacheKey(File scriptFile) { + long start = System.nanoTime(); + try { + if (scriptCacheKey == null) { + scriptCacheKey = ScriptCacheKey.ofFile(getScriptLanguage(), scriptFile.getAbsolutePath(), scriptFile.lastModified()); + keys2Names.put(scriptCacheKey, getName()); + } + } finally { + Double duration = (double) ((System.nanoTime() - start) / ns2ms); + computeScriptCacheKeyCounts.merge(scriptCacheKey, 1L, Long::sum); + computeScriptCacheKeyTimes.merge(scriptCacheKey, duration, Double::sum); } } /** - * @return the cacheKey + * compute cache key of a long value if null + */ + private void computeScriptCacheKey(int reference) { + long start = System.nanoTime(); + try { + if (scriptCacheKey == null) { + scriptCacheKey = ScriptCacheKey.ofString(Integer.toString(reference)); + keys2Names.put(scriptCacheKey, getName()); + } + } finally { + Double duration = (double) ((System.nanoTime() - start) / ns2ms); + computeScriptCacheKeyCounts.merge(scriptCacheKey, 1L, Long::sum); + computeScriptCacheKeyTimes.merge(scriptCacheKey, duration, Double::sum); + } + } + + + /** + * @return the cacheChecked */ public String getCacheKey() { return cacheKey; } /** - * @param cacheKey the cacheKey to set + * @param cacheChecked the cacheChecked to set */ - public void setCacheKey(String cacheKey) { - this.cacheKey = cacheKey; + public void setCacheKey(String cacheChecked) { + this.cacheKey = cacheChecked; } /** @@ -333,7 +420,7 @@ public void setCacheKey(String cacheKey) { */ @Override public void testStarted() { - // NOOP + testStarted(""); } /** @@ -341,7 +428,13 @@ public void testStarted() { */ @Override public void testStarted(String host) { - // NOOP + synchronized (lock) { + if (COMPILED_SCRIPT_CACHE == null) { + COMPILED_SCRIPT_CACHE = + Caffeine.from(JMeterUtils.getPropDefault("jsr223.compiled_scripts_cache_spec", "maximumSize=" + + JMeterUtils.getPropDefault("jsr223.compiled_scripts_cache_size", 100) + ",recordStats")).build(); + } + } } /** @@ -357,8 +450,39 @@ public void testEnded() { */ @Override public void testEnded(String host) { - COMPILED_SCRIPT_CACHE.invalidateAll(); - scriptMd5 = null; + synchronized (lock) { + if (COMPILED_SCRIPT_CACHE != null) { + CacheStats stats = COMPILED_SCRIPT_CACHE.stats(); + logger.info("JSR223 cache stats => scripts: {}, requestsCount: {} (hitCount: {} + missedCount: {}), (hitRate: {}, missRate: {}), " + + "loadCount: {} (loadSuccessCount: {} + loadFailureCount: {}), " + + "evictionCount: {}, evictionWeight: {}, " + + "totalLoadTime: {} ms, averageLoadPenalty: {} ms", + COMPILED_SCRIPT_CACHE.estimatedSize(), + stats.requestCount(), stats.hitCount(), stats.missCount(), + String.format("%.02f", stats.hitRate()), String.format("%.02f", stats.missRate()), + stats.loadCount(), stats.loadSuccessCount(), stats.loadFailureCount(), + stats.evictionCount(), stats.evictionWeight(), + String.format("%.02f", (stats.totalLoadTime() / ns2ms)), String.format("%.02f", (stats.averageLoadPenalty() / ns2ms))); + COMPILED_SCRIPT_CACHE.invalidateAll(); + COMPILED_SCRIPT_CACHE.cleanUp(); + COMPILED_SCRIPT_CACHE = null; + + int topLimit = getTopContributorsLimit(); + if (topLimit > 0) { + logTopContributors(computeScriptCacheKeyCounts, computeScriptCacheKeyTimes, "computeScriptCacheKey"); + logTopContributors(getCompiledScriptCounts, getCompiledScriptTimes, "getCompiledScript"); + logTopContributors(computeScriptCacheKeyCounts, fullRunTimes, "processFileOrScript"); + } + + computeScriptCacheKeyCounts.clear(); + computeScriptCacheKeyTimes.clear(); + getCompiledScriptCounts.clear(); + getCompiledScriptTimes.clear(); + fullRunTimes.clear(); + keys2Names.clear(); + } + } + scriptCacheKey = null; } public String getScriptLanguage() { @@ -368,4 +492,90 @@ public String getScriptLanguage() { public void setScriptLanguage(String s) { scriptLanguage = s; } + + /** + * Read configured maximum number of top contributors to report. + * Property: jsr223.statsReportsTop (default "5"). + */ + private static int getTopContributorsLimit() { + String raw = JMeterUtils.getPropDefault("jsr223.statsReportsTop", "5"); + try { + int v = Integer.parseInt(raw.trim()); + return v < 0 ? 0 : v; + } catch (Exception ex) { + return 5; + } + } + + private static void logTopContributors(Map counts, Map durations, String method) { + // Build entries with key, name, count, total and average durations + int configuredLimit = getTopContributorsLimit(); + if (configuredLimit == 0) { + return; + } + + class Entry { + final ScriptCacheKey key; + final String name; + final long count; + final double totalDuration; + final double avgDuration; + + Entry(ScriptCacheKey key, String name, long count, double totalDuration) { + this.key = key; + this.name = name == null ? key.toString() : name; + this.count = count; + this.totalDuration = totalDuration; + this.avgDuration = count == 0 ? 0.0 : (totalDuration / count); + } + } + + List list = new ArrayList<>(); + for (Map.Entry e : counts.entrySet()) { + ScriptCacheKey key = e.getKey(); + long count = e.getValue() == null ? 0L : e.getValue(); + double total = durations.getOrDefault(key, 0.0); + list.add(new Entry(key, keys2Names.get(key), count, total)); + } + + if (list.isEmpty()) { + logger.info("{}: No contributors recorded.", method); + return; + } + int limit = Math.min(configuredLimit, list.size()); + + StringBuilder sb = new StringBuilder(); + sb.append(String.format("Heaviest top %d contributors by their total '%s' execution times (ms)%n", limit, method)); + + for (int j = 0; j < 2; j++) { + if (j == 0) { + list.sort((a, b) -> Double.compare(b.totalDuration, a.totalDuration)); + sb.append(String.format("%n===> By total duration (ms) <===%n")); + } else { + list.sort((a, b) -> Double.compare(b.avgDuration, a.avgDuration)); + sb.append(String.format("%n===> By average duration (ms) <===%n")); + } + sb.append(String.format(Locale.ROOT, "%-5s %-60s %12s %15s %12s%n", "Rank", "Element name", "Calls", "Duration(ms)", "Avg(ms)")); + + long sumCounts = 0L; + double sumTotal = 0.0; + for (int i = 0; i < limit; i++) { + Entry ent = list.get(i); + String totalStr = String.format(Locale.ROOT, "%.3f", ent.totalDuration); + String avgStr = String.format(Locale.ROOT, "%.3f", ent.avgDuration); + String name = ent.name == null ? ent.key.toString() : ent.name; + String displayName = name.length() > 60 ? name.substring(0, 57) + "..." : name; + sb.append(String.format(Locale.ROOT, "%-5d %-60s %12d %15s %12s%n", (i + 1), displayName, ent.count, totalStr, avgStr)); + sumCounts += ent.count; + sumTotal += ent.totalDuration; + } + + // SUM row for the printed items: show summed count and total duration and averaged avg + String sumTotalStr = String.format(Locale.ROOT, "%.3f", sumTotal); + String sumAvgStr = String.format(Locale.ROOT, "%.3f", (sumCounts == 0L ? 0.0 : (sumTotal / sumCounts))); + sb.append(String.format(Locale.ROOT, "%-5s %-60s %12d %15s %12s%n", "", "Total:", sumCounts, sumTotalStr, sumAvgStr)); + } + logger.info(sb.toString()); + } + } diff --git a/src/protocol/http/src/main/java/org/apache/jmeter/protocol/http/control/CacheManager.java b/src/protocol/http/src/main/java/org/apache/jmeter/protocol/http/control/CacheManager.java index 6b1c1d48b15..a09c2b3690a 100644 --- a/src/protocol/http/src/main/java/org/apache/jmeter/protocol/http/control/CacheManager.java +++ b/src/protocol/http/src/main/java/org/apache/jmeter/protocol/http/control/CacheManager.java @@ -283,7 +283,7 @@ private void setCache(String lastModified, String cacheControl, String expires, } else { // Makes expiresDate effectively-final Date entryExpiresDate = expiresDate; - getCache().get( + var unused = getCache().get( url, key -> { CacheEntry cacheEntry = new CacheEntry(lastModified, entryExpiresDate, etag, null); diff --git a/xdocs/usermanual/component_reference.xml b/xdocs/usermanual/component_reference.xml index 213a62758ed..dd27b725128 100644 --- a/xdocs/usermanual/component_reference.xml +++ b/xdocs/usermanual/component_reference.xml @@ -1185,7 +1185,7 @@ To benefit from this feature: Cache size is controlled by the following JMeter property (jmeter.properties): -jsr223.compiled_scripts_cache_size=100 + jsr223.compiled_scripts_cache_size=100 or via a more complex cache setup using the jsr223.compiled_scripts_cache_spec Unlike the , the interpreter is not saved between invocations. JSR223 Test Elements using Script file or Script text + checked Cache compiled script if available are now compiled if ScriptEngine supports this feature, this enables great performance enhancements. diff --git a/xdocs/usermanual/properties_reference.xml b/xdocs/usermanual/properties_reference.xml index d74ece0613d..bb5b0603323 100644 --- a/xdocs/usermanual/properties_reference.xml +++ b/xdocs/usermanual/properties_reference.xml @@ -1984,7 +1984,18 @@ JMETER-SERVER Used by JSR-223 elements.
Size of compiled scripts cache.
- Defaults to: 100 + Defaults to: 100 + + + Used by JSR-223 elements.
+ Caffeine framework spec configuration in String format. Overrides jsr223.compiled_scripts_cache_size
+ Defaults to: maximumSize=jsr223.compiled_scripts_cache_size,recordStats. + Extra details: Caffeine spec + + + Used by JSR-223 elements.
+ Should usage reports be printed at the end of the run (value > 0) then how many items to display.
+ Defaults to: statsReportsTop=5