Skip to content

Commit

Permalink
Compute client waiting time without including testing framework time
Browse files Browse the repository at this point in the history 
This commit adds a private field to RunState to track when the system
under test was most recently stopped. Then, when checking ClientWorkers'
maximum wait times, we use that time as the basis for computing the
maximum wait time.

Co-authored-by: James Wilcox <[email protected]>
  • Loading branch information
@emichael @wilcoxjay
emichael and wilcoxjay committed Jul 11, 2023
1 parent 45d2c5b commit 5447d45
Show file tree
Hide file tree
Showing 3 changed files with 103 additions and 25 deletions.
55 changes: 43 additions & 12 deletions framework/tst/dslabs/framework/testing/ClientWorker.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -31,10 +31,13 @@
import dslabs.framework.Timer;
import dslabs.framework.VizIgnore;
import dslabs.framework.testing.utils.Cloning;
import java.time.Duration;
import java.time.Instant;
import java.util.ArrayList;
import java.util.List;
import java.util.Objects;
import java.util.function.Consumer;
import javax.annotation.Nullable;
import lombok.Data;
import lombok.EqualsAndHashCode;
import lombok.Getter;
Expand All @@ -44,8 +47,6 @@
import org.apache.commons.lang3.tuple.Pair;
import org.apache.commons.lang3.tuple.Triple;

import static org.apache.commons.lang3.math.NumberUtils.max;

