Added some more metrics. Added multiple thresholds to metrics.

Author: dgant

src/main/java/bwapi/BWClient.java

@@ -94,24 +94,12 @@ public void startGame(BWClientConfiguration configuration) {
             }
             while (liveGameData.isInGame()) {
                 boolean timeFrame = liveGameData.getFrameCount() > 0 || ! configuration.unlimitedFrameZero;
-                performanceMetrics.frameDuration5.timeIf(timeFrame, () ->
-                performanceMetrics.frameDuration10.timeIf(timeFrame, () ->
-                performanceMetrics.frameDuration15.timeIf(timeFrame, () ->
-                performanceMetrics.frameDuration20.timeIf(timeFrame, () ->
-                performanceMetrics.frameDuration25.timeIf(timeFrame, () ->
-                performanceMetrics.frameDuration30.timeIf(timeFrame, () ->
-                performanceMetrics.frameDuration35.timeIf(timeFrame, () ->
-                performanceMetrics.frameDuration40.timeIf(timeFrame, () ->
-                performanceMetrics.frameDuration45.timeIf(timeFrame, () ->
-                performanceMetrics.frameDuration50.timeIf(timeFrame, () ->
-                performanceMetrics.frameDuration55.timeIf(timeFrame, () ->
                 performanceMetrics.totalFrameDuration.timeIf(
                     timeFrame,
                     () -> {
                         botWrapper.onFrame();
                         performanceMetrics.flushSideEffects.time(() -> getGame().sideEffects.flushTo(liveGameData));
-                    })
-                )))))))))));
+                    });
                 performanceMetrics.bwapiResponse.time(client::update);
                 if (!client.isConnected()) {
                     System.out.println("Reconnecting...");

src/main/java/bwapi/BotWrapper.java

@@ -108,7 +108,11 @@ void onFrame() {
             int frame = liveClientData.gameData().getFrameCount();
             configuration.log("Main: Enqueuing frame #" + frame);
             frameBuffer.enqueueFrame();
+
             configuration.log("Main: Enqueued frame #" + frame);
+            if (frame > 0) {
+                performanceMetrics.clientIdle.startTiming();
+            }
             frameBuffer.lockSize.lock();
             try {
                 while (!frameBuffer.empty()) {
@@ -140,19 +144,21 @@ void onFrame() {
                         }
                         configuration.log("Main: Waiting " + remainingNanos / 1000000 + "ms for bot on frame #" + frame);
                         frameBuffer.conditionSize.awaitNanos(remainingNanos);
+                        long excessNanos = Math.max(0, (System.nanoTime() - endNanos) / 1000000);
+                        performanceMetrics.excessSleep.record(excessNanos);
                     }
                 }
             } catch(InterruptedException ignored) {
             } finally {
                 frameBuffer.lockSize.unlock();
+                performanceMetrics.clientIdle.stopTiming();
                 configuration.log("Main: onFrame asynchronous end");
             }
         } else {
             configuration.log("Main: onFrame synchronous start");
             handleEvents();
             configuration.log("Main: onFrame synchronous end");
         }
