proof of concept profiling

.gitignore

@@ -183,3 +183,6 @@ simgui-ds.json
 simgui.json
 
 !src/main/deploy/photon-configs/*.zip
+
+/*.wpilog
+/*-profile.txt

build.gradle

@@ -104,6 +104,7 @@ dependencies {
 
     implementation 'org.apache.httpcomponents:httpclient:4.5.14'
     implementation 'org.apache.httpcomponents:httpmime:4.5.14'
+    implementation 'it.unimi.dsi:fastutil:8.5.14'
 }
 
 // Simulation configuration (e.g. environment variables).

src/main/java/frc/lib/profiling/EmptyProfiler.java

@@ -0,0 +1,40 @@
+package frc.lib.profiling;
+
+/**
+ * This logger explicitly does nothing. Because there is no variance in doing nothing, a single
+ * instance is provided as {@link #INSTANCE}.
+ */
+public final class EmptyProfiler implements Profiler {
+
+    /**
+     * The sole instance of {@link EmptyProfiler}.
+     */
+    public static final EmptyProfiler INSTANCE = new EmptyProfiler();
+
+    private EmptyProfiler() {}
+
+    @Override
+    public void save() {
+
+    }
+
+    @Override
+    public void startTick() {
+
+    }
+
+    @Override
+    public void endTick() {
+
+    }
+
+    @Override
+    public void push(String location) {
+
+    }
+
+    @Override
+    public void pop() {
+
+    }
+}

src/main/java/frc/lib/profiling/LoggingProfiler.java

