Added performance metrics related to event count to diagnose whether 4.4 tournament module bugs are ongoing

dgant · dgant · commit b40e612f9ef7 · 2020-09-26T13:38:51.000-04:00
diff --git a/src/main/java/bwapi/BWClient.java b/src/main/java/bwapi/BWClient.java
@@ -114,7 +114,7 @@ public void startGame(BWClientConfiguration gameConfiguration) {
                 if (!client.isConnected()) {
                     return;
                 }
-                client.update();
+                client.sendFrameReceiveFrame();
                 if (liveGameData.isInGame()) {
                     performanceMetrics = new PerformanceMetrics(configuration);
                     botWrapper.startNewGame(client.mapFile(), performanceMetrics);
@@ -140,7 +140,7 @@ public void startGame(BWClientConfiguration gameConfiguration) {
                     }
                 }
 
-                client.update();
+                client.sendFrameReceiveFrame();
                 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
@@ -230,14 +230,18 @@ boolean connect() {
         return true;
     }
 
-    void update() {
+    void sendFrameReceiveFrame() {
+        final PerformanceMetrics metrics = bwClient.getPerformanceMetrics();
 
         // Tell BWAPI that we are done with the current frame
-        bwClient.getPerformanceMetrics().frameDurationReceiveToSend.stopTiming();
-        bwClient.getPerformanceMetrics().communicationSendToReceive.startTiming();
-        bwClient.getPerformanceMetrics().communicationSendToSent.startTiming();
+        metrics.frameDurationReceiveToSend.stopTiming();
+        if (bwClient.doTime()) {
+            metrics.communicationSendToReceive.startTiming();
+            metrics.communicationSendToSent.startTiming();
+        }
         try {
-            pipeObjectHandle.writeByte(1); // The "frame done" signal
+            // 1 is the "frame done" signal to BWAPI
+            pipeObjectHandle.writeByte(1);
         }
         catch (Exception e) {
             System.err.println("failed, disconnecting");
@@ -247,15 +251,25 @@ void update() {
             disconnect();
             return;
         }
-        bwClient.getPerformanceMetrics().communicationSendToSent.stopTiming();
-        bwClient.getPerformanceMetrics().frameDurationReceiveToSent.stopTiming();
+        metrics.communicationSendToSent.stopTiming();
+        metrics.frameDurationReceiveToSent.stopTiming();
+        metrics.frameDurationReceiveToSentGTC.stopTiming();
+        if (bwClient.doTime()) {
+            final int eventCount = clientData.gameData().getEventCount();
+            metrics.numberOfEvents.record(eventCount);
+            metrics.numberOfEventsTimesDurationReceiveToSent.record(eventCount * metrics.frameDurationReceiveToSent.runningTotal.last);
+            metrics.numberOfEventsTimesDurationReceiveToSentGTC.record(eventCount * metrics.frameDurationReceiveToSentGTC.runningTotal.last);
+        }
 
         // 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
+        if (bwClient.doTime()) {
+            metrics.communicationListenToReceive.startTiming();
+        }
+        boolean frameReady = false;
+        while (!frameReady) {
             try {
-                code = pipeObjectHandle.readByte();
+                // 2 is the "frame ready" signal from BWAPI
+                frameReady = pipeObjectHandle.readByte() == 2;
             } catch (Exception e) {
                 System.err.println("failed, disconnecting");
                 if (bwClient.getConfiguration().debugConnection) {
@@ -265,14 +279,19 @@ void update() {
                 break;
             }
         }
-        bwClient.getPerformanceMetrics().communicationListenToReceive.stopTiming();
-        bwClient.getPerformanceMetrics().communicationSendToReceive.stopTiming();
+        metrics.communicationListenToReceive.stopTiming();
+        metrics.communicationSendToReceive.stopTiming();
 
         if (bwClient.doTime()) {
-            bwClient.getPerformanceMetrics().frameDurationReceiveToSend.startTiming();
-            bwClient.getPerformanceMetrics().frameDurationReceiveToSent.startTiming();
-            bwClient.getPerformanceMetrics().frameDurationReceiveToReceive.stopTiming();
-            bwClient.getPerformanceMetrics().frameDurationReceiveToReceive.startTiming();
+            metrics.frameDurationReceiveToSend.startTiming();
+            metrics.frameDurationReceiveToSent.startTiming();
+            metrics.frameDurationReceiveToSentGTC.startTiming();
+        }
+        metrics.frameDurationReceiveToReceive.stopTiming();
+        metrics.frameDurationReceiveToReceiveGTC.stopTiming();
+        if (bwClient.doTime()) {
+            metrics.frameDurationReceiveToReceive.startTiming();
+            metrics.frameDurationReceiveToReceiveGTC.startTiming();
         }
     }
 
diff --git a/src/main/java/bwapi/PerformanceMetric.java b/src/main/java/bwapi/PerformanceMetric.java
@@ -1,5 +1,7 @@
 package bwapi;
 
+import com.sun.jna.platform.win32.Kernel32;
+
 import java.text.DecimalFormat;
 import java.util.ArrayList;
 
@@ -44,6 +46,7 @@ public String toString() {
     private final String name;
     private long timeStarted = 0;
     public int interrupted = 0;
+    private boolean usingGetTickCount = false;
 
     RunningTotal runningTotal = new RunningTotal();
     private ArrayList<Threshold> thresholds = new ArrayList<>();
@@ -79,6 +82,15 @@ void timeIf(boolean condition, Runnable runnable) {
         }
     }
 
+    PerformanceMetric useGetTickCount() {
+        usingGetTickCount = true;
+        return this;
+    }
+
+    long getNanoseconds() {
+        return usingGetTickCount ? Kernel32.INSTANCE.GetTickCount() * 1000000L: System.nanoTime();
+    }
+
     /**
      * Manually start timing.
      * The next call to stopTiming() will record the duration in fractional milliseconds.
@@ -87,7 +99,7 @@ void startTiming() {
         if (timeStarted > 0) {
             ++interrupted;
         }
-        timeStarted = System.nanoTime();
+        timeStarted = getNanoseconds();
     }
 
 
@@ -98,7 +110,7 @@ void startTiming() {
     void stopTiming() {
         if (timeStarted <= 0) return;
         // Use nanosecond resolution timer, but record in units of milliseconds.
-        long timeEnded = System.nanoTime();
+        long timeEnded = getNanoseconds();
         long timeDiff = timeEnded - timeStarted;
         timeStarted = 0;
         record(timeDiff / 1000000d);
diff --git a/src/main/java/bwapi/PerformanceMetrics.java b/src/main/java/bwapi/PerformanceMetrics.java
@@ -23,12 +23,26 @@ public class PerformanceMetrics {
      */
     PerformanceMetric frameDurationReceiveToSent;
 
+    /**
+     * Duration of a frame cycle originating at
+     * the time when JBWAPI observes a new frame in shared memory.
+     * Uses GetTickCount() instead of System.nanoRime()
+     */
+    PerformanceMetric frameDurationReceiveToSentGTC;
+
     /**
      * Duration of a frame cycle originating at
      * the time when JBWAPI observes a new frame in shared memory.
      */
     PerformanceMetric frameDurationReceiveToReceive;
 
+    /**
+     * Duration of a frame cycle originating at
+     * the time when JBWAPI observes a new frame in shared memory.
+     * Uses GetTickCount() instead of System.nanoRime()
+     */
+    PerformanceMetric frameDurationReceiveToReceiveGTC;
+
     /**
      * Time spent copying game data from system pipe shared memory to a frame buffer.
      * Applicable only in asynchronous mode.
@@ -110,6 +124,31 @@ public class PerformanceMetrics {
      */
     PerformanceMetric negativeTimeDelta;
 
+    /**
+     * The number of events sent by BWAPI each frame.
+     * Might help diagnosing issues related to https://github.com/bwapi/bwapi/issues/860 and https://github.com/davechurchill/StarcraftAITournamentManager/issues/42
+     */
+    PerformanceMetric numberOfEvents;
+
+    /**
+     * The number of events sent by BWAPI each frame,
+     * multiplied by the duration of time spent on that frame (receive-to-sent).
+     * Might help diagnosing issues related to:
+     * - https://github.com/bwapi/bwapi/issues/860
+     * - https://github.com/davechurchill/StarcraftAITournamentManager/issues/42
+     */
+    PerformanceMetric numberOfEventsTimesDurationReceiveToSent;
+
+    /**
+     * The number of events sent by BWAPI each frame,
+     * multiplied by the duration of time spent on that frame (receive-to-sent),
+     * and using GetTickCount() instead of System.nanoTime().
+     * Might help diagnosing issues related to:
+     * - https://github.com/bwapi/bwapi/issues/860
+     * - https://github.com/davechurchill/StarcraftAITournamentManager/issues/42
+     */
+    PerformanceMetric numberOfEventsTimesDurationReceiveToSentGTC;
+
     private BWClientConfiguration configuration;
     private ArrayList<PerformanceMetric> performanceMetrics = new ArrayList<>();
 
@@ -120,9 +159,11 @@ public class PerformanceMetrics {
 
     public void reset() {
         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);
+        frameDurationReceiveToSend = new PerformanceMetric(this, "Frame duration: After 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: After receiving 'frame ready' -> after sending 'frame done'", 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55, 85);
+        frameDurationReceiveToSentGTC = new PerformanceMetric(this, "Frame duration: After receiving 'frame ready' -> after sending 'frame done' (Using GetTickCount())", 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55, 85).useGetTickCount();
+        frameDurationReceiveToReceive = new PerformanceMetric(this, "Frame duration: After receiving 'frame ready' -> receiving next 'frame ready'", 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55, 85);
+        frameDurationReceiveToReceiveGTC = new PerformanceMetric(this, "Frame duration: After receiving 'frame ready' -> receiving next 'frame ready' (Using GetTickCount())", 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55, 85).useGetTickCount();
         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);
@@ -137,6 +178,9 @@ public void reset() {
         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);
+        numberOfEvents = new PerformanceMetric(this, "Number of events received from BWAPI", 1, 2, 3, 4, 5, 6, 8, 10, 15, 20);
+        numberOfEventsTimesDurationReceiveToSent = new PerformanceMetric(this, "Number of events received from BWAPI, multiplied by the receive-to-sent duration of that frame", 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55, 85);
+        numberOfEventsTimesDurationReceiveToSentGTC = new PerformanceMetric(this, "Number of events received from BWAPI, multiplied by the receive-to-sent duration of that frame (Using GetTickCount())", 5, 10, 15, 20, 25, 30, 35, 40, 45, 50, 55, 85);
     }
 
     void addMetric(PerformanceMetric performanceMetric) {
@@ -154,3 +198,4 @@ public String toString() {
         return outputBuilder.toString();
     }
 }
+

Original file line number	Diff line number	Diff line change
`@@ -114,7 +114,7 @@ public void startGame(BWClientConfiguration gameConfiguration) {`
`114`	`114`	`if (!client.isConnected()) {`
`115`	`115`	`return;`
`116`	`116`	`}`
`117`		`- client.update();`
	`117`	`+ client.sendFrameReceiveFrame();`
`118`	`118`	`if (liveGameData.isInGame()) {`
`119`	`119`	`performanceMetrics = new PerformanceMetrics(configuration);`
`120`	`120`	`botWrapper.startNewGame(client.mapFile(), performanceMetrics);`
`@@ -140,7 +140,7 @@ public void startGame(BWClientConfiguration gameConfiguration) {`
`140`	`140`	`}`
`141`	`141`	`}`
`142`	`142`
`143`		`- client.update();`
	`143`	`+ client.sendFrameReceiveFrame();`
`144`	`144`	`if (!client.isConnected()) {`
`145`	`145`	`System.out.println("Reconnecting...");`
`146`	`146`	`client.reconnect();`