-
     }
 
     /**
@@ -235,7 +241,7 @@ private void handleEvents() {
         }
 
         if (configuration.async) {
-            performanceMetrics.framesBehind.record(frameBuffer.framesBuffered() - 1);
+            performanceMetrics.framesBehind.record(Math.max(1, frameBuffer.framesBuffered()) - 1);
         }
 
         performanceMetrics.botResponse.timeIf(

src/main/java/bwapi/PerformanceMetric.java

@@ -1,28 +1,56 @@
 package bwapi;
 
 import java.text.DecimalFormat;
+import java.util.ArrayList;
 
 /**
  * Aggregates labeled time series data.
  */
 public class PerformanceMetric {
-    private final String name;
-    private final long maxAllowed;
+    class RunningTotal {
+        int samples = 0;
+        double mean = 0d;
+        double min = Long.MAX_VALUE;
+        double max = Long.MIN_VALUE;
+        void record(double value) {
+            min = Math.min(min, value);
+            max = Math.max(max, value);
+            mean = (mean * samples + value) / (samples + 1d);
+            ++samples;
+        }
+    }
+    class Threshold {
+        double threshold;
+        RunningTotal runningTotal = new RunningTotal();
+        Threshold(double value) {
+            threshold = value;
+        }
+        void record(double value) {
+            if (value >= threshold) {
+                runningTotal.record(value);
+            }
+        }
+        public String toString() {
+            if (runningTotal.samples <= 0) {
+                return "";
+            }
+            DecimalFormat formatter = new DecimalFormat("###,###.#");
+            return "\n>= " + formatter.format(threshold) + ": " + runningTotal.samples + " samples averaging " + formatter.format(runningTotal.mean) + ").";
+        }
+    }
 
-    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;
-    public int samplesExceeding = 0;
+    private final String name;
     public int interrupted = 0;
-
     private long timeStarted = 0;
 
-    PerformanceMetric(String name, long maxAllowed) {
+    RunningTotal runningTotal = new RunningTotal();
+    private ArrayList<Threshold> thresholds = new ArrayList<>();
+
+    PerformanceMetric(String name, double... thresholds) {
         this.name = name;
-        this.maxAllowed = maxAllowed;
+        for (double threshold : thresholds) {
+            this.thresholds.add(new Threshold(threshold));
+        }
     }
 
     /**
@@ -77,47 +105,37 @@ void stopTiming() {
      * Manually records a specific value.
      */
     void record(double value) {
-        lastValue = value;
-        minValue = Math.min(minValue, value);
-        maxValue = Math.max(maxValue, value);
-        avgValue = (avgValue * samples + value) / (samples + 1d);
-        ++samples;
-        if (value > maxAllowed) {
-            avgValueExceeding = (avgValueExceeding * samplesExceeding + value) / (samplesExceeding + 1d);
-            ++samplesExceeding;
-        }
+        runningTotal.record(value);
+        thresholds.forEach(threshold -> threshold.record(value));
     }
 
     /**
      * @return A pretty-printed description of the recorded values.
      */
     @Override
     public String toString() {
+        if (runningTotal.samples <= 0) {
+            return name + ": No samples.";
+        }
         DecimalFormat formatter = new DecimalFormat("###,###.#");
-        return name
+        String output = name
                 + ": "
-                + (samples > 0
-                    ? formatter.format(samples)
-                        + " samples averaging "
-                        + formatter.format(avgValue)
-                        + " ["
-                        + formatter.format(minValue)
-                        + " - "
-                        + formatter.format(maxValue)
-                        + "] over "
-                        + samples
-                        + " samples"
-                        + (samplesExceeding > 0
-                            ? ". "
-                                + samplesExceeding
-                                + " values over "
-                                + maxAllowed
-                                + " averaging "
-                                + formatter.format(avgValueExceeding)
-                            : "")
-                    : "No samples")
-                + (interrupted > 0
-                    ? ". Interrupted " + interrupted + " times"
-                    : "");
+                + formatter.format(runningTotal.samples)
+                    + " samples averaging "
+                    + formatter.format(runningTotal.mean)
+                    + " ["
+                    + formatter.format(runningTotal.min)
+                    + " - "
+                    + formatter.format(runningTotal.max)
+                    + "] over "
+                    + runningTotal.samples
+                    + " samples. ";
+        for (Threshold threshold : thresholds) {
+            output += threshold.toString();
+        }
+        if (interrupted > 0) {
+            output += "\n\tInterrupted " + interrupted + " times";
+        }
+        return output;
     }
 }

src/main/java/bwapi/PerformanceMetrics.java

@@ -10,95 +10,84 @@ public class PerformanceMetrics {
      * Likely to be at least a little bit of an undercount,
      * given that the tournament module is timing a superset of JBWAPI's execution time.
      */
-    public PerformanceMetric totalFrameDuration;
+    PerformanceMetric totalFrameDuration;
 
     /**
      * Time spent copying game data from system pipe shared memory to a frame buffer.
      * Applicable only in asynchronous mode.
      */
-    public PerformanceMetric copyingToBuffer;
+    PerformanceMetric copyingToBuffer;
 
     /**
      * Time spent intentionally blocking on bot operation due to a full frame buffer.
      * Applicable only in asynchronous mode.
      */
-    public PerformanceMetric intentionallyBlocking;
+    PerformanceMetric intentionallyBlocking;
 
     /**
      * 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;
+    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;
+    PerformanceMetric framesBehind;
 
     /**
      * Time spent applying bot commands to the live frame.
      */
-    public PerformanceMetric flushSideEffects;
+    PerformanceMetric flushSideEffects;
 
     /**
      * Time spent waiting for bot event handlers to complete for a single frame.
      */
-    public PerformanceMetric botResponse;
+    PerformanceMetric botResponse;
 
     /**
      * Time spent waiting for a response from BWAPI; is likely reflective of the performance of any opponent bots.
      */
-    public PerformanceMetric bwapiResponse;
+    PerformanceMetric bwapiResponse;
 
     /**
      * Time bot spends idle.
      * Applicable only in asynchronous mode.
      */
-    public PerformanceMetric botIdle;
-
-    public PerformanceMetric frameDuration5;
-    public PerformanceMetric frameDuration10;
-    public PerformanceMetric frameDuration15;
-    public PerformanceMetric frameDuration20;
-    public PerformanceMetric frameDuration25;
-    public PerformanceMetric frameDuration30;
-    public PerformanceMetric frameDuration35;
-    public PerformanceMetric frameDuration40;
-    public PerformanceMetric frameDuration45;
-    public PerformanceMetric frameDuration50;
-    public PerformanceMetric frameDuration55;
+    PerformanceMetric botIdle;
+
+    /**
+     * Time the main thread spends idle, waiting for the bot to finish processing frames.
+     * Applicable only in asynchronous mode.
+     */
+    PerformanceMetric clientIdle;
+
+    /**
+     * Time the main thread spends oversleeping its timeout target, potentially causing overtime frames.
+     * Applicable only in asynchronous mode.
+     */
+    PerformanceMetric excessSleep;
 
     private BWClientConfiguration configuration;
 
-    public PerformanceMetrics(BWClientConfiguration configuration) {
+    PerformanceMetrics(BWClientConfiguration configuration) {
         this.configuration = configuration;
         reset();
     }
 
     void reset() {
-        final int sideEffectsBufferMs = 1;
-        final int realTimeFrameMs = 42;
-        totalFrameDuration = new PerformanceMetric("JBWAPI frame duration", configuration.maxFrameDurationMs + 5);
-        copyingToBuffer = new PerformanceMetric("Time copying to buffer", configuration.maxFrameDurationMs + 5);
+        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);
-        frameBufferSize = new PerformanceMetric("Frames buffered", 0);
-        framesBehind = new PerformanceMetric("Frames behind real-time", 0);
-        flushSideEffects = new PerformanceMetric("Flushing side effects", sideEffectsBufferMs );
-        botResponse = new PerformanceMetric("Bot event handlers", configuration.maxFrameDurationMs);
-        bwapiResponse = new PerformanceMetric("Responses from BWAPI", realTimeFrameMs);
+        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);
-        frameDuration5 = new PerformanceMetric("JBWAPI frame @  5ms", 5);
-        frameDuration10 = new PerformanceMetric("JBWAPI frame @ 10ms", 10);
-        frameDuration15 = new PerformanceMetric("JBWAPI frame @ 15ms", 15);
-        frameDuration20 = new PerformanceMetric("JBWAPI frame @ 20ms", 20);
-        frameDuration25 = new PerformanceMetric("JBWAPI frame @ 25ms", 25);
-        frameDuration30 = new PerformanceMetric("JBWAPI frame @ 30ms", 30);
-        frameDuration35 = new PerformanceMetric("JBWAPI frame @ 35ms", 35);
-        frameDuration40 = new PerformanceMetric("JBWAPI frame @ 40ms", 40);
-        frameDuration45 = new PerformanceMetric("JBWAPI frame @ 45ms", 45);
-        frameDuration50 = new PerformanceMetric("JBWAPI frame @ 50ms", 50);
-        frameDuration55 = new PerformanceMetric("JBWAPI frame @ 55ms", 55);
+        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);
     }
 
     @Override