@EqualsAndHashCode(of = {"client", "results"}, callSuper = false)
@ToString(of = {"client", "results"})
public final class ClientWorker extends Node {
Expand All @@ -71,15 +72,16 @@ private static class InterRequestTimer implements Timer {
@VizIgnore private boolean waitingToSend = false;
@VizIgnore private Command lastCommand = null;
@VizIgnore private Result expectedResult = null;
@VizIgnore private long lastSendTimeMillis;
@VizIgnore private Instant lastSendTime = null;

// Resulting state
@Getter @VizIgnore private final List<Command> sentCommands =
new ArrayList<>();
@Getter private final List<Result> results = new ArrayList<>();
@Getter @VizIgnore private boolean resultsOk = true;
@Getter @VizIgnore private Pair<Result, Result> expectedAndReceived = null;
@VizIgnore private long maxWaitTimeMillis = 0;
@VizIgnore private Duration maxWaitTime = Duration.ZERO;
@VizIgnore private Instant maxWaitTimeSendTime = null;


public <C extends Node & Client> ClientWorker(@NonNull C client,
Expand Down Expand Up @@ -118,12 +120,37 @@ public synchronized void addCommand(String command, String result) {
sendNextCommandWhilePossible();
}

public synchronized long maxWaitTimeMilis() {
if (waitingOnResult) {
return max(maxWaitTimeMillis,
System.currentTimeMillis() - lastSendTimeMillis);
/**
* Compute the maximum time this client has waited to receive the result of
* a command, assuming that the system stopped running at {@code stopTime}.
*
* <p>If {@code stopTime} is {@code null}, this method assumes that the
* system is still running and takes the current time when computing how
* long it has waited for the most recently sent command.
*
* @return the maximum amount of time the client waited, along with the time
* it sent the command it waited the most time for. Returns {@code null} if
* it never sent a command.
*/
public synchronized @Nullable Pair<Duration, Instant> maxWaitTime(
@Nullable Instant stopTime) {
if (!waitingOnResult) {
if (maxWaitTimeSendTime != null) {
return ImmutablePair.of(maxWaitTime, maxWaitTimeSendTime);
}
return null;
}
if (stopTime == null) {
stopTime = Instant.now();
}
return maxWaitTimeMillis;
Duration currentWaitTime = Duration.between(lastSendTime, stopTime);
if (currentWaitTime.compareTo(maxWaitTime) > 0) {
return ImmutablePair.of(currentWaitTime, lastSendTime);
}
if (maxWaitTimeSendTime != null) {
return ImmutablePair.of(maxWaitTime, maxWaitTimeSendTime);
}
return null;
}

private void sendNextCommandWhilePossible() {
Expand All @@ -148,8 +175,12 @@ private void sendNextCommandWhilePossible() {
results.add(result);
}

maxWaitTimeMillis = max(maxWaitTimeMillis,
System.currentTimeMillis() - lastSendTimeMillis);
Duration waitTime =
Duration.between(lastSendTime, Instant.now());
if (waitTime.compareTo(maxWaitTime) > 0) {
maxWaitTime = waitTime;
maxWaitTimeSendTime = lastSendTime;
}

if (workload.hasResults() &&
!Objects.equals(expectedResult, result)) {
Expand Down Expand Up @@ -205,7 +236,7 @@ private void sendNextCommand() {

waitingToSend = false;
waitingOnResult = true;
lastSendTimeMillis = System.currentTimeMillis();
lastSendTime = Instant.now();
}

public synchronized boolean done() {
Expand Down
33 changes: 22 additions & 11 deletions framework/tst/dslabs/framework/testing/junit/BaseJUnitTest.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -41,6 +41,8 @@
import dslabs.framework.testing.utils.GlobalSettings;
import dslabs.framework.testing.visualization.DebuggerWindow;
import java.text.DecimalFormat;
import java.time.Duration;
import java.time.Instant;
import java.util.ArrayList;
import java.util.HashSet;
import java.util.List;
Expand Down Expand Up @@ -229,19 +231,27 @@ protected final void sendCommandAndCheck(Client client, Command command,

protected final void assertMaxWaitTimeLessThan(long allowedMillis) {
// TODO: maybe shut the runstate and threads down here

long maxWaitTimeMillis = 0;
Instant stopTime = runState.stopTime();
Duration maxWaitTime = Duration.ZERO;
for (ClientWorker cw : runState.clientWorkers()) {
long t = cw.maxWaitTimeMilis();
if (t > allowedMillis) {
fail(String.format("%s waited too long, %s ms (%s ms allowed)",
cw.address(), t, allowedMillis));
var maxWait = cw.maxWaitTime(stopTime);
if (maxWait == null) {
continue;
}
Duration waitTime = maxWait.getLeft();
if (waitTime.toMillis() > allowedMillis) {
fail(String.format(
"%s waited too long, %s ms (%s ms allowed) starting %s",
cw.address(), waitTime.toMillis(), allowedMillis,
maxWait.getRight()));
}
if (waitTime.compareTo(maxWaitTime) > 0) {
maxWaitTime = waitTime;
}
maxWaitTimeMillis = Math.max(maxWaitTimeMillis, t);
}

System.out.printf("Maximum client wait time %s ms (%s ms allowed)%n",
maxWaitTimeMillis, allowedMillis);
maxWaitTime.toMillis(), allowedMillis);
}


Expand Down Expand Up @@ -334,7 +344,8 @@ private void assertEndConditionValid() {
} else {
exception.printStackTrace();
System.err.println(
"\nException thrown by nodes during search. Visualization started.\n");
"\nException thrown by nodes during search. " +
"Visualization started.\n");
}

throw new VizStarted();
Expand Down Expand Up @@ -439,8 +450,8 @@ protected final void assertSpaceExhausted() {
}

private void failTestAndContinue() {
System.err.println(
"Search test failed. Continuing to run the rest of the test...\n");
System.err.println("Search test failed. " +
"Continuing to run the rest of the test...\n");
failedSearchTest = true;
}

Expand Down
40 changes: 38 additions & 2 deletions framework/tst/dslabs/framework/testing/runner/RunState.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -36,10 +36,13 @@
import dslabs.framework.testing.TimerEnvelope;
import dslabs.framework.testing.runner.Network.Inbox;
import dslabs.framework.testing.utils.Cloning;
import java.time.Duration;
import java.time.Instant;
import java.util.Collections;
import java.util.HashMap;
import java.util.Map;
import java.util.Set;
import javax.annotation.Nullable;
import lombok.Getter;
import lombok.ToString;
import lombok.extern.java.Log;
Expand All @@ -63,6 +66,11 @@ public class RunState extends AbstractState {
private final Map<Address, Thread> nodeThreads = new HashMap<>();
private long startTimeMillis;
private boolean running = false, shuttingDown = false;
/**
* The time the system was most recently stopped, {@code null} if this
* {@link RunState} was never started or is currently running.
*/
private Instant stopTime = null;

// TODO: memoize important settings (e.g. multithreaded) at start time to
// ensure safety (even though they should never be modified)
Expand Down Expand Up @@ -228,11 +236,13 @@ public void run(RunSettings settings) throws InterruptedException {
synchronized (this) {
if (running) {
LOG.warning(
"Cannot run state, either currently running or not yet shutdown completely");
"Cannot run state, either currently running or " +
"not yet shutdown completely");
return;
}

this.running = true;
this.stopTime = null;
this.settings = settings;
this.startTimeMillis = System.currentTimeMillis();
this.mainThread = Thread.currentThread();
Expand All @@ -258,6 +268,9 @@ public void run(RunSettings settings) throws InterruptedException {
this.running = false;
}
this.mainThread = null;
if (stopTime == null) {
stopTime = Instant.now();
}
notifyAll();
}
}
Expand All @@ -274,12 +287,14 @@ private synchronized boolean startInternal(RunSettings settings) {

if (running) {
LOG.warning(
"Cannot start state, either currently running or not yet shutdown completely");
"Cannot start state, either currently running or not yet " +
"shutdown completely");
return false;
}

this.settings = settings;
this.running = true;
this.stopTime = null;
this.startTimeMillis = System.currentTimeMillis();

if (this.settings.multiThreaded()) {
Expand Down Expand Up @@ -332,13 +347,19 @@ public synchronized void stop() throws InterruptedException {
shuttingDown = true;

// Interrupt all threads
Instant prewait = Instant.now();
if (mainThread != null) {
mainThread.interrupt();
}
for (Thread t : nodeThreads.values()) {
t.interrupt();
}

// Log the stop time at the moment we start shutting down the threads.
if (stopTime == null) {
stopTime = Instant.now();
}

// Wait on all threads
try {
while (mainThread != null || !nodeThreads.isEmpty()) {
Expand All @@ -349,9 +370,24 @@ public synchronized void stop() throws InterruptedException {
notifyAll();
}

Duration timeWaited = Duration.between(prewait, Instant.now());
if (timeWaited.compareTo(Duration.ofSeconds(1)) > 0) {
LOG.warning("Took more than one second (" + timeWaited +
"ms) to shutdown threads. This likely indicates a " +
"performance bug in your system where a single " +
"message/timer takes more than a second to process.");
}

running = false;
}

/**
* If the system is stopped, return the time that it stopped at. Otherwise,
* return {@code null}.
*/
public synchronized @Nullable Instant stopTime() {
return stopTime;
}

@Override
public Iterable<TimerEnvelope> timers(Address address) {
Expand Down

0 comments on commit 5447d45

Please sign in to comment.