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 Nov 19, 2023
1 parent 73e9e15 commit 64e99a4
Show file tree
Hide file tree
Showing 3 changed files with 99 additions and 20 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
30 changes: 22 additions & 8 deletions framework/tst/dslabs/framework/testing/junit/BaseJUnitTest.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -41,10 +41,14 @@
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.time.ZonedDateTime;
import java.util.ArrayList;
import java.util.HashSet;
import java.util.List;
import java.util.Set;
import java.util.TimeZone;
import lombok.SneakyThrows;
import org.junit.Rule;
import org.junit.rules.TestRule;
Expand Down Expand Up @@ -229,19 +233,29 @@ 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), started " +
"waiting at %s", cw.address(),
waitTime.toMillis(), allowedMillis,
ZonedDateTime.ofInstant(maxWait.getRight(),
TimeZone.getDefault().toZoneId())));
}
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
34 changes: 34 additions & 0 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 @@ -233,6 +241,7 @@ public void run(RunSettings settings) throws InterruptedException {
}

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

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

if (this.settings.multiThreaded()) {
Expand Down Expand Up @@ -332,13 +345,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 +368,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 64e99a4

Please sign in to comment.