Merge pull request #5800 from kwvanderlinde/performance/5795-timer-improvements

Timer improvements

Author: kwvanderlinde

common/src/main/java/net/rptools/lib/StringUtil.java

@@ -19,6 +19,7 @@
 import java.util.ArrayList;
 import java.util.Arrays;
 import java.util.List;
+import java.util.concurrent.TimeUnit;
 import java.util.regex.Pattern;
 
 /**
@@ -28,6 +29,18 @@ public class StringUtil {
   private static NumberFormat nf = NumberFormat.getNumberInstance();
   private static final int MIN_FRACTION_DIGITS = 0;
 
+  public static String formatTimeUnit(TimeUnit unit) {
+    return switch (unit) {
+      case NANOSECONDS -> "ns";
+      case MICROSECONDS -> "μs";
+      case MILLISECONDS -> "ms";
+      case SECONDS -> "s";
+      case MINUTES -> "m";
+      case HOURS -> "h";
+      case DAYS -> "d";
+    };
+  }
+
   public static String formatDecimal(double value) {
     String result1;
     result1 = nf.format(value); // On a separate line to allow for breakpoints

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

@@ -14,18 +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> {
@@ -49,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();
     }
   }
 
@@ -62,23 +63,38 @@ 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;
   private boolean enabled;
 
-  public CodeTimer(String n) {
+  private CodeTimer(String n) {
     name = n;
     enabled = true;
   }
 
-  public boolean isEnabled() {
-    return enabled;
+  public void setThreshold(long threshold) {
+    this.threshold = TimeUnit.NANOSECONDS.convert(threshold, TimeUnit.MILLISECONDS);
   }
 
-  public void setThreshold(long threshold) {
-    this.threshold = threshold;
+  public void setThreshold(long threshold, TimeUnit timeUnit) {
+    this.threshold = TimeUnit.NANOSECONDS.convert(threshold, timeUnit);
+  }
+
+  public void setReportingUnit(TimeUnit reportingUnit) {
+    this.reportingUnit = reportingUnit;
   }
 
   public void setEnabled(boolean enabled) {
@@ -90,62 +106,95 @@ public void increment(String id) {
   }
 
   public void increment(String id, int amount) {
-    counterMap.merge(id, amount, Integer::sum);
+    if (!enabled) {
+      return;
+    }
+    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));
+  }
 
-    Timer timer = timeMap.get(id);
-    if (timer == null) {
-      throw new IllegalArgumentException("Could not find timer id: " + id);
+  private void complete() {
+    if (!enabled) {
+      return;
     }
-    timer.stop();
-  }
 
-  public void clear() {
-    timeMap.clear();
-    counterMap.clear();
+    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);
+        });
   }
 
-  @Override
-  public String toString() {
-    StringBuilder builder = new StringBuilder(100);
+  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());
+      }
+    }
 
+    // Count up all the counter events.
+    for (var event : counterEvents) {
+      counterMap.merge(event.id(), event.amount(), Long::sum);
+    }
+
+    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() / 1_000_000;
+      long elapsed = entry.getValue().elapsedNs;
       if (elapsed < threshold) {
         continue;
       }
-      builder.append(String.format("  %3d.  %6d ms  %s\n", i, elapsed, id));
+
+      builder.append(
+          String.format(
+              "  %3d.  %6d %s  %s\n",
+              i,
+              reportingUnit.convert(elapsed, TimeUnit.NANOSECONDS),
+              StringUtil.formatTimeUnit(reportingUnit),
+              id));
     }
 
     if (!counterMap.isEmpty()) {
@@ -164,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/swing/NoteFrame.java

@@ -17,18 +17,18 @@
 import java.awt.BorderLayout;
 import java.awt.Color;
 import java.awt.Dimension;
+import java.awt.Font;
 import java.awt.event.WindowEvent;
 import javax.swing.BorderFactory;
 import javax.swing.JButton;
 import javax.swing.JFrame;
 import javax.swing.JPanel;
 import javax.swing.JScrollPane;
 import javax.swing.JTextArea;
-import javax.swing.text.JTextComponent;
 import net.rptools.maptool.language.I18N;
 
 public class NoteFrame extends JFrame {
-  private JTextComponent noteArea;
+  private JTextArea noteArea;
   private JButton clearButton;
   private JButton closeButton;
 
@@ -43,10 +43,12 @@ private void initUI() {
     add(BorderLayout.SOUTH, createButtonBar());
   }
 
-  private JTextComponent getNoteArea() {
+  private JTextArea getNoteArea() {
     if (noteArea == null) {
       noteArea = new JTextArea();
       noteArea.setBorder(BorderFactory.createLineBorder(Color.black));
+      noteArea.setFont(new Font(Font.MONOSPACED, Font.PLAIN, noteArea.getFont().getSize()));
+      noteArea.setEditable(false);
     }
     return noteArea;
   }
@@ -78,7 +80,8 @@ private JButton getCloseButton() {
   }
 
   public synchronized void addText(String text) {
-    getNoteArea().setText(getNoteArea().getText() + text + "\n");
+    getNoteArea().append(text);
+    getNoteArea().append("\n");
     getNoteArea().setCaretPosition(getNoteArea().getText().length());
   }
 }