All tests passing. Stubbed out performance metrics tests and added bot frame performance test

dgant · dgant · commit 20f9d005877b · 2020-08-14T14:32:28.000-04:00
diff --git a/src/main/java/bwapi/BotWrapper.java b/src/main/java/bwapi/BotWrapper.java
@@ -194,17 +194,18 @@ private Thread createBotThread() {
 
     private void handleEvents() {
         ClientData.GameData gameData = game.clientData().gameData();
-        if (gameData.getFrameCount() > 0 || ! configuration.unlimitedFrameZero) {
-            performanceMetrics.botResponse.startTiming();
-        }
 
         // Populate gameOver before invoking event handlers (in case the bot throws)
         for (int i = 0; i < gameData.getEventCount(); i++) {
             gameOver = gameOver || gameData.getEvents(i).getType() == EventType.MatchEnd;
         }
-        for (int i = 0; i < gameData.getEventCount(); i++) {
-            EventHandler.operation(eventListener, game, gameData.getEvents(i));
-        }
-        performanceMetrics.botResponse.stopTiming();
+
+        performanceMetrics.botResponse.timeIf(
+            ! gameOver && (gameData.getFrameCount() > 0 || ! configuration.unlimitedFrameZero),
+            () -> {
+                for (int i = 0; i < gameData.getEventCount(); i++) {
+                    EventHandler.operation(eventListener, game, gameData.getEvents(i));
+                }
+            });
     }
 }
diff --git a/src/main/java/bwapi/PerformanceMetric.java b/src/main/java/bwapi/PerformanceMetric.java
@@ -2,6 +2,9 @@
 
 import java.text.DecimalFormat;
 