@@ -0,0 +1,195 @@
+package frc.lib.profiling;
+
+import java.io.FileOutputStream;
+import java.io.IOException;
+import java.lang.reflect.Field;
+import java.time.LocalDateTime;
+import java.time.format.DateTimeFormatter;
+import java.util.ArrayList;
+import java.util.HashMap;
+import java.util.List;
+import java.util.Map;
+import java.util.function.LongSupplier;
+import org.littletonrobotics.junction.Logger;
+import org.littletonrobotics.junction.ReceiverThread;
+import org.littletonrobotics.junction.wpilog.WPILOGWriter;
+import it.unimi.dsi.fastutil.longs.LongArrayList;
+import it.unimi.dsi.fastutil.longs.LongList;
+
+/**
+ * This logger saves runtime performance metrics to memory. These metrics are subsequently written
+ * to a file when {@link #save() save} is called.
+ */
+public final class LoggingProfiler implements Profiler {
+    private static final char SPLIT_CHAR = '\u001e';
+
+    private final List<String> path = new ArrayList<>();
+    private final LongList timeList = new LongArrayList();
+    private final Map<String, LoggingProfiler.LocatedInfo> locationInfos = new HashMap<>();
+    private final LongSupplier timeGetter;
+    private final double timeDivisor;
+    private final ProfileLoggingFormat loggingFormat;
+    private boolean tickStarted;
+    private String fullPath = "";
+    private LoggingProfiler.LocatedInfo currentInfo;
+
+    /**
+     * @param filePath file path to write when {@link #save() save} is called.
+     * @param timeGetter a supplier for the current time.
+     * @param timeDivisor a conversion factor turning the units of {@code timeGetter} to the units
+     *        output to a file.
+     * @param loggingFormat file format to use when {@link #save() save} is called.
+     */
+    public LoggingProfiler(LongSupplier timeGetter, double timeDivisor,
+        ProfileLoggingFormat loggingFormat) {
+        this.timeGetter = timeGetter;
+        this.timeDivisor = timeDivisor;
+        this.loggingFormat = loggingFormat;
+    }
+
+    @Override
+    public void save() {
+        try {
+            String filePath = null;
+
+            Field dataReceiversField = ReceiverThread.class.getDeclaredField("dataReceivers");
+            dataReceiversField.setAccessible(true);
+            Field receiverThreadField = Logger.class.getDeclaredField("receiverThread");
+            receiverThreadField.setAccessible(true);
+            Field logDateField = WPILOGWriter.class.getDeclaredField("logDate");
+            logDateField.setAccessible(true);
+            Field randomIdentifierField = WPILOGWriter.class.getDeclaredField("randomIdentifier");
+            randomIdentifierField.setAccessible(true);
+            Field timeFormatterField = WPILOGWriter.class.getDeclaredField("timeFormatter");
+            timeFormatterField.setAccessible(true);
+            Field logMatchTextField = WPILOGWriter.class.getDeclaredField("logMatchText");
+            logMatchTextField.setAccessible(true);
+
+            Object dataReceivers = dataReceiversField.get(receiverThreadField.get(null));
+            if (dataReceivers instanceof List<?> dataReceiversList) {
+                for (Object dataReceiver : dataReceiversList) {
+                    if (dataReceiver instanceof WPILOGWriter dataWriter) {
+                        StringBuilder newFilenameBuilder = new StringBuilder();
+                        newFilenameBuilder.append("Log_");
+                        LocalDateTime logDate = (LocalDateTime) logDateField.get(dataWriter);
+                        if (logDate == null) {
+                            Object randomIdentifier = randomIdentifierField.get(dataWriter);
+                            newFilenameBuilder.append(randomIdentifier);
+                        } else {
+                            DateTimeFormatter timeFormatter =
+                                (DateTimeFormatter) timeFormatterField.get(dataWriter);
+                            newFilenameBuilder.append(timeFormatter.format(logDate));
+                        }
+                        Object logMatchText = logMatchTextField.get(dataWriter);
+                        if (logMatchText != null) {
+                            newFilenameBuilder.append("_");
+                            newFilenameBuilder.append(logMatchText);
+                        }
+                        newFilenameBuilder.append("-profile.txt");
+                        filePath = newFilenameBuilder.toString();
+                    }
+                }
+            }
+            try (var outStream = new FileOutputStream(filePath)) {
+                loggingFormat.begin(outStream);
+                for (var entry : locationInfos.entrySet().stream().sorted((a, b) -> loggingFormat
+                    .compare(a.getKey(), a.getValue(), b.getKey(), b.getValue())).toList()) {
+                    var info = entry.getValue();
+                    var name = entry.getKey().replace(SPLIT_CHAR, '.');
+                    loggingFormat.write(name, info, timeDivisor, outStream);
+                }
+                loggingFormat.end(outStream);
+            }
+        } catch (IOException | NoSuchFieldException | SecurityException | IllegalArgumentException
+            | IllegalAccessException e) {
+            throw new RuntimeException(e);
+        }
+    }
+
+    @Override
+    public void startTick() {
+        if (this.tickStarted) {
+            throw new RuntimeException("Profiler tick already started. Missing endTick()?");
+        } else {
+            this.tickStarted = true;
+            this.fullPath = "";
+            this.path.clear();
+            this.push("root");
+        }
+    }
+
+    @Override
+    public void endTick() {
+        if (!this.tickStarted) {
+            throw new RuntimeException("Profiler tick already ended. Missing startTick()?");
+        } else {
+            this.pop();
+            this.tickStarted = false;
+            if (!this.fullPath.isEmpty()) {
+                throw new RuntimeException(
+                    "Profiler tick ended before path was fully popped. Mismatched push/pop?");
+            }
+        }
+    }
+
+    @Override
+    public void push(String location) {
+        if (!this.tickStarted) {
+            throw new RuntimeException("Cannot push '" + location
+                + "' to the profiler if profiler tick hasn't started. Missing startTick()?");
+        } else {
+            if (!this.fullPath.isEmpty()) {
+                this.fullPath = this.fullPath + SPLIT_CHAR;
+            }
+            this.fullPath += location;
+            this.path.add(this.fullPath);
+            this.timeList.add(timeGetter.getAsLong());
+            this.currentInfo = null;
+        }
+    }
+
+    @Override
+    public void pop() {
+        if (!this.tickStarted) {
+            throw new RuntimeException(
+                "Cannot pop from profiler if profiler tick hasn't started. Missing startTick()?");
+        } else if (this.timeList.isEmpty()) {
+            throw new RuntimeException(
+                "Tried to pop one too many times! Mismatched push() and pop()?");
+        } else {
+            this.path.remove(this.path.size() - 1);
+
+            long currentTime = timeGetter.getAsLong();
+            long startTime = this.timeList.removeLong(this.timeList.size() - 1);
+            long timeSpan = currentTime - startTime;
+
+            LocatedInfo locatedInfo = this.getCurrentInfo();
+
+            locatedInfo.totalTime += timeSpan;
+            locatedInfo.visits++;
+            locatedInfo.maxTime = Math.max(locatedInfo.maxTime, timeSpan);
+            locatedInfo.minTime = Math.min(locatedInfo.minTime, timeSpan);
+            this.fullPath = this.path.isEmpty() ? "" : this.path.get(this.path.size() - 1);
+            this.currentInfo = null;
+        }
+    }
+
+    private LocatedInfo getCurrentInfo() {
+        if (this.currentInfo == null) {
+            this.currentInfo =
+                this.locationInfos.computeIfAbsent(this.fullPath, _k -> new LocatedInfo());
+        }
+        return this.currentInfo;
+    }
+
+    /**
+     * Performance metrics for a given state of the profile stack.
+     */
+    public static class LocatedInfo {
+        long maxTime = Long.MIN_VALUE;
+        long minTime = Long.MAX_VALUE;
+        long totalTime;
+        long visits;
+    }
+
+}