@@ -113,16 +102,7 @@ public String toString() {
                 + "\n" + botResponse.toString()
                 + "\n" + bwapiResponse.toString()
                 + "\n" + botIdle.toString()
-                + "\n" + frameDuration5.toString()
-                + "\n" + frameDuration10.toString()
-                + "\n" + frameDuration15.toString()
-                + "\n" + frameDuration20.toString()
-                + "\n" + frameDuration25.toString()
-                + "\n" + frameDuration30.toString()
-                + "\n" + frameDuration35.toString()
-                + "\n" + frameDuration40.toString()
-                + "\n" + frameDuration45.toString()
-                + "\n" + frameDuration50.toString()
-                + "\n" + frameDuration55.toString();
+                + "\n" + clientIdle.toString()
+                + "\n" + excessSleep.toString();
     }
 }

src/main/java/bwapi/Unit.java

@@ -115,7 +115,7 @@ public int getID() {
      * <p>
      * In the event that this function returns false, there are two cases to consider:
      * 1. You own the unit. This means the unit is dead.
-     * 2. Another player owns the unit. This could either mean that you don't have access
+     * 2. Another player owns the unit. This could either runningTotal that you don't have access
      * to the unit or that the unit has died. You can specifically identify dead units
      * by polling onUnitDestroy.
      * @see #isVisible