Trying various tactics to resolve timeouts. Added a timer resolution hack which should force Windows to use the lowest resolution (16ms) for GetTickCount() (though it appeared to be doing that in all environments anyway). Reduced thread priority for JBWAPI + bot threads to increase likelihood that BWAPI receives priority sooner.

Author: dgant

src/main/java/bwapi/BWClient.java

@@ -1,5 +1,7 @@
 package bwapi;
 
+import com.sun.jna.platform.win32.Kernel32;
+
 import java.util.Objects;
 
 /**
@@ -10,10 +12,12 @@ public class BWClient {
     private BotWrapper botWrapper;
     private Client client;
     private PerformanceMetrics performanceMetrics;
+    private TimerResolutionThread timerResolutionThread;
 
     public BWClient(final BWEventListener eventListener) {
         Objects.requireNonNull(eventListener);
         this.eventListener = eventListener;
+        this.timerResolutionThread = new TimerResolutionThread();
     }
 
     /**
@@ -75,6 +79,10 @@ public void startGame(BWClientConfiguration configuration) {
         configuration.validate();
         botWrapper = new BotWrapper(configuration, eventListener);
 
+        // Use reduced priority to encourage Windows to give priority to StarCraft.exe/BWAPI.
+        // If BWAPI doesn't get priority, it may not detect completion of a frame on our end in timely fashion.
+        Thread.currentThread().setPriority(Thread.NORM_PRIORITY);
+
         if (client == null) {
             client = new Client(configuration);
         }
@@ -94,12 +102,29 @@ public void startGame(BWClientConfiguration configuration) {
             }
             while (liveGameData.isInGame()) {
                 boolean timeFrame = liveGameData.getFrameCount() > 0 || ! configuration.unlimitedFrameZero;
+
+                long ticksBefore = Kernel32.INSTANCE.GetTickCount();
                 performanceMetrics.totalFrameDuration.timeIf(
                     timeFrame,
                     () -> {
                         botWrapper.onFrame();
                         performanceMetrics.flushSideEffects.time(() -> getGame().sideEffects.flushTo(liveGameData));
                     });
+                long ticksAfter = Kernel32.INSTANCE.GetTickCount();
+                if (timeFrame) {
+                    long deltaTicks = ticksAfter - ticksBefore;
+                    long deltaMillis = (long) performanceMetrics.totalFrameDuration.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) {
+                        performanceMetrics.positiveTimeDelta.record(delta);
+                    } else if (delta < 0) {
+                        performanceMetrics.negativeTimeDelta.record(-delta);
+                    }
+                }
+
                 performanceMetrics.bwapiResponse.time(client::update);
                 if (!client.isConnected()) {
                     System.out.println("Reconnecting...");

src/main/java/bwapi/BotWrapper.java

@@ -81,6 +81,8 @@ void onFrame() {
                 configuration.log("Main: Starting bot thread");
                 botThread = createBotThread();
                 botThread.setName("JBWAPI Bot");
+                // Reduced priority helps ensure that StarCraft.exe/BWAPI pick up on our frame completion in timely fashion
+                botThread.setPriority(Thread.MIN_PRIORITY);
                 botThread.start();
             }
 

src/main/java/bwapi/Client.java

@@ -247,6 +247,9 @@ void update() {
         while (code != 2) {
             try {
                 code = pipeObjectHandle.readByte();
+                if (code != 2) {
+                    Thread.sleep(0, 1);
+                }
             }
             catch (Exception e) {
                 System.err.println("failed, disconnecting");

src/main/java/bwapi/MSVCRT.java

@@ -4,7 +4,7 @@
 import com.sun.jna.Native;
 
 /**
- * JNI interface for access the native MSVC implementation of memcpy.
+ * JNI interface for accessing native MSVC code.
  */
 interface MSVCRT extends Library {
     MSVCRT INSTANCE = Native.load("msvcrt.dll", MSVCRT.class);

src/main/java/bwapi/PerformanceMetric.java

@@ -9,10 +9,12 @@
 public class PerformanceMetric {
     class RunningTotal {
         int samples = 0;
+        double last = 0d;
         double mean = 0d;
         double min = Long.MAX_VALUE;
         double max = Long.MIN_VALUE;
         void record(double value) {
+            last = value;
             min = Math.min(min, value);
             max = Math.max(max, value);
             mean = (mean * samples + value) / (samples + 1d);
@@ -35,7 +37,7 @@ public String toString() {
                 return "";
             }
             DecimalFormat formatter = new DecimalFormat("###,###.#");
-            return "\n>= " + formatter.format(threshold) + ": " + runningTotal.samples + " samples averaging " + formatter.format(runningTotal.mean) + ").";
+            return "\n>= " + formatter.format(threshold) + ": " + runningTotal.samples + " samples averaging " + formatter.format(runningTotal.mean);
         }
     }
 

src/main/java/bwapi/PerformanceMetrics.java

@@ -69,14 +69,29 @@ public class PerformanceMetrics {
      */
     PerformanceMetric excessSleep;
 
+    /**
+     * Instances of System.nanoTime() measuring a longer frame duration with respect to WinAPI's GetTickCount.
+     */
+    PerformanceMetric positiveTimeDelta;
+
+    /**
+     * Instances of System.nanoTime() measuring a shorter frame duration with respect to WinAPI's GetTickCount.
+     */
+    PerformanceMetric negativeTimeDelta;
+
+    /**
+     * When Kernel32.INSTANCE.GetTickCount() returns at least one inexplicable value
+     */
+    PerformanceMetric weirdTimeDelta;
+
     private BWClientConfiguration configuration;
 
     PerformanceMetrics(BWClientConfiguration configuration) {
         this.configuration = configuration;
         reset();
     }
 
-    void reset() {
+    public void reset() {
         totalFrameDuration = new PerformanceMetric("JBWAPI 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);
@@ -88,21 +103,27 @@ void reset() {
         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");
     }
 
     @Override
     public String toString() {
         return "Performance metrics:"
-                + "\n" + totalFrameDuration.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" + totalFrameDuration.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();
     }
 }

src/main/java/bwapi/TimerResolutionThread.java

@@ -0,0 +1,34 @@
+package bwapi;
+
+/**
+ * See https://hazelcast.com/blog/locksupport-parknanos-under-the-hood-and-the-curious-case-of-parking-part-ii-windows/
+ *
+ * "Is this it? Just a single flag and my JVM will use high-resolution timers?
+ * Well, it turns out it’s not that simple.
+ * This flag has been reported to be broken since 2006!
+ * However, the very same bug report suggests a very interesting workaround:"
+ *
+ * “Do not use ForceTimeHighResolution but instead,
+ * at the start of the application create and start
+ * a daemon Thread that simply sleeps for a very long time
+ * (that isn’t a multiple of 10ms)
+ * as this will set the timer period to be 1ms for the duration of that sleep
+ * – which in this case is the lifetime of the VM"
+ *
+ * "What the R$#@#@ have I just read?
+ * Let me rephrase it:
+ *  “If you want a high-resolution timer then just start a new thread and let it sleep forever”.
+ *  That’s simply hilarious!
+ */
+class TimerResolutionThread {
+    TimerResolutionThread() {
+        Thread t = new Thread(() -> {
+            try {
+                Thread.sleep(Long.MAX_VALUE);
+            } catch (InterruptedException e) { // a delicious interrupt, omm, omm
+            }
+        });
+        t.setDaemon(true);
+        t.start();
+    }
+}