Fixing performance metrics. Fixed framebuffer thinking it's full one frame too soon.

Author: dgant

src/main/java/bwapi/BWClientConfiguration.java

@@ -25,6 +25,14 @@ public class BWClientConfiguration {
      */
     public boolean unlimitedFrameZero = true;
 
+    /**
+     * The maximum amount of time the bot is supposed to spend on a single frame.
+     * In asynchronous mode, JBWAPI will attempt to let the bot use up to this much time to process all frames before returning control to BWAPI.
+     * In synchronous mode, JBWAPI is not empowered to prevent the bot to exceed this amount, but will record overruns in performance metrics.
+     * Real-time human play typically uses the "fastest" game speed, which has 42.86ms (42,860ns) between frames.
+     */
+    public int maxFrameDurationMs = 40;
+
     /**
      * Runs the bot in asynchronous mode. Asynchronous mode helps attempt to ensure that the bot adheres to real-time performance constraints.
      *
@@ -38,12 +46,6 @@ public class BWClientConfiguration {
      */
     public boolean async = false;
 
-    /**
-     * If JBWAPI detects that this much time (in nanoseconds) has passed since a bot's event handlers began, returns control back to BWAPI.
-     * Real-time human play typically uses the "fastest" game speed, which has 42.86ms (42,860ns) between frames.
-     */
-    public int asyncFrameDurationMs = 40;
-
     /**
      * The maximum number of frames to buffer while waiting on a bot.
      * Each frame buffered adds about 33 megabytes to JBWAPI's memory footprint.
@@ -59,8 +61,8 @@ public class BWClientConfiguration {
      * Checks that the configuration is in a valid state. Throws an IllegalArgumentException if it isn't.
      */
     public void validate() {
-        if (async && asyncFrameDurationMs < 0) {
-            throw new IllegalArgumentException("asyncFrameDurationMs needs to be a non-negative number (it's how long JBWAPI waits for a bot response before returning control to BWAPI).");
+        if (async && maxFrameDurationMs < 0) {
+            throw new IllegalArgumentException("maxFrameDurationMs needs to be a non-negative number (it's how long JBWAPI waits for a bot response before returning control to BWAPI).");
         }
         if (async && asyncFrameBufferSize < 1) {
             throw new IllegalArgumentException("asyncFrameBufferSize needs to be a positive number (There needs to be at least one frame buffer).");

src/main/java/bwapi/BotWrapper.java

@@ -46,7 +46,7 @@ class BotWrapper {
     BotWrapper(BWClientConfiguration configuration, BWEventListener eventListener) {
         this.configuration = configuration;
         this.eventListener = eventListener;
-        frameBuffer = configuration.async ? new FrameBuffer(configuration.asyncFrameBufferSize) : null;
+        frameBuffer = configuration.async ? new FrameBuffer(configuration) : null;
     }
 
     /**
@@ -79,7 +79,7 @@ void onFrame() {
         if (configuration.async) {
             configuration.log("Main: onFrame asynchronous start");
             long startNanos = System.nanoTime();
-            long endNanos = startNanos + configuration.asyncFrameDurationMs * 1000000;
+            long endNanos = startNanos + configuration.maxFrameDurationMs * 1000000;
             if (botThread == null) {
                 configuration.log("Main: Starting bot thread");
                 botThread = createBotThread();
@@ -98,7 +98,6 @@ void onFrame() {
             frameBuffer.lockSize.lock();
             try {
                 while (!frameBuffer.empty()) {
-                    configuration.log("Main: Waiting for empty frame buffer");
 
                     // Make bot exceptions fall through to the main thread.
                     Throwable lastThrow = getLastBotThrow();
@@ -108,12 +107,15 @@ void onFrame() {
                     }
 
                     if (configuration.unlimitedFrameZero && frame == 0) {
-                        configuration.log("Main: Waiting indefinitely on frame " + frame);
+                        configuration.log("Main: Waiting indefinitely on frame #" + frame);
                         frameBuffer.conditionSize.await();
                     } else {
                         long remainingNanos = endNanos - System.nanoTime();
-                        if (remainingNanos <= 0) break;
-                        configuration.log("Main: Waiting " + remainingNanos / 1000000 + "ms for bot");
+                        if (remainingNanos <= 0) {
+                            configuration.log("Main: Out of time in frame #" + frame);
+                            break;
+                        }
+                        configuration.log("Main: Waiting " + remainingNanos / 1000000 + "ms for bot on frame #" + frame);
                         frameBuffer.conditionSize.awaitNanos(remainingNanos);
                     }
                 }
@@ -155,11 +157,11 @@ private Thread createBotThread() {
                 configuration.log("Bot: Thread started");
                 while (!gameOver) {
 
-                    configuration.log("Bot: Attempting to handle next frame");
+                    configuration.log("Bot: Ready for another frame");
                     frameBuffer.lockSize.lock();
                     try {
                         while (frameBuffer.empty()) {
-                            configuration.log("Bot: Waiting for next frame");
+                            configuration.log("Bot: Waiting for a frame");
                             performanceMetrics.botIdle.startTiming();
                             frameBuffer.conditionSize.awaitUninterruptibly();
                         }
@@ -170,10 +172,11 @@ private Thread createBotThread() {
 
                     configuration.log("Bot: Peeking next frame");
                     game.clientData().setBuffer(frameBuffer.peek());
-                    performanceMetrics.frameBufferSize.record(frameBuffer.framesBuffered() - 1);
 
                     configuration.log("Bot: Handling frame #" + game.getFrameCount());
                     handleEvents();
+
+                    configuration.log("Bot: Events done. Dequeuing frame #" + game.getFrameCount());
                     frameBuffer.dequeue();
                 }
             } catch (Throwable throwable) {
@@ -200,6 +203,10 @@ private void handleEvents() {
             gameOver = gameOver || gameData.getEvents(i).getType() == EventType.MatchEnd;
         }
 
+        if (configuration.async) {
+            performanceMetrics.framesBehind.record(frameBuffer.framesBuffered() - 1);
+        }
+
         performanceMetrics.botResponse.timeIf(
             ! gameOver && (gameData.getFrameCount() > 0 || ! configuration.unlimitedFrameZero),
             () -> {

src/main/java/bwapi/FrameBuffer.java

@@ -41,6 +41,7 @@ class FrameBuffer {
 
     private ByteBuffer liveData;
     private PerformanceMetrics performanceMetrics;
+    private BWClientConfiguration configuration;
     private int size;
     private int stepGame = 0;
     private int stepBot = 0;
@@ -51,8 +52,9 @@ class FrameBuffer {
     final Lock lockSize = new ReentrantLock();
     final Condition conditionSize = lockSize.newCondition();
 
-    FrameBuffer(int size) {
-        this.size = size;
+    FrameBuffer(BWClientConfiguration configuration) {
+        this.size = configuration.asyncFrameBufferSize;
+        this.configuration = configuration;
         while(dataBuffer.size() < size) {
             dataBuffer.add(ByteBuffer.allocateDirect(BUFFER_SIZE));
         }
@@ -94,7 +96,7 @@ boolean empty() {
     boolean full() {
         lockSize.lock();
         try {
-            return framesBuffered() >= size - 1;
+            return framesBuffered() >= size;
         } finally {
             lockSize.unlock();
         }
@@ -117,6 +119,7 @@ void enqueueFrame() {
             lockSize.lock();
             try {
                 while (full()) {
+                    configuration.log("Main: Waiting for frame buffer capacity");
                     performanceMetrics.intentionallyBlocking.startTiming();
                     conditionSize.awaitUninterruptibly();
                 }
@@ -130,6 +133,7 @@ void enqueueFrame() {
 
             lockSize.lock();
             try {
+                performanceMetrics.frameBufferSize.record(framesBuffered());
                 ++stepGame;
                 conditionSize.signalAll();
             } finally { lockSize.unlock(); }

src/main/java/bwapi/PerformanceMetric.java

@@ -86,7 +86,7 @@ void record(double value) {
             avgValueExceeding = (avgValueExceeding * samplesExceeding + value) / (samplesExceeding + 1d);
             ++samplesExceeding;
         }
-        System.out.println(name + " #" + samples + " = " + value); // TODO: REMOVE
+        System.out.println("Metric: " + name + " (n=" + samples + "): " + value); // TODO: REMOVE
     }
 
     /**

src/main/java/bwapi/PerformanceMetrics.java

@@ -25,11 +25,17 @@ public class PerformanceMetrics {
     public PerformanceMetric intentionallyBlocking;
 
     /**
-     * Number of frames backed up in the frame buffer, after releasing each frame.
+     * Number of frames backed up in the frame buffer, after enqueuing each frame (and not including the newest frame).
      * Applicable only in asynchronous mode.
      */
     public PerformanceMetric frameBufferSize;
 
+    /**
+     * Number of frames behind real-time the bot is at the time it handles events.
+     * Applicable only in asynchronous mode.
+     */
+    public PerformanceMetric framesBehind;
+
     /**
      * Time spent applying bot commands to the live frame.
      */
@@ -55,13 +61,14 @@ public PerformanceMetrics(BWClientConfiguration configuration) {
         final int frameDurationBufferMs = 5;
         final int sideEffectsBufferMs = 1;
         final int realTimeFrameMs = 42;
-        totalFrameDuration = new PerformanceMetric("Total frame duration", configuration.asyncFrameDurationMs + frameDurationBufferMs);
+        totalFrameDuration = new PerformanceMetric("Total frame duration", configuration.maxFrameDurationMs + frameDurationBufferMs);
         copyingToBuffer = new PerformanceMetric("Time copying to buffer", 5);
         intentionallyBlocking = new PerformanceMetric("Intentionally blocking", 0);
         frameBufferSize = new PerformanceMetric("Frames buffered", 0);
+        framesBehind = new PerformanceMetric("Frames behind", 0);
         flushSideEffects = new PerformanceMetric("Flush side effects", sideEffectsBufferMs );
-        botResponse = new PerformanceMetric("Bot Responses", configuration.asyncFrameDurationMs);
-        bwapiResponse = new PerformanceMetric("BWAPI Responses", realTimeFrameMs);
+        botResponse = new PerformanceMetric("Bot responses", configuration.maxFrameDurationMs);
+        bwapiResponse = new PerformanceMetric("BWAPI responses", realTimeFrameMs);
         botIdle = new PerformanceMetric("Bot idle", Long.MAX_VALUE);
     }
 
@@ -72,6 +79,7 @@ public String toString() {
                 + "\n" + copyingToBuffer.toString()
                 + "\n" + intentionallyBlocking.toString()
                 + "\n" + frameBufferSize.toString()
+                + "\n" + framesBehind.toString()
                 + "\n" + flushSideEffects.toString()
                 + "\n" + botResponse.toString()
                 + "\n" + bwapiResponse.toString();

src/test/java/bwapi/SynchronizationEnvironment.java

@@ -52,8 +52,9 @@ public class SynchronizationEnvironment {
         }).when(listener).onEnd(anyBoolean());
         doAnswer(answer -> {
             configuration.log("Test: onFrame()");
-            if (onFrames.containsKey(liveFrame())) {
-                onFrames.get(liveFrame()).run();
+            int botFrame = bwClient.getGame().getFrameCount();
+            if (onFrames.containsKey(botFrame)) {
+                onFrames.get(botFrame).run();
             }
             return null;
         }).when(listener).onFrame();

src/test/java/bwapi/SynchronizationTest.java

@@ -39,15 +39,15 @@ private void assertWithin(String message, double expected, double actual, double
     }
 
     @Test
-    public void sync_IfException_ThrowException() throws InterruptedException {
+    public void sync_IfException_ThrowException() {
         SynchronizationEnvironment environment = new SynchronizationEnvironment();
         environment.configuration.async = false;
         environment.onFrame(0, () -> { throw new RuntimeException("Simulated bot exception"); });
         assertThrows(RuntimeException.class, environment::runGame);
     }
 
     @Test
-    public void async_IfException_ThrowException() throws InterruptedException {
+    public void async_IfException_ThrowException() {
         // An exception in the bot thread must be re-thrown by the main thread.
         SynchronizationEnvironment environment = new SynchronizationEnvironment();
         environment.configuration.async = true;
@@ -57,10 +57,10 @@ public void async_IfException_ThrowException() throws InterruptedException {
     }
 
     @Test
-    public void sync_IfDelay_ThenNoBuffer() throws InterruptedException {
+    public void sync_IfDelay_ThenNoBuffer() {
         SynchronizationEnvironment environment = new SynchronizationEnvironment();
         environment.configuration.async = false;
-        environment.configuration.asyncFrameDurationMs = 1;
+        environment.configuration.maxFrameDurationMs = 1;
         environment.configuration.asyncFrameBufferSize = 3;
 
         IntStream.range(0, 5).forEach(frame -> {
@@ -76,10 +76,10 @@ public void sync_IfDelay_ThenNoBuffer() throws InterruptedException {
     }
 
     @Test
-    public void async_IfBotDelay_ThenClientBuffers() throws InterruptedException {
+    public void async_IfBotDelay_ThenClientBuffers() {
         SynchronizationEnvironment environment = new SynchronizationEnvironment();
         environment.configuration.async = true;
-        environment.configuration.asyncFrameDurationMs = 10;
+        environment.configuration.maxFrameDurationMs = 10;
         environment.configuration.asyncFrameBufferSize = 4;
 
         environment.onFrame(1, () -> {
@@ -99,10 +99,10 @@ public void async_IfBotDelay_ThenClientBuffers() throws InterruptedException {
     }
 
     @Test
-    public void async_IfBotDelay_ThenClientStalls() throws InterruptedException {
+    public void async_IfBotDelay_ThenClientStalls() {
         SynchronizationEnvironment environment = new SynchronizationEnvironment();
         environment.configuration.async = true;
-        environment.configuration.asyncFrameDurationMs = 50;
+        environment.configuration.maxFrameDurationMs = 50;
         environment.configuration.asyncFrameBufferSize = 5;
 
         environment.onFrame(1, () -> {
@@ -124,11 +124,11 @@ public void async_IfBotDelay_ThenClientStalls() throws InterruptedException {
     }
 
     @Test
-    public void async_IfFrameZeroWaitsEnabled_ThenAllowInfiniteTime() throws InterruptedException {
+    public void async_IfFrameZeroWaitsEnabled_ThenAllowInfiniteTime() {
         SynchronizationEnvironment environment = new SynchronizationEnvironment();
         environment.configuration.async = true;
         environment.configuration.unlimitedFrameZero = true;
-        environment.configuration.asyncFrameDurationMs = 5;
+        environment.configuration.maxFrameDurationMs = 5;
         environment.configuration.asyncFrameBufferSize = 2;
 
         environment.onFrame(0, () -> {
@@ -142,11 +142,11 @@ public void async_IfFrameZeroWaitsEnabled_ThenAllowInfiniteTime() throws Interru
     }
 
     @Test
-    public void async_IfFrameZeroWaitsDisabled_ThenClientBuffers() throws InterruptedException {
+    public void async_IfFrameZeroWaitsDisabled_ThenClientBuffers() {
         SynchronizationEnvironment environment = new SynchronizationEnvironment();
         environment.configuration.async = true;
         environment.configuration.unlimitedFrameZero = false;
-        environment.configuration.asyncFrameDurationMs = 5;
+        environment.configuration.maxFrameDurationMs = 5;
         environment.configuration.asyncFrameBufferSize = 2;
 
         environment.onFrame(0, () -> {
@@ -175,8 +175,37 @@ public void async_MeasurePerformance_IntentionallyBlocking() {
     }
 
     @Test
-    public void async_MeasurePerformance_FrameBufferSize() {
+    public void async_MeasurePerformance_FrameBufferSizeAndFramesBehind() {
+        SynchronizationEnvironment environment = new SynchronizationEnvironment();
+        environment.configuration.async = true;
+        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);
+            assertWithin("5: Frame buffer maximum", 0, environment.metrics().frameBufferSize.maxValue, 0.1);
+            assertWithin("5: Frame buffer previous", 0, environment.metrics().frameBufferSize.lastValue, 0.1);
+            assertWithin("5: Frames behind average", 0, environment.metrics().framesBehind.avgValue, 0.1);
+            assertWithin("5: Frames behind minimum", 0, environment.metrics().framesBehind.minValue, 0.1);
+            assertWithin("5: Frames behind maximum", 0, environment.metrics().framesBehind.maxValue, 0.1);
+            assertWithin("5: Frames behind previous", 0, environment.metrics().framesBehind.lastValue, 0.1);
+            sleepUnchecked(200);
+        });
+        environment.onFrame(6, () -> {
+            assertWithin("6: Frame buffer average", 1 / 6.0 + 2 / 7.0, environment.metrics().frameBufferSize.avgValue, 0.1);
+            assertWithin("6: Frame buffer minimum", 0, environment.metrics().frameBufferSize.minValue, 0.1);
+            assertWithin("6: Frame buffer maximum", 2, environment.metrics().frameBufferSize.maxValue, 0.1);
+            assertWithin("6: Frame buffer previous", 2, environment.metrics().frameBufferSize.lastValue, 0.1);
+            assertWithin("6: Frames behind average", 1 / 6.0, environment.metrics().framesBehind.avgValue, 0.1);
+            assertWithin("6: Frames behind minimum", 0, environment.metrics().framesBehind.minValue, 0.1);
+            assertWithin("6: Frames behind maximum", 1, environment.metrics().framesBehind.maxValue, 0.1);
+            assertWithin("6: Frames behind previous", 1, environment.metrics().framesBehind.lastValue, 0.1);
+        });
 
+        environment.runGame(8);
     }
 
     @Test
@@ -191,7 +220,7 @@ public void async_MeasurePerformance_FlushSideEffects() {
     private final static long MS_MARGIN = 10;
 
     @Test
-    public void async_MeasurePerformance_BotResponse() {
+    public void MeasurePerformance_BotResponse() {
         SynchronizationEnvironment environment = new SynchronizationEnvironment();
 
         // Frame zero appears to take an extra 60ms, so let's disable timing for it