Fixed erroneous conversion between nanoseconds and milliseconds. First pass at performance metrics.

Author: dgant

src/main/java/bwapi/BWClient.java

@@ -8,6 +8,7 @@
 public class BWClient {
     private final BWEventListener eventListener;
     private BotWrapper botWrapper;
+    private PerformanceMetrics performanceMetrics;
 
     public BWClient(final BWEventListener eventListener) {
         Objects.requireNonNull(eventListener);
@@ -22,6 +23,14 @@ public Game getGame() {
         return botWrapper == null ? null : botWrapper.getGame();
     }
 
+    /**
+     * Returns JBWAPI performance metrics.
+     * Metrics will be mostly empty if metrics collection isn't timersEnabled in the bot configuration
+     */
+    public PerformanceMetrics performanceMetrics() {
+        return performanceMetrics;
+    }
+
     public void startGame() {
         BWClientConfiguration configuration = new BWClientConfiguration();
         startGame(configuration);
@@ -59,16 +68,21 @@ public void startGame(BWClientConfiguration configuration) {
                 }
                 client.update();
                 if (liveGameData.isInGame()) {
-                    botWrapper.startNewGame(client.mapFile());
+                    performanceMetrics = new PerformanceMetrics(configuration);
+                    botWrapper.startNewGame(client.mapFile(), performanceMetrics);
                 }
             }
             while (liveGameData.isInGame()) {
-                botWrapper.onFrame();
-                getGame().sideEffects.flushTo(liveGameData);
-                client.update();
-                if (!client.isConnected()) {
-                    client.reconnect();
-                }
+                performanceMetrics.totalFrameDuration.time(() -> {
+                    botWrapper.onFrame();
+                    performanceMetrics.flushSideEffects.time(() -> {
+                        getGame().sideEffects.flushTo(liveGameData);
+                    });
+                    client.update();
+                    if (!client.isConnected()) {
+                        client.reconnect();
+                    }
+                });
             }
             botWrapper.endGame();
         } while (configuration.autoContinue);

src/main/java/bwapi/BWClientConfiguration.java

@@ -32,7 +32,7 @@ public class BWClientConfiguration {
      * If JBWAPI detects that this much time (in nanoseconds) has passed since a bot's event handlers began, returns control back to BWAPI.
      * Real-time human play typically uses the "fastest" game speed, which has 42.86ms (42,860ns) between frames.
      */
-    public int asyncFrameDurationNanos = 40000;
+    public int asyncFrameDurationMs = 40000;
 
     /**
      * The maximum number of frames to buffer while waiting on a bot.
@@ -51,16 +51,16 @@ public class BWClientConfiguration {
 
     /**
      * Enables collection of diagnostics.
-     * When enabled, JBWAPI collects and publishes performance metrics.
+     * When timersEnabled, JBWAPI collects and publishes performance metrics.
      */
     public boolean diagnosePerformance = false;
 
     /**
      * Checks that the configuration is in a valid state. Throws an IllegalArgumentException if it isn't.
      */
     public void validate() {
-        if (async && asyncFrameDurationNanos < 0) {
-            throw new IllegalArgumentException("asyncFrameDurationNanos needs to be a non-negative number (it's how long JBWAPI waits for a bot response before returning control to BWAPI).");
+        if (async && asyncFrameDurationMs < 0) {
+            throw new IllegalArgumentException("asyncFrameDurationMs needs to be a non-negative number (it's how long JBWAPI waits for a bot response before returning control to BWAPI).");
         }
         if (async && asyncFrameBufferSize < 1) {
             throw new IllegalArgumentException("asyncFrameBufferSize needs to be a positive number (There needs to be at least one frame buffer).");

src/main/java/bwapi/BotWrapper.java

@@ -38,6 +38,7 @@ class BotWrapper {
     private Game game;
     private Thread botThread;
     private boolean gameOver;
+    private PerformanceMetrics performanceMetrics;
 
     BotWrapper(BWClientConfiguration configuration, BWEventListener eventListener) {
         this.configuration = configuration;
@@ -48,8 +49,9 @@ class BotWrapper {
     /**
      * Resets the BotWrapper for a new game.
      */
-    void startNewGame(ByteBuffer dataSource) {
-        frameBuffer.initialize(dataSource);
+    void startNewGame(ByteBuffer dataSource, PerformanceMetrics performanceMetrics) {
+        frameBuffer.initialize(dataSource, performanceMetrics);
+        this.performanceMetrics = performanceMetrics;
         game = new Game(liveClientData);
         liveClientData.setBuffer(dataSource);
         botThread = null;
@@ -70,16 +72,17 @@ Game getGame() {
     void onFrame() {
         if (configuration.async) {
             long startNanos = System.nanoTime();
-            long endNanos = startNanos + configuration.asyncFrameDurationNanos;
+            long endNanos = startNanos + configuration.asyncFrameDurationMs * 1000000;
             if (botThread == null) {
                 botThread = createBotThread();
                 botThread.setName("JBWAPI Bot");
                 botThread.start();
             }
-            frameBuffer.enqueueFrame();
+            performanceMetrics.copyingToBuffer.time(frameBuffer::enqueueFrame);
             frameBuffer.lockSize.lock();
             try {
                 while (frameBuffer.empty()) {
+                    performanceMetrics.bwapiResponse.startTiming();
                     if (configuration.asyncWaitOnFrameZero && liveClientData.gameData().getFrameCount() == 0) {
                         frameBuffer.conditionSize.await();
                     } else {
@@ -88,6 +91,7 @@ void onFrame() {
                         frameBuffer.conditionSize.awaitNanos(remainingNanos);
                     }
                 }
+                performanceMetrics.bwapiResponse.stopTiming();
             } catch(InterruptedException ignored) {
             } finally {
                 frameBuffer.lockSize.unlock();
@@ -112,23 +116,33 @@ private Thread createBotThread() {
         return new Thread(() -> {
             while ( ! gameOver) {
                 frameBuffer.lockSize.lock();
-                try { while (frameBuffer.empty()) frameBuffer.conditionSize.awaitUninterruptibly(); } finally { frameBuffer.lockSize.unlock(); }
-
+                try {
+                    while (frameBuffer.empty()) {
+                        performanceMetrics.botIdle.startTiming();
+                        frameBuffer.conditionSize.awaitUninterruptibly();
+                    }
+                    performanceMetrics.botIdle.stopTiming();
+                } finally {
+                    frameBuffer.lockSize.unlock();
+                }
                 game.clientData().setBuffer(frameBuffer.peek());
+                performanceMetrics.frameBufferSize.record(frameBuffer.framesBuffered());
                 handleEvents();
                 frameBuffer.dequeue();
             }
         });
     }
 
     private void handleEvents() {
-        ClientData.GameData gameData = game.clientData().gameData();
-        for (int i = 0; i < gameData.getEventCount(); i++) {
-            ClientData.Event event = gameData.getEvents(i);
-            EventHandler.operation(eventListener, game, event);
-            if (event.getType() == EventType.MatchEnd) {
-                gameOver = true;
+        performanceMetrics.botResponse.time(() -> {
+            ClientData.GameData gameData = game.clientData().gameData();
+            for (int i = 0; i < gameData.getEventCount(); i++) {
+                ClientData.Event event = gameData.getEvents(i);
+                EventHandler.operation(eventListener, game, event);
+                if (event.getType() == EventType.MatchEnd) {
+                    gameOver = true;
+                }
             }
-        }
+        });
     }
 }

src/main/java/bwapi/Bullet.java

@@ -21,7 +21,7 @@
  * represents a new Bullet.
  * <p>
  * If {@link Flag#CompleteMapInformation} is disabled, then a {@link Bullet} is accessible if and only if
- * it is visible. Otherwise if {@link Flag#CompleteMapInformation} is enabled, then all Bullets
+ * it is visible. Otherwise if {@link Flag#CompleteMapInformation} is timersEnabled, then all Bullets
  * in the game are accessible.
  *
  * @see Game#getBullets
@@ -54,7 +54,7 @@ public int getID() {
      * return value will be false regardless of the Bullet's true existence. This is because
      * absolutely no state information on invisible enemy bullets is made available to the AI.
      * <p>
-     * If {@link Flag#CompleteMapInformation} is enabled, then this function is accurate for all
+     * If {@link Flag#CompleteMapInformation} is timersEnabled, then this function is accurate for all
      * {@link Bullet} information.
      *
      * @return true if the bullet exists or is visible, false if the bullet was destroyed or has gone out of scope.

src/main/java/bwapi/CommandTemp.java

@@ -2,7 +2,7 @@
 
 /**
  * Latency Compensation:
- * Only need to implement LatCom for current frame, the server updates the next frame already if latcom is enabled.
+ * Only need to implement LatCom for current frame, the server updates the next frame already if latcom is timersEnabled.
  * Use Caches for all internal state that might be affected by latcom, and add the (current) frame, to let Player & Unit
  * check if they need to use the cached/latcom version of the value or the from server (or a combination of both)
  * <p>

src/main/java/bwapi/FrameBuffer.java

@@ -37,6 +37,7 @@ of this software and associated documentation files (the "Software"), to deal
 class FrameBuffer {
 
     private ByteBuffer dataSource;
+    private PerformanceMetrics performanceMetrics;
     private int size;
     private int stepGame = 0;
     private int stepBot = 0;
@@ -57,8 +58,9 @@ class FrameBuffer {
     /**
      * Resets for a new game
      */
-    void initialize(ByteBuffer dataSource) {
+    void initialize(ByteBuffer dataSource, PerformanceMetrics performanceMetrics) {
         this.dataSource = dataSource;
+        this.performanceMetrics = performanceMetrics;
         stepGame = 0;
         stepBot = 0;
     }
@@ -110,7 +112,13 @@ void enqueueFrame() {
         lockWrite.lock();
         try {
             lockSize.lock();
-            try { while (full()) conditionSize.awaitUninterruptibly(); } finally { lockSize.unlock(); };
+            try {
+                while (full()) {
+                    performanceMetrics.intentionallyBlocking.startTiming();
+                    conditionSize.awaitUninterruptibly();
+                }
+                performanceMetrics.intentionallyBlocking.stopTiming();
+            } finally { lockSize.unlock(); };
             ByteBuffer dataTarget = dataBuffer.get(indexGame());
             dataSource.rewind();
             dataTarget.rewind();
@@ -133,7 +141,6 @@ ByteBuffer peek() {
             while(empty()) conditionSize.awaitUninterruptibly();
             return dataBuffer.get(indexBot());
         } finally { lockSize.unlock(); }
-
     }
 
     /**

src/main/java/bwapi/Game.java

@@ -329,7 +329,7 @@ public List<Player> getPlayers() {
 
     /**
      * Retrieves the set of all accessible units.
-     * If {@link Flag#CompleteMapInformation} is enabled, then the set also includes units that are not
+     * If {@link Flag#CompleteMapInformation} is timersEnabled, then the set also includes units that are not
      * visible to the player.
      * <p>
      * Units that are inside refineries are not included in this set.
@@ -624,13 +624,13 @@ public void pingMinimap(final Position p) {
     }
 
     /**
-     * Checks if the state of the given flag is enabled or not.
+     * Checks if the state of the given flag is timersEnabled or not.
      * <p>
-     * Flags may only be enabled at the start of the match during the {@link BWEventListener#onStart}
+     * Flags may only be timersEnabled at the start of the match during the {@link BWEventListener#onStart}
      * callback.
      *
      * @param flag The {@link Flag} entry describing the flag's effects on BWAPI.
-     * @return true if the given flag is enabled, false if the flag is disabled.
+     * @return true if the given flag is timersEnabled, false if the flag is disabled.
      * @see Flag
      */
     public boolean isFlagEnabled(final Flag flag) {
@@ -640,7 +640,7 @@ public boolean isFlagEnabled(final Flag flag) {
     /**
      * Enables the state of a given flag.
      * <p>
-     * Flags may only be enabled at the start of the match during the {@link BWEventListener#onStart}
+     * Flags may only be timersEnabled at the start of the match during the {@link BWEventListener#onStart}
      * callback.
      *
      * @param flag The {@link Flag} entry describing the flag's effects on BWAPI.
@@ -1640,7 +1640,7 @@ public boolean issueCommand(final Collection<Unit> units, final UnitCommand comm
 
     /**
      * Retrieves the set of units that are currently selected by the user outside of
-     * BWAPI. This function requires that{@link Flag#UserInput} be enabled.
+     * BWAPI. This function requires that{@link Flag#UserInput} be timersEnabled.
      *
      * @return A List<Unit> containing the user's selected units. If {@link Flag#UserInput} is disabled,
      * then this set is always empty.
@@ -2163,7 +2163,7 @@ public boolean isDebug() {
     /**
      * Checks the state of latency compensation.
      *
-     * @return true if latency compensation is enabled, false if it is disabled.
+     * @return true if latency compensation is timersEnabled, false if it is disabled.
      * @see #setLatCom
      */
     public boolean isLatComEnabled() {
@@ -2174,9 +2174,9 @@ public boolean isLatComEnabled() {
      * Changes the state of latency compensation. Latency compensation
      * modifies the state of BWAPI's representation of units to reflect the implications of
      * issuing a command immediately after the command was performed, instead of waiting
-     * consecutive frames for the results. Latency compensation is enabled by default.
+     * consecutive frames for the results. Latency compensation is timersEnabled by default.
      *
-     * @param isEnabled Set whether the latency compensation feature will be enabled (true) or disabled (false).
+     * @param isEnabled Set whether the latency compensation feature will be timersEnabled (true) or disabled (false).
      * @see #isLatComEnabled
      */
     public void setLatCom(final boolean isEnabled) {
@@ -2278,11 +2278,11 @@ public boolean setVision(Player player, boolean enabled) {
     }
 
     /**
-     * Checks if the GUI is enabled.
+     * Checks if the GUI is timersEnabled.
      * <p>
      * The GUI includes all drawing functions of BWAPI, as well as screen updates from Broodwar.
      *
-     * @return true if the GUI is enabled, and everything is visible, false if the GUI is disabled and drawing
+     * @return true if the GUI is timersEnabled, and everything is visible, false if the GUI is disabled and drawing
      * functions are rejected
      * @see #setGUI
      */
@@ -2341,7 +2341,7 @@ public boolean setMap(final String mapFileName) {
     /**
      * Sets the state of the fog of war when watching a replay.
      *
-     * @param reveal The state of the reveal all flag. If false, all fog of war will be enabled. If true,
+     * @param reveal The state of the reveal all flag. If false, all fog of war will be timersEnabled. If true,
      *               then the fog of war will be revealed. It is true by default.
      */
     public boolean setRevealAll(boolean reveal) {