src/main/java/frc/lib/profiling/ProfileLoggingFormat.java

@@ -0,0 +1,31 @@
+package frc.lib.profiling;
+
+import java.io.OutputStream;
+import frc.lib.profiling.LoggingProfiler.LocatedInfo;
+
+/**
+ * Describes how a profile is written to a file.
+ */
+public interface ProfileLoggingFormat {
+
+    /**
+     * Comparison function used for sorting profile information.
+     */
+    int compare(String leftName, LocatedInfo leftInfo, String rightName, LocatedInfo rightInfo);
+
+    /**
+     * Write a profile to the file specified in {@code outStream}.
+     */
+    void write(String name, LocatedInfo info, double timeDivisor, OutputStream outStream);
+
+    /**
+     * Write information before seeing any profiles.
+     */
+    void begin(OutputStream outputStream);
+
+    /**
+     * Write information after seeing all profiles.
+     */
+    void end(OutputStream outputStream);
+
+}

src/main/java/frc/lib/profiling/Profiler.java

@@ -0,0 +1,87 @@
+package frc.lib.profiling;
+
+/**
+ * Interface supporting profiling calls for measuring and saving runtime performance.
+ *
+ * Operates on the idea of a "profile stack", which is just a stack of names with associated
+ * profiling metrics. For instance, the following code
+ *
+ * <pre>
+ * {@code
+ * Profiler profiler = someProfiler();
+ * profiler.startTick();
+ * profiler.push("Hello")
+ * someExpensiveFunction();
+ * profiler.swap("World")
+ * someLessExpensiveFunction();
+ * profiler.pop();
+ * profiler.endTick();
+ * }
+ * </pre>
+ *
+ * will produce a profile with three sections:
+ * <ul>
+ * <li>{@code root}, which describes the time between {@link #startTick() profiler.startTick()} and
+ * {@link #endTick() profiler.endTick()},</li>
+ * <li>{@code root.Hello}, which describes the time between {@link #push(String)
+ * profiler.push("Hello")} and {@link #swap(String) profiler.swap("World")}, and</li>
+ * <li>{@code root.World}, which describes the time between {@link #swap(String)
+ * profiler.swap("World")} and {@link #pop() profiler.pop()}.
+ * </ul>
+ *
+ * A call to {@link #save() profiler.save()} would output the performance metrics of these sections
+ * in the case of a {@link LoggingProfiler}.
+ */
+public sealed interface Profiler permits EmptyProfiler, LoggingProfiler, ValidatingProfiler {
+    /**
+     * Called at the top of the main loop. Indicates the profiler is at "root" and records the start
+     * time. Within the main loop, no meaningful work should occur before this call.
+     *
+     * @throws RuntimeException if called twice without a call to {@link #endTick() endTick} in
+     *         between.
+     */
+    void startTick();
+
+    /**
+     * Called at the bottom of the main loop. Indicates the profiler's "root" is finished, and its
+     * time usage metrics are updated. Within the main loop, no meaningful work should occur after
+     * this call.
+     *
+     * @throws RuntimeException if the profile stack is not empty or {@link #startTick() startTick}
+     *         has not been called.
+     */
+    void endTick();
+
+    /**
+     * The profile stack is pushed with the {@code location} as its top. Must be accompanied by a
+     * call to {@link #pop() pop}.
+     *
+     * @throws RuntimeException if {@link #startTick() startTick} hasn't been called yet.
+     */
+    void push(String location);
+
+    /**
+     * The profile stack is popped. Must be preceded (at some point) by a call to
+     * {@link #push(String) push}.
+     *
+     * @throws RuntimeException if {@link #startTick() startTick} hasn't been called yet or the
+     *         profile stack is empty.
+     */
+    void pop();
+
+    /**
+     * The top of the profile stack is replaced with {@code location}. This is equivalent to a call
+     * to {@link #pop() pop} followed immediately by a call to {@link #push(String) push}.
+     *
+     * @throws RuntimeException if the profile stack is empty.
+     */
+    default void swap(String location) {
+        pop();
+        push(location);
+    }
+
+    /**
+     * Write profile data to a file.
+     */
+    void save();
+}