improvements to scenario log handling

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,
+            sessionName,
-                options.getScriptFile(),
+            options.getScriptFile(),
-                options.getScriptingEngine(),
+            options.getScriptingEngine(),
-                options.getProgressSpec(),
+            options.getProgressSpec(),
-                options.wantsGraaljsCompatMode(),
+            options.wantsGraaljsCompatMode(),
-                options.wantsStackTraces(),
+            options.wantsStackTraces(),
-                options.wantsCompileScript(),
+            options.wantsCompileScript(),
-                String.join("\n", args)
+            options.getReportSummaryTo(),
+            String.join("\n", args)
         );
         ScriptBuffer buffer = new BasicScriptBuffer()
                 .add(options.getCommands().toArray(new Cmd[0]));

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<String> 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;
     }
 
-
 }

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() {
+    public String getSummaryReport() {
-        logger.debug("-- BEGIN METRICS DETAIL --");
+        ByteArrayOutputStream os = new ByteArrayOutputStream();
-        Log4JMetricsReporter reporter = Log4JMetricsReporter.forRegistry(ActivityMetrics.getMetricRegistry())
+        PrintStream ps = new PrintStream(os);
-                .withLoggingLevel(Log4JMetricsReporter.LoggingLevel.DEBUG)
+        ConsoleReporter consoleReporter = ConsoleReporter.forRegistry(ActivityMetrics.getMetricRegistry())
-                .convertDurationsTo(TimeUnit.MICROSECONDS)
+            .convertDurationsTo(TimeUnit.MICROSECONDS)
-                .convertRatesTo(TimeUnit.SECONDS)
+            .convertRatesTo(TimeUnit.SECONDS)
-                .filter(MetricFilter.ALL)
+            .filter(MetricFilter.ALL)
-                .outputTo(logger)
+            .outputTo(ps)
-                .build();
+            .build();
-        reporter.report();
+        consoleReporter.report();
-        logger.info("-- END METRICS DETAIL --");
 
+        ps.flush();
+        String result = os.toString(StandardCharsets.UTF_8);
+        return result;
     }
 
     public void reportToConsole() {
-        ConsoleReporter consoleReporter = ConsoleReporter.forRegistry(ActivityMetrics.getMetricRegistry())
+        String summaryReport = getSummaryReport();
-                .convertDurationsTo(TimeUnit.MICROSECONDS)
+        System.out.println(summaryReport);
-                .convertRatesTo(TimeUnit.SECONDS)
-                .filter(MetricFilter.ALL)
-                .outputTo(System.out)
-                .build();
-        consoleReporter.report();
     }
 
 
@@ -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 --");
+    }
 }

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.");

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.*;
-import java.io.IOException;
 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<ScenarioResult> {
 
     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<ScenarioResult> {
     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<ScenarioResult> {
     }
 
     public Scenario(
-            String scenarioName,
+        String scenarioName,
-            String scriptfile,
+        String scriptfile,
-            Engine engine,
+        Engine engine,
-            String progressInterval,
+        String progressInterval,
-            boolean wantsGraaljsCompatMode,
+        boolean wantsGraaljsCompatMode,
-            boolean wantsStackTraces,
+        boolean wantsStackTraces,
-            boolean wantsCompiledScript,
+        boolean wantsCompiledScript,
-            String commandLine) {
+        String reportSummaryTo,
+        String commandLine) {
         this.scenarioName = scenarioName;
         this.scriptfile = scriptfile;
         this.engine = engine;
@@ -110,6 +111,7 @@ public class Scenario implements Callable<ScenarioResult> {
         this.wantsGraaljsCompatMode = wantsGraaljsCompatMode;
         this.wantsStackTraces = wantsStackTraces;
         this.wantsCompiledScript = wantsCompiledScript;
+        this.reportSummaryTo = reportSummaryTo;
         this.commandLine = commandLine;
     }
 
@@ -124,6 +126,7 @@ public class Scenario implements Callable<ScenarioResult> {
 
     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<ScenarioResult> {
 
         startedAtMillis = System.currentTimeMillis();
         Annotators.recordAnnotation(
-                Annotation.newBuilder()
+            Annotation.newBuilder()
-                        .session(this.scenarioName)
+                .session(this.scenarioName)
-                        .now()
+                .now()
-                        .layer(Layer.Scenario)
+                .layer(Layer.Scenario)
-                        .detail("engine", this.engine.toString())
+                .detail("engine", this.engine.toString())
-                        .build()
+                .build()
         );
         init();
         logger.debug("Running control script for " + getScenarioName() + ".");
@@ -268,17 +271,17 @@ public class Scenario implements Callable<ScenarioResult> {
 
                         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),
+                            Path.of(filename),
-                                script.getBytes(StandardCharsets.UTF_8),
+                            script.getBytes(StandardCharsets.UTF_8),
-                                StandardOpenOption.TRUNCATE_EXISTING,
+                            StandardOpenOption.TRUNCATE_EXISTING,
-                                StandardOpenOption.CREATE
+                            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<ScenarioResult> {
 
         // We report the scenario state via annotation even for short runs
         Annotation annotation = Annotation.newBuilder()
-                .session(this.scenarioName)
+            .session(this.scenarioName)
-                .interval(this.startedAtMillis, endedAtMillis)
+            .interval(this.startedAtMillis, endedAtMillis)
-                .layer(Layer.Scenario)
+            .layer(Layer.Scenario)
-                .label("state", this.state.toString())
+            .label("state", this.state.toString())
-                .detail("command_line", this.commandLine)
+            .detail("command_line", this.commandLine)
-                .build();
+            .build();
 
         Annotators.recordAnnotation(annotation);
 
@@ -353,7 +356,47 @@ public class Scenario implements Callable<ScenarioResult> {
     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<ScenarioResult> {
     public void enableCharting() {
         MetricRegistry metricRegistry = ActivityMetrics.getMetricRegistry();
     }
+
+    public String getReportSummaryTo() {
+        return reportSummaryTo;
+    }
 }
 

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(),
+            rq.getScenarioName(),
-                "",
+            "",
-                Scenario.Engine.Graalvm,
+            Scenario.Engine.Graalvm,
-                "disabled",
+            "disabled",
-                false,
+            false,
-                true,
+            true,
-                false,
+            false,
-                cmdList.toString());
+            "",
+            cmdList.toString());
 
         scenario.addScriptText(buffer.getParsedScript());
 

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);

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;
     }