+/**
+ * Aggregates labeled time series data.
+ */
 public class PerformanceMetric {
     private final String name;
     private final long maxAllowed;
@@ -22,19 +25,45 @@ public class PerformanceMetric {
         this.maxAllowed = maxAllowed;
     }
 
+    /**
+     * Records the duration of a function call.
+     * @param runnable The function to time
+     */
     void time(Runnable runnable) {
         startTiming();
         runnable.run();
         stopTiming();
     }
 
+    /**
+     * Convenience method; calls a function; but only records the duration if a condition is met
+     * @param condition Whether to record the function call duration
+     * @param runnable The function to call
+     */
+    void timeIf(boolean condition, Runnable runnable) {
+        if (condition) {
+            time(runnable);
+        } else {
+            runnable.run();
+        }
+    }
+
+    /**
+     * Manually start timing.
+     * The next call to stopTiming() will record the duration in fractional milliseconds.
+     */
     void startTiming() {
         if (timeStarted > 0) {
             ++interrupted;
         }
         timeStarted = System.nanoTime();
     }
 
+
+   /**
+     * Manually stop timing.
+     * If paired with a previous call to startTiming(), records the measured time between the calls in fractional milliseconds.
+     */
     void stopTiming() {
         if (timeStarted <= 0) return;
         // Use nanosecond resolution timer, but record in units of milliseconds.
@@ -44,6 +73,9 @@ void stopTiming() {
         record(timeDiff / 1000000d);
     }
 
+    /**
+     * Manually records a specific value.
+     */
     void record(double value) {
         lastValue = value;
         minValue = Math.min(minValue, value);
@@ -54,8 +86,12 @@ void record(double value) {
             avgValueExceeding = (avgValueExceeding * samplesExceeding + value) / (samplesExceeding + 1d);
             ++samplesExceeding;
         }
+        System.out.println(name + " #" + samples + " = " + value); // TODO: REMOVE
     }
 
+    /**
+     * @return A pretty-printed description of the recorded values.
+     */
     @Override
     public String toString() {
         DecimalFormat formatter = new DecimalFormat("###,###.#");
diff --git a/src/test/java/bwapi/SynchronizationEnvironment.java b/src/test/java/bwapi/SynchronizationEnvironment.java
@@ -63,12 +63,20 @@ ClientData.GameData liveGameData() {
         return client.clientData().gameData();
     }
 
+    PerformanceMetrics metrics() {
+        return bwClient.getPerformanceMetrics();
+    }
+
     void onFrame(Integer frame, Runnable runnable) {
         onFrames.put(frame, runnable);
-        onEndFrame = Math.max(onEndFrame, frame + 1);
     }
 
     void runGame() {
+        runGame(10);
+    }
+
+    void runGame(int onEndFrame) {
+        this.onEndFrame = onEndFrame;
         if (configuration.async) {
             final long MEGABYTE = 1024 * 1024;
             long memoryFree = Runtime.getRuntime().freeMemory() / MEGABYTE;
diff --git a/src/test/java/bwapi/SynchronizationTest.java b/src/test/java/bwapi/SynchronizationTest.java
@@ -1,18 +1,12 @@
 package bwapi;
 
-import static org.assertj.core.api.Assertions.assertThat;
-import static org.junit.Assert.assertEquals;
-import static org.junit.Assert.assertNull;
-import static org.junit.Assert.assertThrows;
-import static org.mockito.Mockito.*;
+import org.junit.Test;
 
-import java.util.HashMap;
-import java.util.Map;
 import java.util.stream.IntStream;
 
-import org.junit.Rule;
-import org.junit.Test;
-import org.junit.rules.Timeout;
+import static org.junit.Assert.assertEquals;
+import static org.junit.Assert.assertThrows;
+import static org.junit.Assert.assertTrue;
 
 public class SynchronizationTest {
 
@@ -24,6 +18,26 @@ private void sleepUnchecked(int milliseconds) {
         }
     }
 
+    private String describeApproximateExpectation(double expected, double actual, double margin) {
+        return "Expected " + expected + " == " + actual + " +/- " + margin;
+    }
+
+    private boolean measureApproximateEquality(double expected, double actual, double margin) {
+        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),
+                measureApproximateEquality(expected, actual, margin));
+    }
+
     @Test
     public void sync_IfException_ThrowException() throws InterruptedException {
         SynchronizationEnvironment environment = new SynchronizationEnvironment();
@@ -48,6 +62,7 @@ public void sync_IfDelay_ThenNoBuffer() throws InterruptedException {
         environment.configuration.async = false;
         environment.configuration.asyncFrameDurationMs = 1;
         environment.configuration.asyncFrameBufferSize = 3;
+
         IntStream.range(0, 5).forEach(frame -> {
             environment.onFrame(frame, () -> {
                 sleepUnchecked(5);
@@ -61,17 +76,163 @@ public void sync_IfDelay_ThenNoBuffer() throws InterruptedException {
     }
 
     @Test
-    public void async_IfDelay_ThenBuffer() throws InterruptedException {
+    public void async_IfBotDelay_ThenClientBuffers() throws InterruptedException {
         SynchronizationEnvironment environment = new SynchronizationEnvironment();
         environment.configuration.async = true;
-        environment.configuration.asyncFrameDurationMs = 1;
+        environment.configuration.asyncFrameDurationMs = 10;
         environment.configuration.asyncFrameBufferSize = 4;
+
         environment.onFrame(1, () -> {
-            sleepUnchecked(5);
+            sleepUnchecked(40);
             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());
         });
+
+        environment.onFrame(6, () -> { // Maybe it should be possible to demand that these assertions pass a frame earlier?
+            assertEquals("Bot should be observing the live frame", 6, environment.bwClient.getGame().getFrameCount());
+            assertEquals("Client should not be ahead of the bot", 6, environment.liveGameData().getFrameCount());
+            assertEquals("Bot should not be behind the live game", 0, environment.bwClient.framesBehind());
+        });
+
+        environment.runGame();
+    }
+
+    @Test
+    public void async_IfBotDelay_ThenClientStalls() throws InterruptedException {
+        SynchronizationEnvironment environment = new SynchronizationEnvironment();
+        environment.configuration.async = true;
+        environment.configuration.asyncFrameDurationMs = 50;
+        environment.configuration.asyncFrameBufferSize = 5;
+
+        environment.onFrame(1, () -> {
+            sleepUnchecked(125);
+            assertEquals("3: Bot should be observing an old frame", 1, environment.bwClient.getGame().getFrameCount());
+            assertEquals("3: Client should have progressed as slowly as possible", 3, environment.liveGameData().getFrameCount());
+            assertEquals("3: Bot should be behind the live game by as little as possible", 2, environment.bwClient.framesBehind());
+            sleepUnchecked(50);
+            assertEquals("4: Bot should be observing an old frame", 1, environment.bwClient.getGame().getFrameCount());
+            assertEquals("4: Client should have progressed as slowly as possible", 4, environment.liveGameData().getFrameCount());
+            assertEquals("4: Bot should be behind the live game by as little as possible", 3, environment.bwClient.framesBehind());
+            sleepUnchecked(50);
+            assertEquals("5: Bot should be observing an old frame", 1, environment.bwClient.getGame().getFrameCount());
+            assertEquals("5: Client should have progressed as slowly as possible", 5, environment.liveGameData().getFrameCount());
+            assertEquals("5: Bot should be behind the live game by as little as possible", 4, environment.bwClient.framesBehind());
+        });
+
         environment.runGame();
     }
+
+    @Test
+    public void async_IfFrameZeroWaitsEnabled_ThenAllowInfiniteTime() throws InterruptedException {
+        SynchronizationEnvironment environment = new SynchronizationEnvironment();
+        environment.configuration.async = true;
+        environment.configuration.unlimitedFrameZero = true;
+        environment.configuration.asyncFrameDurationMs = 5;
+        environment.configuration.asyncFrameBufferSize = 2;
+
+        environment.onFrame(0, () -> {
+            sleepUnchecked(50);
+            assertEquals("Bot should still be on frame zero", 0, environment.bwClient.getGame().getFrameCount());
+            assertEquals("Client should still be on frame zero", 0, environment.liveGameData().getFrameCount());
+            assertEquals("Bot should not be behind the live game", 0, environment.bwClient.framesBehind());
+        });
+
+        environment.runGame();
+    }
+
+    @Test
+    public void async_IfFrameZeroWaitsDisabled_ThenClientBuffers() throws InterruptedException {
+        SynchronizationEnvironment environment = new SynchronizationEnvironment();
+        environment.configuration.async = true;
+        environment.configuration.unlimitedFrameZero = false;
+        environment.configuration.asyncFrameDurationMs = 5;
+        environment.configuration.asyncFrameBufferSize = 2;
+
+        environment.onFrame(0, () -> {
+            sleepUnchecked(50);
+            assertEquals("Bot should still be on frame zero", 0, environment.bwClient.getGame().getFrameCount());
+            assertEquals("Client should have advanced to the next frame", 2, environment.liveGameData().getFrameCount());
+            assertEquals("Bot should be behind the live game", 2, environment.bwClient.framesBehind());
+        });
+
+        environment.runGame();
+    }
+
+    @Test
+    public void async_MeasurePerformance_TotalFrameDuration() {
+
+    }
+
+    @Test
+    public void async_MeasurePerformance_CopyingToBuffer() {
+
+    }
+
+    @Test
+    public void async_MeasurePerformance_IntentionallyBlocking() {
+
+    }
+
+    @Test
+    public void async_MeasurePerformance_FrameBufferSize() {
+
+    }
+
+    @Test
+    public void async_MeasurePerformance_FlushSideEffects() {
+
+    }
+
+    /**
+     * Number of milliseconds of leeway to give in performance metrics.
+     * Increase if tests are flaky due to variance in execution speed.
+     */
+    private final static long MS_MARGIN = 10;
+
+    @Test
+    public void async_MeasurePerformance_BotResponse() {
+        SynchronizationEnvironment environment = new SynchronizationEnvironment();
+
+        // Frame zero appears to take an extra 60ms, so let's disable timing for it
+        // (and also verify that we omit frame zero from performance metrics)
+        environment.configuration.unlimitedFrameZero = true;
+
+        environment.onFrame(1, () -> {
+            sleepUnchecked(100);
+        });
+        environment.onFrame(2, () -> {
+            assertWithin("2: Bot response average", 100, environment.metrics().botResponse.avgValue, MS_MARGIN);
+            assertWithin("2: Bot response minimum", 100, environment.metrics().botResponse.minValue, MS_MARGIN);
+            assertWithin("2: Bot response maximum", 100, environment.metrics().botResponse.maxValue, MS_MARGIN);
+            assertWithin("2: Bot response previous", 100, environment.metrics().botResponse.lastValue, MS_MARGIN);
+            sleepUnchecked(300);
+        });
+        environment.onFrame(3, () -> {
+            assertWithin("3: Bot response average", 200, environment.metrics().botResponse.avgValue, MS_MARGIN);
+            assertWithin("3: Bot response minimum", 100, environment.metrics().botResponse.minValue, MS_MARGIN);
+            assertWithin("3: Bot response maximum", 300, environment.metrics().botResponse.maxValue, MS_MARGIN);
+            assertWithin("3: Bot response previous", 300, environment.metrics().botResponse.lastValue, MS_MARGIN);
+            sleepUnchecked(200);
+        });
+
+        environment.runGame(4);
+
+        assertWithin("Final: Bot response average", 200, environment.metrics().botResponse.avgValue, MS_MARGIN);
+        assertWithin("Final: Bot response minimum", 100, environment.metrics().botResponse.minValue, MS_MARGIN);
+        assertWithin("Final: Bot response maximum", 300, environment.metrics().botResponse.maxValue, MS_MARGIN);
+        assertWithin("Final: Bot response previous", 200, environment.metrics().botResponse.lastValue, MS_MARGIN);
+    }
+
+    @Test
+    public void async_MeasurePerformance_BwapiResponse() {
+
+    }
+
+    @Test
+    public void async_MeasurePerformance_BotIdle() {
+
+    }
+
+
 }
