Finished asynchronous unit tests; fixed miscellaneous performance measurements

dgant · dgant · commit 0e35168251ee · 2020-08-16T01:41:17.000-04:00
diff --git a/src/main/java/bwapi/BWClient.java b/src/main/java/bwapi/BWClient.java
@@ -93,11 +93,11 @@ public void startGame(BWClientConfiguration configuration) {
                 }
                 botWrapper.onFrame();
                 performanceMetrics.flushSideEffects.time(() -> getGame().sideEffects.flushTo(liveGameData));
-                client.update();
+                performanceMetrics.totalFrameDuration.stopTiming();
+                performanceMetrics.bwapiResponse.time(client::update);
                 if (!client.isConnected()) {
                     client.reconnect();
                 }
-                performanceMetrics.totalFrameDuration.stopTiming();
             }
             botWrapper.endGame();
         } while (configuration.autoContinue);
diff --git a/src/main/java/bwapi/BotWrapper.java b/src/main/java/bwapi/BotWrapper.java
@@ -90,11 +90,10 @@ void onFrame() {
             Add a frame to buffer
             If buffer is full, it will wait until it has capacity
             Wait for empty buffer OR termination condition
-             */
+            */
             int frame = liveClientData.gameData().getFrameCount();
             configuration.log("Main: Enqueuing frame #" + frame);
             frameBuffer.enqueueFrame();
-            performanceMetrics.bwapiResponse.startTiming();
             frameBuffer.lockSize.lock();
             try {
                 while (!frameBuffer.empty()) {
@@ -122,7 +121,6 @@ void onFrame() {
             } catch(InterruptedException ignored) {
             } finally {
                 frameBuffer.lockSize.unlock();
-                performanceMetrics.bwapiResponse.stopTiming();
                 configuration.log("Main: onFrame asynchronous end");
             }
         } else {
@@ -158,17 +156,17 @@ private Thread createBotThread() {
                 while (!gameOver) {
 
                     configuration.log("Bot: Ready for another frame");
-                    frameBuffer.lockSize.lock();
-                    try {
-                        while (frameBuffer.empty()) {
-                            configuration.log("Bot: Waiting for a frame");
-                            performanceMetrics.botIdle.startTiming();
-                            frameBuffer.conditionSize.awaitUninterruptibly();
+                    performanceMetrics.botIdle.time(() -> {
+                        frameBuffer.lockSize.lock();
+                        try {
+                            while (frameBuffer.empty()) {
+                                configuration.log("Bot: Waiting for a frame");
+                                frameBuffer.conditionSize.awaitUninterruptibly();
+                            }
+                        } finally {
+                            frameBuffer.lockSize.unlock();
                         }
-                        performanceMetrics.botIdle.stopTiming();
-                    } finally {
-                        frameBuffer.lockSize.unlock();
-                    }
+                    });
 
                     configuration.log("Bot: Peeking next frame");
                     game.clientData().setBuffer(frameBuffer.peek());
diff --git a/src/main/java/bwapi/PerformanceMetrics.java b/src/main/java/bwapi/PerformanceMetrics.java
@@ -57,12 +57,19 @@ public class PerformanceMetrics {
      */
     public PerformanceMetric botIdle;
 
+    private BWClientConfiguration configuration;
+
     public PerformanceMetrics(BWClientConfiguration configuration) {
+        this.configuration = configuration;
+        reset();
+    }
+
+    void reset() {
         final int frameDurationBufferMs = 5;
         final int sideEffectsBufferMs = 1;
         final int realTimeFrameMs = 42;
         totalFrameDuration = new PerformanceMetric("Total frame duration", configuration.maxFrameDurationMs + frameDurationBufferMs);
-        copyingToBuffer = new PerformanceMetric("Time copying to buffer", 5);
+        copyingToBuffer = new PerformanceMetric("Time copying to buffer", 15);
         intentionallyBlocking = new PerformanceMetric("Intentionally blocking", 0);
         frameBufferSize = new PerformanceMetric("Frames buffered", 0);
         framesBehind = new PerformanceMetric("Frames behind", 0);
@@ -82,6 +89,7 @@ public String toString() {
                 + "\n" + framesBehind.toString()
                 + "\n" + flushSideEffects.toString()
                 + "\n" + botResponse.toString()
-                + "\n" + bwapiResponse.toString();
+                + "\n" + bwapiResponse.toString()
+                + "\n" + botIdle.toString();
     }
 }
diff --git a/src/test/java/bwapi/SynchronizationEnvironment.java b/src/test/java/bwapi/SynchronizationEnvironment.java
@@ -4,22 +4,19 @@
 import java.util.HashMap;
 import java.util.Map;
 
-import static com.sun.javafx.fxml.expression.Expression.greaterThan;
-import static org.assertj.core.api.Assertions.assertThat;
 import static org.junit.Assert.assertTrue;
 import static org.mockito.ArgumentMatchers.anyBoolean;
 import static org.mockito.Mockito.doAnswer;
 import static org.mockito.Mockito.mock;
 import static org.mockito.Mockito.when;
 
-import org.hamcrest.MatcherAssert.*;
-
 public class SynchronizationEnvironment {
     BWClientConfiguration configuration;
     BWClient bwClient;
     private BWEventListener listener;
     private Client client;
     private int onEndFrame;
+    private long bwapiDelayMs;
     private Map<Integer, Runnable> onFrames;
 
     SynchronizationEnvironment() {
@@ -29,6 +26,7 @@ public class SynchronizationEnvironment {
         bwClient = new BWClient(listener);
         bwClient.setClient(client);
         onEndFrame = -1;
+        bwapiDelayMs = 0;
         onFrames = new HashMap<>();
 
         when(client.mapFile()).thenReturn(GameBuilder.binToBufferUnchecked(GameBuilder.DEFAULT_BUFFER_PATH));
@@ -72,6 +70,10 @@ void onFrame(Integer frame, Runnable runnable) {
         onFrames.put(frame, runnable);
     }
 
+    void setBwapiDelayMs(long milliseconds) {
+        bwapiDelayMs = milliseconds;
+    }
+
     void runGame() {
         runGame(10);
     }
@@ -99,7 +101,8 @@ private int liveFrame() {
         return client.clientData().gameData().getFrameCount();
     }
 
-    private void clientUpdate() {
+    private void clientUpdate() throws InterruptedException{
+        Thread.sleep(bwapiDelayMs);
         client.clientData().gameData().setFrameCount(liveFrame() + 1);
         configuration.log("Test: clientUpdate() to liveFrame #" + liveFrame());
         if (liveFrame() == 0) {
diff --git a/src/test/java/bwapi/SynchronizationTest.java b/src/test/java/bwapi/SynchronizationTest.java
@@ -10,7 +10,7 @@
 
 public class SynchronizationTest {
 
-    private void sleepUnchecked(int milliseconds) {
+    private void sleepUnchecked(long milliseconds) {
         try {
             Thread.sleep(milliseconds);
         } catch(InterruptedException exception) {
@@ -26,12 +26,6 @@ private boolean measureApproximateEquality(double expected, double actual, doubl
         return expected + margin >= actual && expected - margin <= actual;
     }
 
-    private void assertWithin(double expected, double actual, double margin) {
-        assertTrue(
-                describeApproximateExpectation(expected, actual, margin),
-                measureApproximateEquality(expected, actual, margin));
-    }
-
     private void assertWithin(String message, double expected, double actual, double margin) {
         assertTrue(
                 message + ": " + describeApproximateExpectation(expected, actual, margin),
@@ -83,10 +77,10 @@ public void async_IfBotDelay_ThenClientBuffers() {
         environment.configuration.asyncFrameBufferSize = 4;
 
         environment.onFrame(1, () -> {
-            sleepUnchecked(40);
+            sleepUnchecked(50);
             assertEquals("Bot should be observing an old frame", 1, environment.bwClient.getGame().getFrameCount());
-            assertEquals("Client should be as far ahead as the frame buffer allows", 4, environment.liveGameData().getFrameCount());
-            assertEquals("Bot should be behind the live game", 3, environment.bwClient.framesBehind());
+            assertEquals("Client should be as far ahead as the frame buffer allows", 5, environment.liveGameData().getFrameCount());
+            assertEquals("Bot should be behind the live game", 4, environment.bwClient.framesBehind());
         });
 
         environment.onFrame(6, () -> { // Maybe it should be possible to demand that these assertions pass a frame earlier?
@@ -161,17 +155,36 @@ public void async_IfFrameZeroWaitsDisabled_ThenClientBuffers() {
 
     @Test
     public void async_MeasurePerformance_TotalFrameDuration() {
-
+        final int frames = 10;
+        final int frameSleep = 20;
+        SynchronizationEnvironment environment = new SynchronizationEnvironment();
+        environment.configuration.async = true;
+        environment.configuration.unlimitedFrameZero = true;
+        environment.configuration.maxFrameDurationMs = frameSleep + 20;
+        IntStream.range(0, frames).forEach(i -> environment.onFrame(i, () -> {
+            sleepUnchecked(frameSleep);
+        }));
+        environment.runGame(frames);
+
+        // Assume copying accounts for almost all the frame time except what the bot uses
+        double meanCopy = environment.metrics().copyingToBuffer.avgValue;
+        assertWithin("Total frame duration: Average", environment.metrics().totalFrameDuration.avgValue, meanCopy + frameSleep, MS_MARGIN);
     }
 
     @Test
     public void async_MeasurePerformance_CopyingToBuffer() {
-
-    }
-
-    @Test
-    public void async_MeasurePerformance_IntentionallyBlocking() {
-
+        // Somewhat lazy test; just verify that we're getting sane values
+        SynchronizationEnvironment environment = new SynchronizationEnvironment();
+        environment.configuration.async = true;
+        environment.runGame(20);
+        final double minObserved = 2;
+        final double maxObserved = 15;
+        final double meanObserved = (minObserved + maxObserved) / 2;
+        final double rangeObserved = (maxObserved - minObserved) / 2;
+        assertWithin("Copy to buffer: minimum", environment.metrics().copyingToBuffer.minValue, meanObserved, rangeObserved);
+        assertWithin("Copy to buffer: maximum", environment.metrics().copyingToBuffer.maxValue, meanObserved, rangeObserved);
+        assertWithin("Copy to buffer: average", environment.metrics().copyingToBuffer.avgValue, meanObserved, rangeObserved);
+        assertWithin("Copy to buffer: previous", environment.metrics().copyingToBuffer.lastValue, meanObserved, rangeObserved);
     }
 
     @Test
@@ -181,8 +194,7 @@ public void async_MeasurePerformance_FrameBufferSizeAndFramesBehind() {
         environment.configuration.unlimitedFrameZero = true;
         environment.configuration.asyncFrameBufferSize = 3;
         environment.configuration.maxFrameDurationMs = 20;
-        environment.configuration.logVerbosely = true;
-        
+
         environment.onFrame(5, () -> {
             assertWithin("5: Frame buffer average", 0, environment.metrics().frameBufferSize.avgValue, 0.1);
             assertWithin("5: Frame buffer minimum", 0, environment.metrics().frameBufferSize.minValue, 0.1);
@@ -208,13 +220,8 @@ public void async_MeasurePerformance_FrameBufferSizeAndFramesBehind() {
         environment.runGame(8);
     }
 
-    @Test
-    public void async_MeasurePerformance_FlushSideEffects() {
-
-    }
-
     /**
-     * Number of milliseconds of leeway to give in performance metrics.
+     * Number of milliseconds of leeway to give in potentially noisy performance metrics.
      * Increase if tests are flaky due to variance in execution speed.
      */
     private final static long MS_MARGIN = 10;
@@ -254,14 +261,48 @@ public void MeasurePerformance_BotResponse() {
     }
 
     @Test
-    public void async_MeasurePerformance_BwapiResponse() {
-
+    public void MeasurePerformance_BwapiResponse() {
+        final long bwapiDelayMs = 50;
+        SynchronizationEnvironment environment = new SynchronizationEnvironment();
+        environment.setBwapiDelayMs(bwapiDelayMs);
+        environment.runGame();
+        System.out.println(environment.metrics());
+        assertWithin("BWAPI Response: Average", environment.metrics().bwapiResponse.avgValue, bwapiDelayMs, MS_MARGIN);
     }
 
     @Test
-    public void async_MeasurePerformance_BotIdle() {
-
+    public void MeasurePerformance_BotIdle() {
+        final long bwapiDelayMs = 10;
+        final int frames = 10;
+        SynchronizationEnvironment environment = new SynchronizationEnvironment();
+        environment.configuration.async = true;
+        environment.configuration.asyncFrameBufferSize = 3;
+        environment.configuration.unlimitedFrameZero = true;
+        environment.setBwapiDelayMs(bwapiDelayMs);
+        environment.runGame(frames);
+        double expected = environment.metrics().copyingToBuffer.avgValue + bwapiDelayMs;
+        assertWithin("Bot Idle: Average", environment.metrics().botIdle.avgValue, expected, MS_MARGIN);
     }
 
-
+    @Test
+    public void async_MeasurePerformance_IntentionallyBlocking() {
+        SynchronizationEnvironment environment = new SynchronizationEnvironment();
+        environment.configuration.async = true;
+        environment.configuration.unlimitedFrameZero = true;
+        environment.configuration.asyncFrameBufferSize = 2;
+        environment.configuration.maxFrameDurationMs = 20;
+        final int frameDelayMs = 100;
+        environment.onFrame(1, () -> {
+            sleepUnchecked(100);
+        });
+        environment.onFrame(2, () -> {
+            assertWithin(
+                    "2: Intentionally blocking previous",
+                    environment.metrics().intentionallyBlocking.lastValue,
+                    frameDelayMs - environment.configuration.asyncFrameBufferSize * environment.configuration.maxFrameDurationMs,
+                    MS_MARGIN);
+            sleepUnchecked(100);
+        });
+        environment.runGame(3);
+    }
 }

Original file line number	Diff line number	Diff line change
`@@ -93,11 +93,11 @@ public void startGame(BWClientConfiguration configuration) {`
`93`	`93`	`}`
`94`	`94`	`botWrapper.onFrame();`
`95`	`95`	`performanceMetrics.flushSideEffects.time(() -> getGame().sideEffects.flushTo(liveGameData));`
`96`		`- client.update();`
	`96`	`+ performanceMetrics.totalFrameDuration.stopTiming();`
	`97`	`+ performanceMetrics.bwapiResponse.time(client::update);`
`97`	`98`	`if (!client.isConnected()) {`
`98`	`99`	`client.reconnect();`
`99`	`100`	`}`
`100`		`- performanceMetrics.totalFrameDuration.stopTiming();`
`101`	`101`	`}`
`102`	`102`	`botWrapper.endGame();`
`103`	`103`	`} while (configuration.autoContinue);`