Restored stepwise logging to monitor asynchronous steps

Author: dgant

src/main/java/bwapi/BWClientConfiguration.java

@@ -50,6 +50,11 @@ public class BWClientConfiguration {
      */
     public int asyncFrameBufferSize = 10;
 
+    /**
+     * Toggles verbose logging, particularly of synchronization steps.
+     */
+    public boolean logVerbosely = false;
+
     /**
      * Checks that the configuration is in a valid state. Throws an IllegalArgumentException if it isn't.
      */
@@ -61,4 +66,10 @@ public void validate() {
             throw new IllegalArgumentException("asyncFrameBufferSize needs to be a positive number (There needs to be at least one frame buffer).");
         }
     }
+
+    public void log(String value) {
+        if (logVerbosely) {
+            System.out.println(value);
+        }
+    }
 }

src/main/java/bwapi/BotWrapper.java

@@ -76,9 +76,11 @@ Game getGame() {
      */
     void onFrame() {
         if (configuration.async) {
+            configuration.log("Main: onFrame asynchronous start");
             long startNanos = System.nanoTime();
             long endNanos = startNanos + configuration.asyncFrameDurationMs * 1000000;
             if (botThread == null) {
+                configuration.log("Main: Starting bot thread");
                 botThread = createBotThread();
                 botThread.setName("JBWAPI Bot");
                 botThread.start();
@@ -88,35 +90,44 @@ void onFrame() {
             If buffer is full, it will wait until it has capacity
             Wait for empty buffer OR termination condition
              */
+            configuration.log("Main: Enqueuing frame");
             boolean isFrameZero = liveClientData.gameData().getFrameCount() == 0;
             frameBuffer.enqueueFrame();
             performanceMetrics.bwapiResponse.startTiming();
             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();
                     if (lastThrow != null) {
+                        configuration.log("Main: Rethrowing bot throwable");
                         throw new RuntimeException(lastThrow);
                     }
 
                     if (configuration.unlimitedFrameZero && isFrameZero) {
+                        configuration.log("Main: Waiting indefinitely on frame 0");
                         frameBuffer.conditionSize.await();
                     } else {
                         long remainingNanos = endNanos - System.nanoTime();
                         if (remainingNanos <= 0) break;
+                        configuration.log("Main: Waiting " + remainingNanos / 1000000 + "ms for bot");
                         frameBuffer.conditionSize.awaitNanos(remainingNanos);
                     }
                 }
             } catch(InterruptedException ignored) {
             } finally {
                 frameBuffer.lockSize.unlock();
                 performanceMetrics.bwapiResponse.stopTiming();
+                configuration.log("Main: onFrame asynchronous end");
             }
         } else {
+            configuration.log("Main: onFrame synchronous start");
             handleEvents();
+            configuration.log("Main: onFrame synchronous end");
         }
+
     }
 
     /**
@@ -139,20 +150,25 @@ Throwable getLastBotThrow() {
 
     private Thread createBotThread() {
         return new Thread(() -> {
+            configuration.log("Bot: Thread started");
             while ( ! gameOver) {
+                configuration.log("Bot: Attempting to handle next frame");
                 frameBuffer.lockSize.lock();
                 try {
                     while (frameBuffer.empty()) {
+                        configuration.log("Bot: Waiting for next frame");
                         performanceMetrics.botIdle.startTiming();
                         frameBuffer.conditionSize.awaitUninterruptibly();
                     }
                     performanceMetrics.botIdle.stopTiming();
                 } finally {
                     frameBuffer.lockSize.unlock();
                 }
+                configuration.log("Bot: Peeking next frame");
                 game.clientData().setBuffer(frameBuffer.peek());
                 performanceMetrics.frameBufferSize.record(frameBuffer.framesBuffered() - 1);
                 try {
+                    configuration.log("Bot: Handling frame #" + game.getFrameCount());
                     handleEvents();
                 } finally {
                     // In the case where t

src/main/java/bwapi/Game.java

@@ -142,7 +142,6 @@ private static boolean hasPower(final int x, final int y, final UnitType unitTyp
     Call this method in EventHander::OnMatchStart
     */
     void init() {
-        System.out.println("Game.init()"); // TODO: REMOVE!
         visibleUnits.clear();
 
         final int forceCount = gameData().getForceCount();

src/main/java/bwapi/PerformanceMetric.java

@@ -8,6 +8,7 @@ public class PerformanceMetric {
 
     public double minValue = Long.MAX_VALUE;
     public double maxValue = Long.MIN_VALUE;
+    public double lastValue = 0;
     public double avgValue = 0;
     public double avgValueExceeding = 0;
     public int samples = 0;
@@ -44,6 +45,7 @@ void stopTiming() {
     }
 
     void record(double value) {
+        lastValue = value;
         minValue = Math.min(minValue, value);
         maxValue = Math.max(maxValue, value);
         avgValue = (avgValue * samples + value) / (samples + 1d);

src/test/java/bwapi/SynchronizationTest.java

@@ -66,11 +66,12 @@ public void async_IfDelay_ThenBuffer() throws InterruptedException {
         environment.configuration.async = true;
         environment.configuration.asyncFrameDurationMs = 1;
         environment.configuration.asyncFrameBufferSize = 3;
+        environment.configuration.logVerbosely = true;
         environment.onFrame(1, () -> {
-            sleepUnchecked(5);
+            sleepUnchecked(50);
             assertEquals("Bot should be observing an old frame", 1, environment.bwClient.getGame().getFrameCount());
-            assertEquals("Bot should be behind the live game", 2, environment.bwClient.framesBehind());
             assertEquals("Client should be as far ahead as the frame buffer allows", 3, environment.liveGameData().getFrameCount());
+            assertEquals("Bot should be behind the live game", 2, environment.bwClient.framesBehind());
         });
         environment.runGame();
     }