diff --git a/engine-cli/src/main/java/io/nosqlbench/engine/cli/NBCLI.java b/engine-cli/src/main/java/io/nosqlbench/engine/cli/NBCLI.java index 1da8145ab..f23611188 100644 --- a/engine-cli/src/main/java/io/nosqlbench/engine/cli/NBCLI.java +++ b/engine-cli/src/main/java/io/nosqlbench/engine/cli/NBCLI.java @@ -29,8 +29,8 @@ import io.nosqlbench.nb.api.logging.NBLogLevel; import io.nosqlbench.nb.api.markdown.exporter.MarkdownExporter; import io.nosqlbench.virtdata.userlibs.apps.VirtDataMainApp; import joptsimple.internal.Strings; -import org.apache.logging.log4j.Logger; import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; import org.apache.logging.log4j.core.config.ConfigurationFactory; import java.io.BufferedReader; @@ -40,7 +40,9 @@ import java.io.InputStreamReader; import java.nio.charset.StandardCharsets; import java.nio.file.Files; import java.nio.file.Path; -import java.util.*; +import java.util.Arrays; +import java.util.Map; +import java.util.Optional; import java.util.concurrent.locks.LockSupport; import java.util.stream.Collectors; @@ -332,14 +334,15 @@ public class NBCLI { ScenariosExecutor executor = new ScenariosExecutor("executor-" + sessionName, 1); Scenario scenario = new Scenario( - sessionName, - options.getScriptFile(), - options.getScriptingEngine(), - options.getProgressSpec(), - options.wantsGraaljsCompatMode(), - options.wantsStackTraces(), - options.wantsCompileScript(), - String.join("\n", args) + sessionName, + options.getScriptFile(), + options.getScriptingEngine(), + options.getProgressSpec(), + options.wantsGraaljsCompatMode(), + options.wantsStackTraces(), + options.wantsCompileScript(), + options.getReportSummaryTo(), + String.join("\n", args) ); ScriptBuffer buffer = new BasicScriptBuffer() .add(options.getCommands().toArray(new Cmd[0])); diff --git a/engine-cli/src/main/java/io/nosqlbench/engine/cli/NBCLIOptions.java b/engine-cli/src/main/java/io/nosqlbench/engine/cli/NBCLIOptions.java index 03a4a7b68..1dad3b43c 100644 --- a/engine-cli/src/main/java/io/nosqlbench/engine/cli/NBCLIOptions.java +++ b/engine-cli/src/main/java/io/nosqlbench/engine/cli/NBCLIOptions.java @@ -76,6 +76,7 @@ public class NBCLIOptions { private static final String REPORT_INTERVAL = "--report-interval"; private static final String REPORT_GRAPHITE_TO = "--report-graphite-to"; private static final String REPORT_CSV_TO = "--report-csv-to"; + private static final String REPORT_SUMMARY_TO = "--report-summary-to"; private static final String PROGRESS = "--progress"; private static final String WITH_LOGGING_PATTERN = "--with-logging-pattern"; private static final String LOG_HISTOGRAMS = "--log-histograms"; @@ -149,6 +150,7 @@ public class NBCLIOptions { private final List statePathAccesses = new ArrayList<>(); private final String hdrForChartFileName = DEFAULT_CHART_HDR_LOG_NAME; private String dockerPromRetentionDays = "183d"; + private String reportSummaryTo = "stdout:60"; public String getAnnotatorsConfig() { return annotatorsConfig; @@ -163,6 +165,10 @@ public class NBCLIOptions { return this.dockerPromRetentionDays; } + public String getReportSummaryTo() { + return reportSummaryTo; + } + public enum Mode { ParseGlobalsOnly, ParseAllOptions @@ -490,6 +496,10 @@ public class NBCLIOptions { arglist.removeFirst(); reportCsvTo = arglist.removeFirst(); break; + case REPORT_SUMMARY_TO: + arglist.removeFirst(); + reportSummaryTo = arglist.removeFirst(); + break; case LIST_DRIVERS: case LIST_ACTIVITY_TYPES: arglist.removeFirst(); @@ -841,5 +851,4 @@ public class NBCLIOptions { return progressSpec; } - } diff --git a/engine-core/src/main/java/io/nosqlbench/engine/core/lifecycle/ScenarioResult.java b/engine-core/src/main/java/io/nosqlbench/engine/core/lifecycle/ScenarioResult.java index 56bf419ac..c0350ca98 100644 --- a/engine-core/src/main/java/io/nosqlbench/engine/core/lifecycle/ScenarioResult.java +++ b/engine-core/src/main/java/io/nosqlbench/engine/core/lifecycle/ScenarioResult.java @@ -25,6 +25,9 @@ import io.nosqlbench.engine.core.logging.Log4JMetricsReporter; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; +import java.io.ByteArrayOutputStream; +import java.io.PrintStream; +import java.nio.charset.StandardCharsets; import java.util.Optional; import java.util.concurrent.TimeUnit; @@ -54,28 +57,25 @@ public class ScenarioResult { logger.info("-- SCENARIO TOOK " + getElapsedMillis() + "ms --"); } - public void reportToLog() { - logger.debug("-- BEGIN METRICS DETAIL --"); - Log4JMetricsReporter reporter = Log4JMetricsReporter.forRegistry(ActivityMetrics.getMetricRegistry()) - .withLoggingLevel(Log4JMetricsReporter.LoggingLevel.DEBUG) - .convertDurationsTo(TimeUnit.MICROSECONDS) - .convertRatesTo(TimeUnit.SECONDS) - .filter(MetricFilter.ALL) - .outputTo(logger) - .build(); - reporter.report(); - logger.info("-- END METRICS DETAIL --"); + public String getSummaryReport() { + ByteArrayOutputStream os = new ByteArrayOutputStream(); + PrintStream ps = new PrintStream(os); + ConsoleReporter consoleReporter = ConsoleReporter.forRegistry(ActivityMetrics.getMetricRegistry()) + .convertDurationsTo(TimeUnit.MICROSECONDS) + .convertRatesTo(TimeUnit.SECONDS) + .filter(MetricFilter.ALL) + .outputTo(ps) + .build(); + consoleReporter.report(); + ps.flush(); + String result = os.toString(StandardCharsets.UTF_8); + return result; } public void reportToConsole() { - ConsoleReporter consoleReporter = ConsoleReporter.forRegistry(ActivityMetrics.getMetricRegistry()) - .convertDurationsTo(TimeUnit.MICROSECONDS) - .convertRatesTo(TimeUnit.SECONDS) - .filter(MetricFilter.ALL) - .outputTo(System.out) - .build(); - consoleReporter.report(); + String summaryReport = getSummaryReport(); + System.out.println(summaryReport); } @@ -100,4 +100,21 @@ public class ScenarioResult { public long getElapsedMillis() { return endedAt - startedAt; } + + public void reportTo(PrintStream out) { + out.println(getSummaryReport()); + } + + public void reportToLog() { + logger.debug("-- BEGIN METRICS DETAIL --"); + Log4JMetricsReporter reporter = Log4JMetricsReporter.forRegistry(ActivityMetrics.getMetricRegistry()) + .withLoggingLevel(Log4JMetricsReporter.LoggingLevel.DEBUG) + .convertDurationsTo(TimeUnit.MICROSECONDS) + .convertRatesTo(TimeUnit.SECONDS) + .filter(MetricFilter.ALL) + .outputTo(logger) + .build(); + reporter.report(); + logger.info("-- END METRICS DETAIL --"); + } } diff --git a/engine-core/src/main/java/io/nosqlbench/engine/core/lifecycle/ScenariosResults.java b/engine-core/src/main/java/io/nosqlbench/engine/core/lifecycle/ScenariosResults.java index 85fa585dd..af181748a 100644 --- a/engine-core/src/main/java/io/nosqlbench/engine/core/lifecycle/ScenariosResults.java +++ b/engine-core/src/main/java/io/nosqlbench/engine/core/lifecycle/ScenariosResults.java @@ -69,7 +69,6 @@ public class ScenariosResults { oresult.reportElapsedMillis(); if (oresult.getElapsedMillis() >= 60_000) { oresult.reportToConsole(); - oresult.reportToLog(); } else { logger.info("Metrics suppressed because scenario was less than 1 minute long."); logger.info("Metrics data is not reliable for short sampling periods."); diff --git a/engine-core/src/main/java/io/nosqlbench/engine/core/script/Scenario.java b/engine-core/src/main/java/io/nosqlbench/engine/core/script/Scenario.java index 4e5e84976..01d6e9407 100644 --- a/engine-core/src/main/java/io/nosqlbench/engine/core/script/Scenario.java +++ b/engine-core/src/main/java/io/nosqlbench/engine/core/script/Scenario.java @@ -38,8 +38,7 @@ import javax.script.Compilable; import javax.script.CompiledScript; import javax.script.ScriptEngine; import javax.script.ScriptEngineManager; -import java.io.BufferedReader; -import java.io.IOException; +import java.io.*; import java.nio.ByteBuffer; import java.nio.charset.Charset; import java.nio.charset.StandardCharsets; @@ -57,6 +56,7 @@ import java.util.stream.Collectors; public class Scenario implements Callable { private final String commandLine; + private final String reportSummaryTo; private Logger logger = LogManager.getLogger("SCENARIO"); private State state = State.Scheduled; @@ -84,7 +84,7 @@ public class Scenario implements Callable { private ScriptParams scenarioScriptParams; private String scriptfile; private Engine engine = Engine.Graalvm; - private boolean wantsStackTraces=false; + private boolean wantsStackTraces = false; private boolean wantsCompiledScript; private long startedAtMillis = -1L; private long endedAtMillis = -1L; @@ -95,14 +95,15 @@ public class Scenario implements Callable { } public Scenario( - String scenarioName, - String scriptfile, - Engine engine, - String progressInterval, - boolean wantsGraaljsCompatMode, - boolean wantsStackTraces, - boolean wantsCompiledScript, - String commandLine) { + String scenarioName, + String scriptfile, + Engine engine, + String progressInterval, + boolean wantsGraaljsCompatMode, + boolean wantsStackTraces, + boolean wantsCompiledScript, + String reportSummaryTo, + String commandLine) { this.scenarioName = scenarioName; this.scriptfile = scriptfile; this.engine = engine; @@ -110,6 +111,7 @@ public class Scenario implements Callable { this.wantsGraaljsCompatMode = wantsGraaljsCompatMode; this.wantsStackTraces = wantsStackTraces; this.wantsCompiledScript = wantsCompiledScript; + this.reportSummaryTo = reportSummaryTo; this.commandLine = commandLine; } @@ -124,6 +126,7 @@ public class Scenario implements Callable { public Scenario(String name, Engine engine) { this.scenarioName = name; + this.reportSummaryTo = "CONSOLE"; this.engine = engine; this.commandLine = ""; } @@ -244,12 +247,12 @@ public class Scenario implements Callable { startedAtMillis = System.currentTimeMillis(); Annotators.recordAnnotation( - Annotation.newBuilder() - .session(this.scenarioName) - .now() - .layer(Layer.Scenario) - .detail("engine", this.engine.toString()) - .build() + Annotation.newBuilder() + .session(this.scenarioName) + .now() + .layer(Layer.Scenario) + .detail("engine", this.engine.toString()) + .build() ); init(); logger.debug("Running control script for " + getScenarioName() + "."); @@ -268,17 +271,17 @@ public class Scenario implements Callable { String filename = scriptfile.replace("_SESSIONNAME_", scenarioName); logger.debug("-> invoking main scenario script (" + - "interpreted from " + filename +")"); + "interpreted from " + filename + ")"); Path written = Files.write( - Path.of(filename), - script.getBytes(StandardCharsets.UTF_8), - StandardOpenOption.TRUNCATE_EXISTING, - StandardOpenOption.CREATE + Path.of(filename), + script.getBytes(StandardCharsets.UTF_8), + StandardOpenOption.TRUNCATE_EXISTING, + StandardOpenOption.CREATE ); BufferedReader reader = Files.newBufferedReader(written); scriptEngine.eval(reader); logger.debug("<- scenario completed (interpreted " + - "from " + filename + ")"); + "from " + filename + ")"); } else { logger.debug("-> invoking main scenario script (interpreted)"); result = scriptEngine.eval(script); @@ -331,12 +334,12 @@ public class Scenario implements Callable { // We report the scenario state via annotation even for short runs Annotation annotation = Annotation.newBuilder() - .session(this.scenarioName) - .interval(this.startedAtMillis, endedAtMillis) - .layer(Layer.Scenario) - .label("state", this.state.toString()) - .detail("command_line", this.commandLine) - .build(); + .session(this.scenarioName) + .interval(this.startedAtMillis, endedAtMillis) + .layer(Layer.Scenario) + .label("state", this.state.toString()) + .detail("command_line", this.commandLine) + .build(); Annotators.recordAnnotation(annotation); @@ -353,7 +356,47 @@ public class Scenario implements Callable { public ScenarioResult call() { run(); String iolog = scriptEnv.getTimedLog(); - return new ScenarioResult(iolog, this.startedAtMillis, this.endedAtMillis); + ScenarioResult result = new ScenarioResult(iolog, this.startedAtMillis, this.endedAtMillis); + + result.reportToLog(); + + Optional.ofNullable(getSummaryDestination(reportSummaryTo, result.getElapsedMillis())) + .ifPresent(result::reportTo); + + return result; + } + + private PrintStream getSummaryDestination(String reportSummaryTo, long elapsedMillis) { + if (reportSummaryTo != null && !reportSummaryTo.isBlank()) { + String[] split = reportSummaryTo.split(":", 2); + String summaryTo = split[0]; + long summaryWhen = split.length == 2 ? Long.parseLong(split[1]) * 1000L : 60000L; + if (elapsedMillis > summaryWhen) { + PrintStream out = null; + switch (summaryTo.toLowerCase()) { + case "console": + case "stdout": + return System.out; + case "stderr": + return System.err; + default: + String outName = summaryTo + .replaceAll("_session_", getScenarioName()) + .replaceAll("_scenario_", getScenarioName()); + try { + out = new PrintStream(new FileOutputStream(outName)); + return out; + } catch (FileNotFoundException e) { + throw new RuntimeException(e); + } + } + } else { + logger.info("Metrics suppressed because scenario was less than " + summaryWhen + "ms long."); + logger.info("Metrics data is not reliable for short sampling periods."); + logger.info("To get metrics on console, run a longer scenario."); + } + } + return null; } @Override @@ -406,5 +449,9 @@ public class Scenario implements Callable { public void enableCharting() { MetricRegistry metricRegistry = ActivityMetrics.getMetricRegistry(); } + + public String getReportSummaryTo() { + return reportSummaryTo; + } } diff --git a/engine-rest/src/main/java/io/nosqlbench/engine/rest/resources/ScenarioExecutorEndpoint.java b/engine-rest/src/main/java/io/nosqlbench/engine/rest/resources/ScenarioExecutorEndpoint.java index e72d2d0d7..6cc1af05d 100644 --- a/engine-rest/src/main/java/io/nosqlbench/engine/rest/resources/ScenarioExecutorEndpoint.java +++ b/engine-rest/src/main/java/io/nosqlbench/engine/rest/resources/ScenarioExecutorEndpoint.java @@ -102,14 +102,15 @@ public class ScenarioExecutorEndpoint implements WebServiceObject { buffer.add(cmdList.toArray(new Cmd[0])); Scenario scenario = new Scenario( - rq.getScenarioName(), - "", - Scenario.Engine.Graalvm, - "disabled", - false, - true, - false, - cmdList.toString()); + rq.getScenarioName(), + "", + Scenario.Engine.Graalvm, + "disabled", + false, + true, + false, + "", + cmdList.toString()); scenario.addScriptText(buffer.getParsedScript()); diff --git a/nb/src/test/java/io/nosqlbench/engine/core/script/AsyncScriptIntegrationTests.java b/nb/src/test/java/io/nosqlbench/engine/core/script/AsyncScriptIntegrationTests.java index 8ab46e3ea..38c7bc63f 100644 --- a/nb/src/test/java/io/nosqlbench/engine/core/script/AsyncScriptIntegrationTests.java +++ b/nb/src/test/java/io/nosqlbench/engine/core/script/AsyncScriptIntegrationTests.java @@ -69,7 +69,6 @@ public class AsyncScriptIntegrationTests { e.execute(s); ScenariosResults scenariosResults = e.awaitAllResults(); ScenarioResult scenarioResult = scenariosResults.getOne(); - scenarioResult.reportToLog(); return scenarioResult; } @@ -199,13 +198,11 @@ public class AsyncScriptIntegrationTests { @Test public void testAwaitFinished() { ScenarioResult scenarioResult = runScenario("awaitfinished"); - scenarioResult.reportToLog(); } @Test public void testStartStop() { ScenarioResult scenarioResult = runScenario("startstopdiag"); - scenarioResult.reportToLog(); int startedAt = scenarioResult.getIOLog().indexOf("starting activity teststartstopdiag"); int stoppedAt = scenarioResult.getIOLog().indexOf("stopped activity teststartstopdiag"); assertThat(startedAt).isGreaterThan(0); diff --git a/nb/src/test/java/io/nosqlbench/engine/core/script/ScriptIntegrationTests.java b/nb/src/test/java/io/nosqlbench/engine/core/script/ScriptIntegrationTests.java index f31f2cb55..37148576a 100644 --- a/nb/src/test/java/io/nosqlbench/engine/core/script/ScriptIntegrationTests.java +++ b/nb/src/test/java/io/nosqlbench/engine/core/script/ScriptIntegrationTests.java @@ -64,7 +64,6 @@ public class ScriptIntegrationTests { e.execute(s); ScenariosResults scenariosResults = e.awaitAllResults(); ScenarioResult scenarioResult = scenariosResults.getOne(); - scenarioResult.reportToLog(); return scenarioResult; }