Assembled complete suite of frame-duration and BWAPI communication performance metrics

dgant · dgant · commit ab695addf01f · 2020-09-25T22:07:04.000-04:00
diff --git a/src/main/java/bwapi/BWClient.java b/src/main/java/bwapi/BWClient.java
@@ -43,6 +43,13 @@ public BWClientConfiguration getConfiguration() {
         return configuration;
     }
 
+    /**
+     * @return Whether the current frame should be subject to timing.
+     */
+    boolean doTime() {
+        return ! configuration.unlimitedFrameZero || (client.isConnected() && client.clientData().gameData().getFrameCount() > 0);
+    }
+
     /**
      * @return The number of frames between the one exposed to the bot and the most recent received by JBWAPI.
      * This tracks the size of the frame buffer except when the game is paused (which results in multiple frames arriving with the same count).
@@ -114,32 +121,26 @@ public void startGame(BWClientConfiguration gameConfiguration) {
                 }
             }
             while (liveGameData.isInGame()) {
-                boolean timeFrame = liveGameData.getFrameCount() > 0 || ! configuration.unlimitedFrameZero;
-
                 long ticksBefore = Kernel32.INSTANCE.GetTickCount();
-                performanceMetrics.endToEndFrameDuration.startTiming();
-                performanceMetrics.jbwapiFrameDuration.timeIf(
-                    timeFrame,
-                    () -> {
-                        botWrapper.onFrame();
-                        performanceMetrics.flushSideEffects.time(() -> getGame().sideEffects.flushTo(liveGameData));
-                    });
+
+                botWrapper.onFrame();
+                performanceMetrics.flushSideEffects.time(() -> getGame().sideEffects.flushTo(liveGameData));
+                performanceMetrics.frameDurationReceiveToSend.stopTiming();
                 long ticksAfter = Kernel32.INSTANCE.GetTickCount();
-                if (timeFrame) {
+
+                // Measure differential between JVM timer and WinAPI's GetTickCount, used by BWAPI 4.4 and below
+                if (doTime()) {
                     long deltaTicks = ticksAfter - ticksBefore;
-                    long deltaMillis = (long) performanceMetrics.jbwapiFrameDuration.runningTotal.last;
+                    long deltaMillis = (long) performanceMetrics.frameDurationReceiveToSend.runningTotal.last;
                     long delta = deltaMillis - deltaTicks;
-                    if (Math.abs(delta) > 1000) {
-                        System.out.println("Got weird tick delta: " + ticksAfter + ", " + ticksBefore + ", " + deltaTicks + ", " + deltaMillis + ", " + delta);
-                        performanceMetrics.weirdTimeDelta.record(1);
-                    } else if (delta > 0) {
+                    if (delta > 0) {
                         performanceMetrics.positiveTimeDelta.record(delta);
                     } else if (delta < 0) {
                         performanceMetrics.negativeTimeDelta.record(-delta);
                     }
                 }
 
-                performanceMetrics.bwapiResponse.time(client::update);
+                client.update();
                 if (!client.isConnected()) {
                     System.out.println("Reconnecting...");
                     client.reconnect();
diff --git a/src/main/java/bwapi/Client.java b/src/main/java/bwapi/Client.java
@@ -231,11 +231,13 @@ boolean connect() {
     }
 
     void update() {
-        // Indicate that we are done with the current frame
-        byte code = 1;
+
+        // Tell BWAPI that we are done with the current frame
+        bwClient.getPerformanceMetrics().frameDurationReceiveToSend.stopTiming();
+        bwClient.getPerformanceMetrics().communicationSendToReceive.startTiming();
+        bwClient.getPerformanceMetrics().communicationSendToSent.startTiming();
         try {
-            pipeObjectHandle.writeByte(code);
-            bwClient.getPerformanceMetrics().endToEndFrameDuration.stopTiming();
+            pipeObjectHandle.writeByte(1); // The "frame done" signal
         }
         catch (Exception e) {
             System.err.println("failed, disconnecting");
@@ -245,27 +247,33 @@ void update() {
             disconnect();
             return;
         }
-        // Wait for BWAPI to indicate that a new frame is ready
-        while (code != 2) {
+        bwClient.getPerformanceMetrics().communicationSendToSent.stopTiming();
+        bwClient.getPerformanceMetrics().frameDurationReceiveToSent.stopTiming();
+
+        // Listen for BWAPI to indicate that a new frame is ready
+        bwClient.getPerformanceMetrics().communicationListenToReceive.startTiming();
+        byte code = 1;
+        while (code != 2) { // The "frame ready" signal
             try {
                 code = pipeObjectHandle.readByte();
-                /*
-                if (code != 2) {
-                    try {
-                        Thread.sleep(0, 1);
-                    } catch (InterruptedException ignored) {}
-                }
-                */
-            }
-            catch (Exception e) {
+            } catch (Exception e) {
                 System.err.println("failed, disconnecting");
                 if (bwClient.getConfiguration().debugConnection) {
                     e.printStackTrace();
                 }
                 disconnect();
-                return;
+                break;
             }
         }
