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

clear logging for scenario and activity lifecycle

Browse Source
This commit is contained in:
Jonathan Shook 2020-04-22 07:30:33 -05:00
parent 113932aed5
commit be93ee52ea
4 changed files with 56 additions and 5 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

1
engine-api/src/main/java/io/nosqlbench/engine/api/activityimpl/SimpleActivity.java
View File

@ -143,6 +143,7 @@ public class SimpleActivity implements Activity {
@Override
public void closeAutoCloseables() {
for (AutoCloseable closeable : closeables) {
logger.debug("CLOSING " + closeable.getClass().getCanonicalName() + ": " + closeable.toString());
try {
closeable.close();
} catch (Exception e) {

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

@ -51,7 +51,10 @@ import java.util.stream.Collectors;
*/
public class ActivityExecutor implements ActivityController, ParameterMap.Listener, ProgressMeter {
private static final Logger logger = LoggerFactory.getLogger(ActivityExecutor.class);
private static final Logger activitylogger = LoggerFactory.getLogger("ACTIVITY");
private final List<Motor<?>> motors = new ArrayList<>();
private final Activity activity;
private final ActivityDef activityDef;
@ -89,6 +92,7 @@ public class ActivityExecutor implements ActivityController, ParameterMap.Listen
*/
public synchronized void startActivity() {
logger.info("starting activity " + activity.getAlias() + " for cycles " + activity.getCycleSummary());
activitylogger.debug("START/before alias=(" + activity.getAlias() + ")");
try {
activity.setRunState(RunState.Starting);
activity.initActivity();
@ -96,17 +100,21 @@ public class ActivityExecutor implements ActivityController, ParameterMap.Listen
} catch (Exception e) {
this.stoppingException = new RuntimeException("Error initializing activity '" +
activity.getAlias() +"': " + e.getMessage(),e);
logger.error("error initializing activity '" + activity.getAlias() + "': " + stoppingException);
activitylogger.error("error initializing activity '" + activity.getAlias() + "': " + stoppingException);
throw stoppingException;
}
adjustToActivityDef(activity.getActivityDef());
activity.setRunState(RunState.Running);
activitylogger.debug("START/after alias=(" + activity.getAlias() + ")");
}
/**
* Simply stop the motors
*/
public synchronized void stopActivity() {
activitylogger.debug("STOP/before alias=(" + activity.getAlias() + ")");
activity.setRunState(RunState.Stopped);
logger.info("stopping activity in progress: " + this.getActivityDef().getAlias());
motors.forEach(Motor::requestStop);
@ -114,6 +122,8 @@ public class ActivityExecutor implements ActivityController, ParameterMap.Listen
activity.shutdownActivity();
activity.closeAutoCloseables();
logger.info("stopped: " + this.getActivityDef().getAlias() + " with " + motors.size() + " slots");
activitylogger.debug("STOP/after alias=(" + activity.getAlias() + ")");
}
/**
@ -122,6 +132,8 @@ public class ActivityExecutor implements ActivityController, ParameterMap.Listen
* @param initialMillisToWait milliseconds to wait after graceful shutdownActivity request, before forcing everything to stop
*/
public synchronized void forceStopExecutor(int initialMillisToWait) {
activitylogger.debug("FORCE STOP/before alias=(" + activity.getAlias() + ")");
activity.setRunState(RunState.Stopped);
executorService.shutdown();
@ -141,11 +153,17 @@ public class ActivityExecutor implements ActivityController, ParameterMap.Listen
logger.debug(runnables.size() + " threads never started.");
if (stoppingException!=null) {
activitylogger.debug("FORCE STOP/exception alias=(" + activity.getAlias() + ")");
throw stoppingException;
}
activitylogger.debug("FORCE STOP/after alias=(" + activity.getAlias() + ")");
}
public boolean requestStopExecutor(int secondsToWait) {
activitylogger.debug("REQUEST STOP/before alias=(" + activity.getAlias() + ")");
activity.setRunState(RunState.Stopped);
logger.info("Stopping executor for " + activity.getAlias() + " when work completes.");
@ -159,6 +177,7 @@ public class ActivityExecutor implements ActivityController, ParameterMap.Listen
logger.trace("interrupted while awaiting termination");
wasStopped = false;
logger.warn("while waiting termination of activity " + activity.getAlias() + ", " + ie.getMessage());
activitylogger.debug("REQUEST STOP/exception alias=(" + activity.getAlias() + ") wasstopped=" +wasStopped);
} finally {
logger.trace("finally shutting down activity " + this.getActivity().getAlias());
activity.shutdownActivity();
@ -169,6 +188,7 @@ public class ActivityExecutor implements ActivityController, ParameterMap.Listen
logger.trace("an exception caused the activity to stop:" + stoppingException.getMessage());
throw stoppingException;
}
activitylogger.debug("REQUEST STOP/after alias=(" + activity.getAlias() + ") wasstopped=" +wasStopped);
return wasStopped;
}
@ -209,13 +229,17 @@ public class ActivityExecutor implements ActivityController, ParameterMap.Listen
}
public boolean awaitFinish(int timeout) {
activitylogger.debug("AWAIT-FINISH/before alias=(" + activity.getAlias() + ")");
boolean awaited = awaitAllRequiredMotorState(timeout, 50, RunState.Finished, RunState.Stopped);
if (awaited) {
awaited = awaitCompletion(timeout);
}
if (stoppingException!=null) {
activitylogger.debug("AWAIT-FINISH/exception alias=(" + activity.getAlias() + ")");
throw stoppingException;
}
activitylogger.debug("AWAIT-FINISH/afte alias=(" + activity.getAlias() + ")");
return awaited;
}

26
engine-core/src/main/java/io/nosqlbench/engine/core/ScenarioController.java
View File

@ -35,6 +35,7 @@ import java.util.stream.Collectors;
public class ScenarioController {
private static final Logger logger = LoggerFactory.getLogger(ScenarioController.class);
private static final Logger scenariologger = LoggerFactory.getLogger("SCENARIO");
private final Map<String, ActivityExecutor> activityExecutors = new ConcurrentHashMap<>();
@ -45,7 +46,9 @@ public class ScenarioController {
* @param activityDef string in alias=value1;driver=value2;... format
*/
public synchronized void start(ActivityDef activityDef) {
getActivityExecutor(activityDef, true).startActivity();
ActivityExecutor activityExecutor = getActivityExecutor(activityDef, true);
scenariologger.debug("START " + activityDef.getAlias());
activityExecutor.startActivity();
}
/**
@ -82,8 +85,12 @@ public class ScenarioController {
*/
public synchronized void run(int timeout, ActivityDef activityDef) {
ActivityExecutor activityExecutor = getActivityExecutor(activityDef, true);
scenariologger.debug("RUN alias=" + activityDef.getAlias());
scenariologger.debug(" (RUN/START) alias=" + activityDef.getAlias());
activityExecutor.startActivity();
activityExecutor.awaitCompletion(timeout);
scenariologger.debug(" (RUN/AWAIT before) alias=" + activityDef.getAlias());
boolean completed = activityExecutor.awaitCompletion(timeout);
scenariologger.debug(" (RUN/AWAIT after) completed=" + activityDef.getAlias());
}
public synchronized void run(int timeout, String activityDefString) {
@ -131,6 +138,7 @@ public class ScenarioController {
if (activityExecutor == null) {
throw new RuntimeException("could not stop missing activity:" + activityDef);
}
scenariologger.debug("STOP " + activityDef.getAlias());
activityExecutor.stopActivity();
}
@ -170,6 +178,7 @@ public class ScenarioController {
}
ActivityExecutor activityExecutor = getActivityExecutor(alias);
ParameterMap params = activityExecutor.getActivityDef().getParams();
scenariologger.debug("SET ("+alias+"/"+param + ")=(" + value + ")");
params.set(param, value);
}
@ -268,6 +277,8 @@ public class ScenarioController {
* @param waitMillis time to wait, in milliseconds
*/
public void waitMillis(long waitMillis) {
scenariologger.debug("WAITMILLIS " + waitMillis);
logger.trace("#> waitMillis(" + waitMillis + ")");
long endTime = System.currentTimeMillis() + waitMillis;
@ -335,9 +346,12 @@ public class ScenarioController {
public boolean awaitCompletion(int waitTimeMillis) {
boolean completed = false;
for (ActivityExecutor executor : activityExecutors.values()) {
if (!executor.awaitCompletion(waitTimeMillis))
if (!executor.awaitCompletion(waitTimeMillis)) {
logger.debug("awaiting completion signaled FALSE");
return false;
}
}
logger.debug("All activities awaiting completion signaled TRUE");
return true;
}
@ -373,7 +387,11 @@ public class ScenarioController {
if (activityExecutor == null) {
throw new RuntimeException("Could not await missing activity: " + activityDef);
}
return activityExecutor.awaitFinish(Integer.MAX_VALUE);
scenariologger.debug("AWAIT/before alias=" + activityDef.getAlias());
boolean finished = activityExecutor.awaitFinish(Integer.MAX_VALUE);
scenariologger.debug("AWAIT/after completed=" + finished);
return finished;
}
/**

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

@ -138,10 +138,15 @@ public class Scenario implements Callable<ScenarioResult> {
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();
logger.debug("<- scenario completed (compiled)");
} else {
logger.debug("-> invoking main scenario script (interpreted)");
result = scriptEngine.eval(script);
logger.debug("<- scenario completed (interpreted)");
}
if (result!=null) {
logger.debug("scenario result: type(" + result.getClass().getCanonicalName() + "): value:" + result.toString());
}
@ -168,6 +173,9 @@ public class Scenario implements Callable<ScenarioResult> {
logger.error(errorDesc, o);
scenarioController.forceStopScenario(5000);
throw new RuntimeException("Non-Script error while running scenario:" + o.getMessage(), o);
} finally {
System.out.flush();
System.err.flush();
}
}
int awaitCompletionTime = 86400*365*1000;