IntenseFinance/nosqlbench
3
0
Fork 0
mirror of https://github.com/nosqlbench/nosqlbench.git synced 2025-02-25 18:55:28 -06:00
Code Issues Packages Projects Releases Wiki Activity

direct work-around for flaky test, simple improvements to logging, some improvements to consistent view of status, misc cleanups

Browse Source
This commit is contained in:
Jonathan Shook 2022-11-22 10:48:53 -06:00
parent 16417f37b6
commit 28f561aedd
10 changed files with 131 additions and 145 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

31
engine-cli/src/main/java/io/nosqlbench/engine/cli/NBCLI.java
View File

@ -63,10 +63,10 @@ import java.util.stream.Collectors;
public class NBCLI implements Function<String[], Integer> {
private static Logger logger;
private static LoggerConfig loggerConfig;
private static int EXIT_OK = 0;
private static int EXIT_WARNING = 1;
private static int EXIT_ERROR = 2;
private static final LoggerConfig loggerConfig;
private static final int EXIT_OK = 0;
private static final int EXIT_WARNING = 1;
private static final int EXIT_ERROR = 2;
static {
loggerConfig = new LoggerConfig();
@ -117,6 +117,7 @@ public class NBCLI implements Function<String[], Integer> {
if (arg.toLowerCase(Locale.ROOT).startsWith("-v") || (arg.toLowerCase(Locale.ROOT).equals("--show-stacktraces"))) {
showStackTraces = true;
break;
}
}
@ -265,7 +266,7 @@ public class NBCLI implements Function<String[], Integer> {
for (ServiceLoader.Provider<BundledApp> provider : loader.stream().toList()) {
Class<? extends BundledApp> appType = provider.type();
String name = appType.getAnnotation(Service.class).selector();
System.out.println(String.format("%-40s %s", name, appType.getCanonicalName()));
System.out.printf("%-40s %s%n", name, appType.getCanonicalName());
}
return EXIT_OK;
}
@ -319,14 +320,14 @@ public class NBCLI implements Function<String[], Integer> {
Path writeTo = Path.of(data.asPath().getFileName().toString());
if (Files.exists(writeTo)) {
throw new BasicError("A file named " + writeTo.toString() + " exists. Remove it first.");
throw new BasicError("A file named " + writeTo + " exists. Remove it first.");
}
try {
Files.writeString(writeTo, data.getCharBuffer(), StandardCharsets.UTF_8);
} catch (IOException e) {
throw new BasicError("Unable to write to " + writeTo.toString() + ": " + e.getMessage());
throw new BasicError("Unable to write to " + writeTo + ": " + e.getMessage());
}
logger.info("Copied internal resource '" + data.asPath() + "' to '" + writeTo.toString() + "'");
logger.info("Copied internal resource '" + data.asPath() + "' to '" + writeTo + "'");
return EXIT_OK;
}
@ -467,13 +468,13 @@ public class NBCLI implements Function<String[], Integer> {
executor.execute(scenario);
while (true) {
Optional<ScenarioResult> pendingResult = executor.getPendingResult(scenario.getScenarioName());
if (pendingResult.isPresent()) {
break;
}
LockSupport.parkNanos(100000000L);
}
// while (true) {
// Optional<ScenarioResult> pendingResult = executor.getPendingResult(scenario.getScenarioName());
// if (pendingResult.isPresent()) {
// break;
// }
// LockSupport.parkNanos(100000000L);
// }
ScenariosResults scenariosResults = executor.awaitAllResults();
logger.debug("Total of " + scenariosResults.getSize() + " result object returned from ScenariosExecutor");

2
engine-core/src/main/java/io/nosqlbench/engine/core/lifecycle/ActivityExecutor.java
View File

@ -229,7 +229,7 @@ public class ActivityExecutor implements ActivityController, ParameterMap.Listen
logger.warn("while waiting termination of shutdown " + activity.getAlias() + ", " + ie.getMessage());
activitylogger.debug("REQUEST STOP/exception alias=(" + activity.getAlias() + ") wasstopped=" + wasStopped);
} catch (RuntimeException e) {
logger.debug("Received exception while awaiting termination: " + e.getMessage());
logger.trace("Received exception while awaiting termination: " + e.getMessage());
wasStopped = true;
stoppingException = e;
} finally {

25
engine-core/src/main/java/io/nosqlbench/engine/core/lifecycle/ScenarioResult.java
View File

@ -54,11 +54,11 @@ public class ScenarioResult {
private final long startedAt;
private final long endedAt;
private Exception exception;
private final Exception exception;
private final String iolog;
public ScenarioResult(String iolog, long startedAt, long endedAt) {
logger.debug("populating result from iolog");
public ScenarioResult(Exception e, String iolog, long startedAt, long endedAt) {
logger.debug("populating "+(e==null? "NORMAL" : "ERROR")+" scenario result");
if (logger.isDebugEnabled()) {
StackTraceElement[] st = Thread.currentThread().getStackTrace();
for (int i = 0; i < st.length; i++) {
@ -66,21 +66,7 @@ public class ScenarioResult {
if (i>10) break;
}
}
this.iolog = iolog;
this.startedAt = startedAt;
this.endedAt = endedAt;
}
public ScenarioResult(Exception e, long startedAt, long endedAt) {
logger.debug("populating result from exception");
if (logger.isDebugEnabled()) {
StackTraceElement[] st = Thread.currentThread().getStackTrace();
for (int i = 0; i < st.length; i++) {
logger.debug(":AT " + st[i].getFileName()+":"+st[i].getLineNumber()+":"+st[i].getMethodName());
if (i>10) break;
}
}
this.iolog = e.getMessage();
this.iolog = ((iolog!=null) ? iolog + "\n\n" : "") + (e!=null? e.getMessage() : "");
this.startedAt = startedAt;
this.endedAt = endedAt;
this.exception = e;
@ -170,8 +156,7 @@ public class ScenarioResult {
}
} else if (v instanceof Gauge) {
Object value = ((Gauge) v).getValue();
if (value != null && value instanceof Number) {
Number n = (Number) value;
if (value != null && value instanceof Number n) {
if (n.doubleValue() != 0) {
NBMetricsSummary.summarize(sb, k, v);
}

152
engine-core/src/main/java/io/nosqlbench/engine/core/script/Scenario.java
View File

@ -71,6 +71,12 @@ public class Scenario implements Callable<ScenarioResult> {
private Exception error;
private ScenarioMetadata scenarioMetadata;
private ScenarioResult result;
public Optional<ScenarioResult> getResultIfComplete() {
return Optional.ofNullable(this.result);
}
public enum State {
Scheduled,
@ -101,16 +107,16 @@ public class Scenario implements Callable<ScenarioResult> {
}
public Scenario(
String scenarioName,
String scriptfile,
Engine engine,
String progressInterval,
boolean wantsStackTraces,
boolean wantsCompiledScript,
String reportSummaryTo,
String commandLine,
Path logsPath,
Maturity minMaturity) {
String scenarioName,
String scriptfile,
Engine engine,
String progressInterval,
boolean wantsStackTraces,
boolean wantsCompiledScript,
String reportSummaryTo,
String commandLine,
Path logsPath,
Maturity minMaturity) {
this.scenarioName = scenarioName;
this.scriptfile = scriptfile;
@ -165,24 +171,24 @@ public class Scenario implements Callable<ScenarioResult> {
return this;
}
private void init() {
private void initializeScriptingEngine() {
logger.debug("Using engine " + engine.toString());
MetricRegistry metricRegistry = ActivityMetrics.getMetricRegistry();
Context.Builder contextSettings = Context.newBuilder("js")
.allowHostAccess(HostAccess.ALL)
.allowNativeAccess(true)
.allowCreateThread(true)
.allowIO(true)
.allowHostClassLookup(s -> true)
.allowHostClassLoading(true)
.allowCreateProcess(true)
.allowAllAccess(true)
.allowEnvironmentAccess(EnvironmentAccess.INHERIT)
.allowPolyglotAccess(PolyglotAccess.ALL)
.option("js.ecmascript-version", "2020")
.option("js.nashorn-compat", "true");
.allowHostAccess(HostAccess.ALL)
.allowNativeAccess(true)
.allowCreateThread(true)
.allowIO(true)
.allowHostClassLookup(s -> true)
.allowHostClassLoading(true)
.allowCreateProcess(true)
.allowAllAccess(true)
.allowEnvironmentAccess(EnvironmentAccess.INHERIT)
.allowPolyglotAccess(PolyglotAccess.ALL)
.option("js.ecmascript-version", "2020")
.option("js.nashorn-compat", "true");
org.graalvm.polyglot.Engine.Builder engineBuilder = org.graalvm.polyglot.Engine.newBuilder();
engineBuilder.option("engine.WarnInterpreterOnly", "false");
@ -218,15 +224,15 @@ public class Scenario implements Callable<ScenarioResult> {
}
Logger extensionLogger =
LogManager.getLogger("extensions." + extensionDescriptor.getBaseVariableName());
LogManager.getLogger("extensions." + extensionDescriptor.getBaseVariableName());
Object extensionObject = extensionDescriptor.getExtensionObject(
extensionLogger,
metricRegistry,
scriptEnv
extensionLogger,
metricRegistry,
scriptEnv
);
ScenarioMetadataAware.apply(extensionObject, getScenarioMetadata());
logger.trace("Adding extension object: name=" + extensionDescriptor.getBaseVariableName() +
" class=" + extensionObject.getClass().getSimpleName());
" class=" + extensionObject.getClass().getSimpleName());
scriptEngine.put(extensionDescriptor.getBaseVariableName(), extensionObject);
}
}
@ -234,40 +240,38 @@ public class Scenario implements Callable<ScenarioResult> {
private synchronized ScenarioMetadata getScenarioMetadata() {
if (this.scenarioMetadata == null) {
this.scenarioMetadata = new ScenarioMetadata(
this.startedAtMillis,
this.scenarioName,
SystemId.getNodeId(),
SystemId.getNodeFingerprint()
this.startedAtMillis,
this.scenarioName,
SystemId.getNodeId(),
SystemId.getNodeFingerprint()
);
}
return scenarioMetadata;
}
public void runScenario() {
private synchronized void runScenario() {
scenarioShutdownHook = new ScenarioShutdownHook(this);
Runtime.getRuntime().addShutdownHook(scenarioShutdownHook);
state = State.Running;
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();
initializeScriptingEngine();
logger.debug("Running control script for " + getScenarioName() + ".");
for (String script : scripts) {
try {
Object result = null;
if (scriptEngine instanceof Compilable && wantsCompiledScript) {
if (scriptEngine instanceof Compilable compilableEngine && wantsCompiledScript) {
logger.debug("Using direct script compilation");
Compilable compilableEngine = (Compilable) scriptEngine;
CompiledScript compiled = compilableEngine.compile(script);
logger.debug("-> invoking main scenario script (compiled)");
result = compiled.eval();
@ -276,17 +280,17 @@ public class Scenario implements Callable<ScenarioResult> {
if (scriptfile != null && !scriptfile.isEmpty()) {
String filename = scriptfile.replace("_SESSION_", 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 control script completed (interpreted) " +
"from " + filename + ")");
"from " + filename + ")");
} else {
logger.debug("-> invoking main scenario script (interpreted)");
result = scriptEngine.eval(script);
@ -295,15 +299,17 @@ public class Scenario implements Callable<ScenarioResult> {
}
if (result != null) {
logger.debug("scenario result: type(" + result.getClass().getCanonicalName() + "): value:" + result.toString());
logger.debug("scenario result: type(" + result.getClass().getCanonicalName() + "): value:" + result);
}
System.err.flush();
System.out.flush();
} catch (Exception e) {
this.state = State.Errored;
logger.error("Error in scenario, shutting down. (" + e.toString() + ")");
logger.error("Error in scenario, shutting down. (" + e + ")");
try {
this.scenarioController.forceStopScenario(5000, false);
} catch (Exception eInner) {
logger.debug("Found inner exception while forcing stop with rethrow=false: " + eInner);
} finally {
this.error = e;
throw new RuntimeException(e);
@ -342,12 +348,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)
.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);
@ -361,20 +367,30 @@ public class Scenario implements Callable<ScenarioResult> {
return endedAtMillis;
}
public ScenarioResult call() {
/**
* This should be the only way to get a ScenarioResult for a Scenario.
*
* @return
*/
public synchronized ScenarioResult call() {
if (result == null) {
try {
runScenario();
} catch (Exception e) {
if (this.error!=null) {
logger.debug("OVERLAPPING ERRORS: prior" + this.error.getMessage() + ", current:" + e.getMessage());
}
this.error = e;
} finally {
logger.debug((this.error == null ? "NORMAL" : "ERRORED") + " scenario run");
}
ScenarioResult result = null;
try {
runScenario();
String iolog = scriptEnv.getTimedLog();
result = new ScenarioResult(iolog, this.startedAtMillis, this.endedAtMillis);
this.result = new ScenarioResult(this.error, iolog, this.startedAtMillis, this.endedAtMillis);
result.reportToLog();
doReportSummaries(reportSummaryTo, result);
} catch (Exception e) {
// note: this exception wasn't being handled here. thrown up the chain to trace issues.
logger.debug("runScenario exception received: " + e.getMessage());
throw e;
}
return result;
}
@ -402,8 +418,8 @@ public class Scenario implements Callable<ScenarioResult> {
break;
default:
String outName = summaryTo
.replaceAll("_SESSION_", getScenarioName())
.replaceAll("_LOGS_", logsPath.toString());
.replaceAll("_SESSION_", getScenarioName())
.replaceAll("_LOGS_", logsPath.toString());
try {
out = new PrintStream(new FileOutputStream(outName));
break;

23
engine-core/src/main/java/io/nosqlbench/engine/core/script/ScenariosExecutor.java
View File

@ -152,7 +152,7 @@ public class ScenariosExecutor {
} catch (Exception e) {
long now = System.currentTimeMillis();
logger.debug("creating exceptional scenario result from getAsyncResultStatus");
oResult = Optional.of(new ScenarioResult(e, now, now));
oResult = Optional.of(new ScenarioResult(e, "errored output", now, now));
}
}
@ -179,24 +179,8 @@ public class ScenariosExecutor {
* @param scenarioName the scenario name of interest
* @return an optional result
*/
public Optional<ScenarioResult> getPendingResult(String scenarioName) {
Future<ScenarioResult> resultFuture1 = submitted.get(scenarioName).resultFuture;
if (resultFuture1 == null) {
throw new BasicError("Unknown scenario name:" + scenarioName);
}
long now = System.currentTimeMillis();
if (resultFuture1.isDone()) {
try {
return Optional.ofNullable(resultFuture1.get());
} catch (Exception e) {
logger.debug("creating exceptional scenario result from getPendingResult");
return Optional.of(new ScenarioResult(e, now, now));
}
} else if (resultFuture1.isCancelled()) {
return Optional.of(new ScenarioResult(new Exception("result was cancelled."), now, now));
}
return Optional.empty();
public Optional<Future<ScenarioResult>> getPendingResult(String scenarioName) {
return Optional.ofNullable(submitted.get(scenarioName)).map(s -> s.resultFuture);
}
public synchronized void stopScenario(String scenarioName) {
@ -204,6 +188,7 @@ public class ScenariosExecutor {
}
public synchronized void stopScenario(String scenarioName, boolean rethrow) {
logger.debug("#stopScenario(name=" + scenarioName + ", rethrow="+ rethrow+")");
Optional<Scenario> pendingScenario = getPendingScenario(scenarioName);
if (pendingScenario.isPresent()) {
ScenarioController controller = pendingScenario.get().getScenarioController();

10
engine-core/src/test/java/io/nosqlbench/engine/core/ScenarioTest.java
View File

@ -26,20 +26,20 @@ import org.junit.jupiter.api.Test;
import static org.assertj.core.api.Assertions.assertThat;
public class ScenarioTest {
private Logger logger = LogManager.getLogger(ScenarioTest.class);
private final Logger logger = LogManager.getLogger(ScenarioTest.class);
@Test
public void shouldLoadScriptText() {
ScriptEnvBuffer buffer = new ScriptEnvBuffer();
Scenario env = new Scenario("testing", Scenario.Engine.Graalvm, "stdout:300", Maturity.Any);
env.addScriptText("print('loaded script environment...');\n");
Scenario scenario = new Scenario("testing", Scenario.Engine.Graalvm, "stdout:300", Maturity.Any);
scenario.addScriptText("print('loaded script environment...');\n");
try {
env.runScenario();
var result=scenario.call();
} catch (Exception e) {
logger.debug("Scenario run encountered an exception: " + e.getMessage());
}
assertThat(env.getIOLog().get().get(0)).contains("loaded script environment...");
assertThat(scenario.getIOLog().get().get(0)).contains("loaded script environment...");
}
}

6
engine-rest/src/main/java/io/nosqlbench/engine/rest/resources/ScenarioExecutorEndpoint.java
View File

@ -41,6 +41,7 @@ import org.joda.time.format.DateTimeFormat;
import java.io.CharArrayWriter;
import java.io.PrintWriter;
import java.util.*;
import java.util.concurrent.Future;
@Service(value = WebServiceObject.class, selector = "scenario-executor")
@Singleton
@ -233,8 +234,9 @@ public class ScenarioExecutorEndpoint implements WebServiceObject {
Optional<Scenario> pendingScenario = executor.getPendingScenario(scenarioName);
if (pendingScenario.isPresent()) {
Optional<ScenarioResult> pendingResult = executor.getPendingResult(scenarioName);
return new LiveScenarioView(pendingScenario.get(), pendingResult.orElse(null));
Optional<Future<ScenarioResult>> pendingResult = executor.getPendingResult(scenarioName);
Future<ScenarioResult> scenarioResultFuture = pendingResult.get();
return new LiveScenarioView(pendingScenario.get());
} else {
throw new RuntimeException("Scenario name '" + scenarioName + "' not found.");
}

10
engine-rest/src/main/java/io/nosqlbench/engine/rest/transfertypes/LiveScenarioView.java
View File

@ -19,7 +19,6 @@ package io.nosqlbench.engine.rest.transfertypes;
import com.fasterxml.jackson.annotation.JsonProperty;
import com.fasterxml.jackson.annotation.JsonPropertyDescription;
import io.nosqlbench.engine.api.activityapi.core.progress.ProgressMeterDisplay;
import io.nosqlbench.engine.core.lifecycle.ScenarioResult;
import io.nosqlbench.engine.core.script.Scenario;
import java.util.ArrayList;
@ -29,21 +28,16 @@ import java.util.List;
public class LiveScenarioView {
private final Scenario scenario;
private final ScenarioResult result;
public LiveScenarioView(Scenario scenario, ScenarioResult result) {
public LiveScenarioView(Scenario scenario) {
this.scenario = scenario;
this.result = result;
}
@JsonProperty
@JsonPropertyDescription("Optionally populated result, "+
" present only if there was an error or the scenario is complete")
public ResultView getResult() {
if (result==null) {
return null;
}
return new ResultView(result);
return new ResultView(scenario.getResultIfComplete().orElse(null));
}
@JsonProperty("scenario_name")

15
engine-rest/src/main/java/io/nosqlbench/engine/rest/transfertypes/ResultView.java
View File

@ -27,14 +27,17 @@ public class ResultView {
}
public String getIOLog() {
return result.getIOLog();
}
public String getError() {
if (result.getException().isPresent()) {
return result.getException().get().getMessage();
if (result!=null) {
return result.getIOLog();
} else {
return "";
}
}
public String getError() {
if (result!=null && result.getException().isPresent()) {
return result.getException().get().getMessage();
}
return "";
}
}

2
nbr/src/test/java/io/nosqlbench/cli/testing/ExitStatusIntegrationTests.java
View File

@ -78,7 +78,7 @@ class ExitStatusIntegrationTests {
invoker.setLogDir("logs/test");
ProcessResult result = invoker.run("exitstatus_asyncstoprequest", 30,
"java", "-jar", JARNAME, "--logs-dir", "logs/test/asyncstop", "--logs-level", "debug", "run",
"driver=diag", "cyclerate=10", "op=erroroncycle:erroroncycle=10", "cycles=500", "-vvv"
"driver=diag", "threads=2", "cyclerate=10", "op=erroroncycle:erroroncycle=10", "cycles=500", "-vvv"
);
assertThat(result.exception).isNull();
String stdout = String.join("\n", result.getStdoutData());