Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Compute client waiting time without including testing framework time #54

Merged
merged 1 commit into from
Nov 19, 2023
Merged

Compute client waiting time without including testing framework time #54

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
55 changes: 43 additions & 12 deletions framework/tst/dslabs/framework/testing/ClientWorker.java
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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