+        bwClient.getPerformanceMetrics().communicationListenToReceive.stopTiming();
+        bwClient.getPerformanceMetrics().communicationSendToReceive.stopTiming();
+
+        if (bwClient.doTime()) {
+            bwClient.getPerformanceMetrics().frameDurationReceiveToSend.startTiming();
+            bwClient.getPerformanceMetrics().frameDurationReceiveToSent.startTiming();
+            bwClient.getPerformanceMetrics().frameDurationReceiveToReceive.stopTiming();
+            bwClient.getPerformanceMetrics().frameDurationReceiveToReceive.startTiming();
+        }
     }
 
     private void sleep(final int millis) {
diff --git a/src/main/java/bwapi/PerformanceMetric.java b/src/main/java/bwapi/PerformanceMetric.java
@@ -42,17 +42,18 @@ public String toString() {
     }
 
     private final String name;
-    public int interrupted = 0;
     private long timeStarted = 0;
+    public int interrupted = 0;
 
     RunningTotal runningTotal = new RunningTotal();
     private ArrayList<Threshold> thresholds = new ArrayList<>();
 
-    PerformanceMetric(String name, double... thresholds) {
+    PerformanceMetric(PerformanceMetrics metrics, String name, double... thresholds) {
         this.name = name;
         for (double threshold : thresholds) {
             this.thresholds.add(new Threshold(threshold));
         }
+        metrics.addMetric(this);
     }
 
     /**
@@ -121,7 +122,7 @@ public String toString() {
         }
         DecimalFormat formatter = new DecimalFormat("###,###.#");
         String output = name
-                + ": "
+                + ":\n"
                 + formatter.format(runningTotal.samples)
                     + " samples averaging "
                     + formatter.format(runningTotal.mean)
diff --git a/src/main/java/bwapi/PerformanceMetrics.java b/src/main/java/bwapi/PerformanceMetrics.java
@@ -1,25 +1,33 @@
 package bwapi;
 
+import java.util.ArrayList;
+
 /**
  * Collects various performance metrics.
  */
 public class PerformanceMetrics {
 
     /**
-     * Total duration of the frame from JBWAPI's perspective,
-     * exclusive of time modifying shared memory to indicate frame completion.
-     * Likely to be at least a little bit of an undercount from the perspective of BWAPI,
-     * given that the tournament module is timing a superset of JBWAPI's execution time.
+     * Duration of the frame cycle steps measured by BWAPI,
+     * from receiving a frame to BWAPI
+     * to sending commands back
+     * *exclusive* of the time spent sending commands back.
+     */
+    PerformanceMetric frameDurationReceiveToSend;
+
+    /**
+     * Duration of the frame cycle steps measured by BWAPI,
+     * from receiving a frame to BWAPI
+     * to sending commands back
+     * *inclusive* of the time spent sending commands back.
      */
-    PerformanceMetric jbwapiFrameDuration;
+    PerformanceMetric frameDurationReceiveToSent;
 
     /**
-     * Total duration of the frame from JBWAPI's perspective,
-     * inclusive of time modifying shared memory to indicate frame completion.
-     * Likely to be at least a little bit of an undercount from the perspective of BWAPI,
-     * given that the tournament module is timing a superset of JBWAPI's execution time.
+     * Duration of a frame cycle originating at
+     * the time when JBWAPI observes a new frame in shared memory.
      */
-    PerformanceMetric endToEndFrameDuration;
+    PerformanceMetric frameDurationReceiveToReceive;
 
     /**
      * Time spent copying game data from system pipe shared memory to a frame buffer.
@@ -56,9 +64,23 @@ public class PerformanceMetrics {
     PerformanceMetric botResponse;
 
     /**
-     * Time spent waiting for a response from BWAPI; is likely reflective of the performance of any opponent bots.
+     * Time spent waiting for a response from BWAPI,
+     * inclusive of the time spent sending the signal to BWAPI
+     * and the time spent waiting for and receiving it.
      */
-    PerformanceMetric bwapiResponse;
+    PerformanceMetric communicationSendToReceive;
+
+    /**
+     * Time spent sending the "frame complete" signal to BWAPI.
+     * Significant durations would indicate something blocking writes to shared memory.
+     */
+    PerformanceMetric communicationSendToSent;
+
+    /**
+     * Time spent waiting for a "frame ready" signal from BWAPI.
+     * This time likely additional response time spent by other bots and StarCraft itself.
+     */
+    PerformanceMetric communicationListenToReceive;
 
     /**
      * Time bot spends idle.
@@ -79,62 +101,56 @@ public class PerformanceMetrics {
     PerformanceMetric excessSleep;
 
     /**
-     * Instances of System.nanoTime() measuring a longer frame duration with respect to WinAPI's GetTickCount.
+     * Instances of System.nanoTime() measuring a longer frame duration with respect to WinAPI's GetTickCount  which BWAPI uses up to 4.4.
      */
     PerformanceMetric positiveTimeDelta;
 
     /**
-     * Instances of System.nanoTime() measuring a shorter frame duration with respect to WinAPI's GetTickCount.
+     * Instances of System.nanoTime() measuring a shorter frame duration with respect to WinAPI's GetTickCount which BWAPI uses up to 4.4.
      */
     PerformanceMetric negativeTimeDelta;
 
-    /**
-     * When Kernel32.INSTANCE.GetTickCount() returns at least one inexplicable value
-     */
-    PerformanceMetric weirdTimeDelta;
-
     private BWClientConfiguration configuration;
+    private ArrayList<PerformanceMetric> performanceMetrics = new ArrayList<>();
 
     PerformanceMetrics(BWClientConfiguration configuration) {
         this.configuration = configuration;
         reset();
     }
 
     public void reset() {
-        jbwapiFrameDuration = new PerformanceMetric("JBWAPI frame duration", 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55, 85);
-        endToEndFrameDuration = new PerformanceMetric("End-to-end frame duration", 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55, 85);
-        copyingToBuffer = new PerformanceMetric("Time copying to buffer", 5, 10, 15, 20, 25, 30);
-        intentionallyBlocking = new PerformanceMetric("Blocking with full buffer", 0);
-        frameBufferSize = new PerformanceMetric("Frames buffered", 0, 1);
-        framesBehind = new PerformanceMetric("Frames behind real-time", 0, 1);
-        flushSideEffects = new PerformanceMetric("Flushing side effects", 1, 3, 5);
-        botResponse = new PerformanceMetric("Bot event handlers", 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55, 85);
-        bwapiResponse = new PerformanceMetric("Responses from BWAPI", 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55, 85);
-        botIdle = new PerformanceMetric("Bot idle", Long.MAX_VALUE);
-        clientIdle = new PerformanceMetric("Client idling", configuration.maxFrameDurationMs);
-        excessSleep = new PerformanceMetric("Excess sleep", 1, 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55, 85);
-        positiveTimeDelta = new PerformanceMetric("Positive timer delta", 1, 2, 3, 4, 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55, 85);
-        negativeTimeDelta = new PerformanceMetric("Negative timer delta", 1, 2, 3, 4, 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55, 85);
-        weirdTimeDelta = new PerformanceMetric("Weird timer delta");
+        performanceMetrics.clear();
+        frameDurationReceiveToSend = new PerformanceMetric(this, "Frame duration: Receiving 'frame ready' -> before sending 'frame done'", 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55, 85);
+        frameDurationReceiveToSent = new PerformanceMetric(this, "Frame duration: Receiving 'frame ready' -> after sending 'frame done'", 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55, 85);
+        frameDurationReceiveToReceive = new PerformanceMetric(this, "Frame duration: From BWAPI receive to BWAPI receive", 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55, 85);
+        communicationSendToReceive = new PerformanceMetric(this, "BWAPI duration: Before sending 'frame done' -> After receiving 'frame ready'", 1, 3, 5, 10, 15, 20, 30);
+        communicationSendToSent = new PerformanceMetric(this, "BWAPI duration: Before sending 'frame done' -> After sending 'frame done'", 1, 3, 5, 10, 15, 20, 30);
+        communicationListenToReceive = new PerformanceMetric(this, "BWAPI duration: Before listening for 'frame ready' -> After receiving 'frame ready'", 1, 3, 5, 10, 15, 20, 30);
+        copyingToBuffer = new PerformanceMetric(this, "Copying frame to buffer", 5, 10, 15, 20, 25, 30);
+        intentionallyBlocking = new PerformanceMetric(this, "Time holding frame until buffer frees capacity", 0);
+        frameBufferSize = new PerformanceMetric(this, "Frames already buffered when enqueuing a new frame", 0, 1);
+        framesBehind = new PerformanceMetric(this, "Frames behind real-time when handling events", 0, 1);
+        flushSideEffects = new PerformanceMetric(this, "Time flushing side effects", 1, 3, 5);
+        botResponse = new PerformanceMetric(this, "Duration of bot event handlers", 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55, 85);
+        botIdle = new PerformanceMetric(this, "Time bot spent idle", Long.MAX_VALUE);
+        clientIdle = new PerformanceMetric(this, "Time client spent waiting for bot", configuration.maxFrameDurationMs);
+        excessSleep = new PerformanceMetric(this, "Excess duration of client sleep", 1, 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55, 85);
+        positiveTimeDelta = new PerformanceMetric(this, "Positive timer discrepancy compared to BWAPI", 1, 2, 3, 4, 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55, 85);
+        negativeTimeDelta = new PerformanceMetric(this, "Negative timer discrepancy compared to BWAPI", 1, 2, 3, 4, 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55, 85);
+    }
+
+    void addMetric(PerformanceMetric performanceMetric) {
+        performanceMetrics.add(performanceMetric);
     }
 
     @Override
     public String toString() {
-        return "Performance metrics:"
-            + "\n" + jbwapiFrameDuration.toString()
-            + "\n" + endToEndFrameDuration.toString()
-            + "\n" + copyingToBuffer.toString()
-            + "\n" + intentionallyBlocking.toString()
-            + "\n" + frameBufferSize.toString()
-            + "\n" + framesBehind.toString()
-            + "\n" + flushSideEffects.toString()
-            + "\n" + botResponse.toString()
-            + "\n" + bwapiResponse.toString()
-            + "\n" + botIdle.toString()
-            + "\n" + clientIdle.toString()
-            + "\n" + excessSleep.toString()
-            + "\n" + positiveTimeDelta.toString()
-            + "\n" + negativeTimeDelta.toString()
-            + "\n" + weirdTimeDelta.toString();
+        StringBuilder outputBuilder = new StringBuilder();
+        outputBuilder.append("Performance metrics:");
+        performanceMetrics.forEach(metric -> {
+            outputBuilder.append("\n");
+            outputBuilder.append(metric.toString());
+        });
+        return outputBuilder.toString();
     }
 }
