Switch to streaming events for timing rather than in-line map lookups

Report timer results off thread

Author: kwvanderlinde

src/main/java/net/rptools/lib/CodeTimer.java

@@ -14,19 +14,23 @@
  */
 package net.rptools.lib;
 
+import java.awt.EventQueue;
 import java.util.ArrayList;
 import java.util.LinkedHashMap;
 import java.util.List;
 import java.util.Map;
 import java.util.concurrent.TimeUnit;
 import net.rptools.maptool.client.AppState;
 import net.rptools.maptool.client.MapTool;
+import org.apache.logging.log4j.LogManager;
+import org.apache.logging.log4j.Logger;
 
 public class CodeTimer {
   private static final ThreadLocal<CodeTimer> ROOT_TIMER =
       ThreadLocal.withInitial(() -> new CodeTimer(""));
   private static final ThreadLocal<List<CodeTimer>> timerStack =
       ThreadLocal.withInitial(ArrayList::new);
+  private static final Logger log = LogManager.getLogger(CodeTimer.class);
 
   @FunctionalInterface
   public interface TimedSection<Ex extends Throwable> {
@@ -50,11 +54,7 @@ public static <Ex extends Exception> void using(String name, TimedSection<Ex> ca
       final var lastTimer = stack.removeLast();
       assert lastTimer == timer : "Timer stack is corrupted";
 
-      if (timer.isEnabled()) {
-        String results = timer.toString();
-        MapTool.getProfilingNoteFrame().addText(results);
-      }
-      timer.clear();
+      timer.complete();
     }
   }
 
@@ -63,8 +63,18 @@ public static CodeTimer get() {
     return stack.isEmpty() ? ROOT_TIMER.get() : stack.getLast();
   }
 
-  private final Map<String, Integer> counterMap = new LinkedHashMap<>();
-  private final Map<String, Timer> timeMap = new LinkedHashMap<>();
+  private enum TimerEventType {
+    Start,
+    Stop
+  }
+
+  private record TimerEvent(TimerEventType type, long timeNs, String id, Object[] parameters) {}
+
+  private record CounterEvent(long amount, String id) {}
+
+  private ArrayList<TimerEvent> timerEvents = new ArrayList<>(100);
+  private ArrayList<CounterEvent> counterEvents = new ArrayList<>(100);
+
   private final String name;
   private long threshold = 1;
   private TimeUnit reportingUnit = TimeUnit.MILLISECONDS;
@@ -75,10 +85,6 @@ private CodeTimer(String n) {
     enabled = true;
   }
 
-  public boolean isEnabled() {
-    return enabled;
-  }
-
   public void setThreshold(long threshold) {
     this.threshold = TimeUnit.NANOSECONDS.convert(threshold, TimeUnit.MILLISECONDS);
   }
@@ -103,58 +109,81 @@ public void increment(String id, int amount) {
     if (!enabled) {
       return;
     }
-    counterMap.merge(id, amount, Integer::sum);
+    counterEvents.add(new CounterEvent(amount, id));
   }
 
   public void start(String id, Object... parameters) {
     if (!enabled) {
       return;
     }
-    if (parameters.length > 0) {
-      id = String.format(id, parameters);
-    }
-
-    Timer timer = timeMap.computeIfAbsent(id, key -> new Timer());
-    timer.start();
+    timerEvents.add(new TimerEvent(TimerEventType.Start, System.nanoTime(), id, parameters));
   }
 
   public void stop(String id, Object... parameters) {
     if (!enabled) {
       return;
     }
-    if (parameters.length > 0) {
-      id = String.format(id, parameters);
+    timerEvents.add(new TimerEvent(TimerEventType.Stop, System.nanoTime(), id, parameters));
+  }
+
+  private void complete() {
+    if (!enabled) {
+      return;
     }
 
-    Timer timer = timeMap.get(id);
-    if (timer == null) {
-      throw new IllegalArgumentException("Could not find timer id: " + id);
+    var name = this.name;
+    var reportingUnit = this.reportingUnit;
+    var threshold = this.threshold;
+    var timerEvents = this.timerEvents;
+    var counterEvents = this.counterEvents;
+    this.timerEvents = new ArrayList<>();
+    this.counterEvents = new ArrayList<>();
+
+    EventQueue.invokeLater(
+        () -> {
+          String results = getResults(name, reportingUnit, threshold, timerEvents, counterEvents);
+          MapTool.getProfilingNoteFrame().addText(results);
+        });
+  }
+
+  private static String getResults(
+      String name,
+      TimeUnit reportingUnit,
+      long threshold,
+      List<TimerEvent> timerEvents,
+      List<CounterEvent> counterEvents) {
+    final Map<String, Long> counterMap = new LinkedHashMap<>();
+    // Maps timer names to start times.
+    final Map<String, Timer> timeMap = new LinkedHashMap<>();
+
+    // Count up all the timing events.
+    for (var event : timerEvents) {
+      var id = String.format(event.id(), event.parameters());
+      var timer = timeMap.computeIfAbsent(id, Timer::new);
+      switch (event.type()) {
+        case Start -> timer.startAt(event.timeNs());
+        case Stop -> timer.stopAt(event.timeNs());
+      }
     }
-    timer.stop();
-  }
 
-  public void clear() {
-    timeMap.clear();
-    counterMap.clear();
-  }
+    // Count up all the counter events.
+    for (var event : counterEvents) {
+      counterMap.merge(event.id(), event.amount(), Long::sum);
+    }
 
-  @Override
-  public String toString() {
     StringBuilder builder = new StringBuilder(100);
-
     builder
         .append("Timer ")
         .append(name)
         .append(" (")
         .append(timeMap.size())
         .append(" elements)\n");
-
     var i = -1;
     for (var entry : timeMap.entrySet()) {
       ++i;
 
       var id = entry.getKey();
-      long elapsed = entry.getValue().getElapsed();
+      long elapsed = entry.getValue().elapsedNs;
       if (elapsed < threshold) {
         continue;
       }
@@ -184,29 +213,29 @@ public String toString() {
     return builder.toString();
   }
 
-  private static class Timer {
-    long elapsed;
-    long start = -1;
+  private static final class Timer {
+    String name;
+    long elapsedNs = 0;
+    long startTimeNs = -1;
 
-    private long getTime() {
-      return System.nanoTime();
+    public Timer(String name) {
+      this.name = name;
     }
 
-    public void start() {
-      start = getTime();
-    }
-
-    public void stop() {
-      elapsed += (getTime() - start);
-      start = -1;
+    public void startAt(long timeNs) {
+      if (startTimeNs >= 0) {
+        log.warn("Invalid timer state: attempted to start timer {} that was already started", name);
+      }
+      startTimeNs = timeNs;
     }
 
-    public long getElapsed() {
-      long time = elapsed;
-      if (start > 0) {
-        time += (getTime() - start);
+    public void stopAt(long timeNs) {
+      if (startTimeNs < 0) {
+        log.warn("Invalid timer state: attempted to stop timer {} that was not started", name);
+        return;
       }
-      return time;
+      elapsedNs += (timeNs - startTimeNs);
+      startTimeNs = -1;
     }
   }
 }

src/main/java/net/rptools/maptool/client/ui/zone/gdx/GdxRenderer.java

@@ -39,6 +39,7 @@
 import java.text.NumberFormat;
 import java.util.*;
 import java.util.List;
+import java.util.concurrent.TimeUnit;
 import java.util.zip.Deflater;
 import javax.swing.*;
 import net.rptools.lib.AwtUtil;
@@ -371,6 +372,8 @@ public void render() {
           "GdxRenderer.renderZone",
           timer -> {
             timer.setThreshold(10);
+            timer.setThreshold(1, TimeUnit.MICROSECONDS);
+            timer.setReportingUnit(TimeUnit.MICROSECONDS);
             doRendering();
           });
     } catch (Exception ex) {