%time magic #104

attempt to measure telemetry at a lower level, excluding JShell compile time

Author: andrus

jjava-jupyter/src/main/java/org/dflib/jjava/jupyter/instrumentation/EvalTimer.java

@@ -3,7 +3,6 @@
 import org.dflib.jjava.jupyter.Extension;
 import org.dflib.jjava.jupyter.channels.JupyterConnection;
 import org.dflib.jjava.jupyter.channels.ShellReplyEnvironment;
-import org.dflib.jjava.jupyter.instrumentation.EvalTimer;
 import org.dflib.jjava.jupyter.kernel.comm.CommManager;
 import org.dflib.jjava.jupyter.kernel.display.DisplayData;
 import org.dflib.jjava.jupyter.kernel.display.Renderer;
@@ -218,14 +217,13 @@ public Object evalRaw(String source) {
      * Creates and returns a builder for an evaluation pipeline.
      */
     public <T> EvalBuilder<T> evalBuilder(String source) {
-        return new SimpleEvalBuilder<>(this, source, EvalTimer.DO_NOTHING);
+        return new SimpleEvalBuilder<>(this, source);
     }
 
     /**
-     * Evaluates the source code in a way appropriate for a given kernel subclass, and using the provided timer to
-     * measure evaluation time.
+     * Evaluates the source code in a way appropriate for a given kernel subclass.
      */
-    protected abstract Object doEval(String source, EvalTimer timer);
+    protected abstract Object doEval(String source);
 
     /**
      * Inspect the code to get things such as documentation for a function. This is

jjava-jupyter/src/main/java/org/dflib/jjava/jupyter/instrumentation/WallAndCpuTimer.java

@@ -1,6 +1,5 @@
 package org.dflib.jjava.jupyter.kernel;
 
-import org.dflib.jjava.jupyter.instrumentation.EvalTimer;
 import org.dflib.jjava.jupyter.kernel.display.DisplayData;
 
 public interface EvalBuilder<T> {
@@ -9,10 +8,5 @@ public interface EvalBuilder<T> {
 
     EvalBuilder<DisplayData> renderResults();
 
-    /**
-     * Installs an evaluation timer for this builder eval call.
-     */
-    EvalBuilder<T> timed(EvalTimer timer);
-
     T eval();
 }

jjava-jupyter/src/main/java/org/dflib/jjava/jupyter/instrumentation/WallTimer.java

@@ -1,6 +1,5 @@
 package org.dflib.jjava.jupyter.kernel;
 
-import org.dflib.jjava.jupyter.instrumentation.EvalTimer;
 import org.dflib.jjava.jupyter.kernel.display.DisplayData;
 
 public class RenderedEvalBuilder implements EvalBuilder<DisplayData> {
@@ -23,11 +22,6 @@ public RenderedEvalBuilder resolveMagics() {
         return new RenderedEvalBuilder(kernel, delegate.resolveMagics());
     }
 
-    @Override
-    public EvalBuilder<DisplayData> timed(EvalTimer timer) {
-        return new RenderedEvalBuilder(kernel, delegate.timed(timer));
-    }
-
     @Override
     public DisplayData eval() {
         Object o = delegate.eval();

jjava-jupyter/src/main/java/org/dflib/jjava/jupyter/kernel/BaseKernel.java

@@ -1,28 +1,20 @@
 package org.dflib.jjava.jupyter.kernel;
 
-import org.dflib.jjava.jupyter.instrumentation.EvalTimer;
 import org.dflib.jjava.jupyter.kernel.display.DisplayData;
 
 public class SimpleEvalBuilder<T> implements EvalBuilder<T> {
 
     private final BaseKernel kernel;
     private final String source;
-    private final EvalTimer timer;
 
-    protected SimpleEvalBuilder(BaseKernel kernel, String source, EvalTimer timer) {
+    protected SimpleEvalBuilder(BaseKernel kernel, String source) {
         this.kernel = kernel;
         this.source = source;
-        this.timer = timer;
-    }
-
-    @Override
-    public EvalBuilder<T> timed(EvalTimer timer) {
-        return new SimpleEvalBuilder<>(kernel, source, timer);
     }
 
     @Override
     public EvalBuilder<T> resolveMagics() {
-        return new SimpleEvalBuilder<>(kernel, kernel.getMagicsResolver().resolve(source), timer);
+        return new SimpleEvalBuilder<>(kernel, kernel.getMagicsResolver().resolve(source));
     }
 
     @Override
@@ -32,11 +24,6 @@ public EvalBuilder<DisplayData> renderResults() {
 
     @Override
     public T eval() {
-        timer.start();
-        try {
-            return (T) kernel.doEval(source, timer);
-        } finally {
-            timer.stop();
-        }
+        return (T) kernel.doEval(source);
     }
 }

jjava-jupyter/src/main/java/org/dflib/jjava/jupyter/kernel/EvalBuilder.java

@@ -0,0 +1,31 @@
+package org.dflib.jjava.jupyter.telemetry;
+
+/**
+ * Aggregates some telemetry number for a sequence of "measurements". Instead of a single method wrapping a measure code
+ * invocation lambda, each measurement is done via two separate methods: {@link #measurementStart()} and
+ * {@link #measurementEnd(Object)}. This is to make the collector minimally invasive and not adding to the call stack
+ * trace.
+ */
+public interface TelemetryCollector<I> {
+
+    I measurementStart();
+
+    void measurementEnd(I startState);
+
+    void stop();
+
+    TelemetryCollector<Object> DO_NOTHING = new TelemetryCollector<>() {
+        @Override
+        public void measurementEnd(Object startState) {
+        }
+
+        @Override
+        public Object measurementStart() {
+            return null;
+        }
+
+        @Override
+        public void stop() {
+        }
+    };
+}

jjava-jupyter/src/main/java/org/dflib/jjava/jupyter/kernel/RenderedEvalBuilder.java

@@ -0,0 +1,75 @@
+package org.dflib.jjava.jupyter.telemetry;
+
+import java.lang.management.ThreadMXBean;
+import java.util.concurrent.atomic.AtomicLong;
+
+public abstract class WallAndCpuTimeCollector implements TelemetryCollector<WallAndCpuTimeCollector.Measure> {
+
+    private final ThreadMXBean threadMXBean;
+    private final AtomicLong totalWT;
+    private final AtomicLong totalUT;
+    private final AtomicLong totalCT;
+
+    public static boolean canMeasureCpuTimes(ThreadMXBean threadMXBean) {
+        // according to JavaDocs, isThreadCpuTimeEnabled() can throw in some cases
+        try {
+            return threadMXBean.isCurrentThreadCpuTimeSupported() && threadMXBean.isThreadCpuTimeEnabled();
+        } catch (Exception e) {
+            return false;
+        }
+    }
+
+    public WallAndCpuTimeCollector(ThreadMXBean threadMXBean) {
+        this.threadMXBean = threadMXBean;
+        this.totalWT = new AtomicLong();
+        this.totalUT = new AtomicLong();
+        this.totalCT = new AtomicLong();
+    }
+
+    @Override
+    public Measure measurementStart() {
+        return new Measure(
+                System.nanoTime(),
+                threadMXBean.getCurrentThreadUserTime(),
+                threadMXBean.getCurrentThreadCpuTime()
+        );
+    }
+
+    @Override
+    public void measurementEnd(Measure m) {
+
+        long wt = System.nanoTime();
+        long ut = threadMXBean.getCurrentThreadUserTime();
+        long ct = threadMXBean.getCurrentThreadCpuTime();
+
+        totalWT.addAndGet(wt - m.wt);
+
+        // sanity check
+        if (m.ut != -1 && ut != -1 && m.ct != -1 && ct != -1) {
+            totalUT.addAndGet(ut - m.ut);
+            totalCT.addAndGet(ct - m.ct);
+        } else {
+            totalUT.set(-1);
+            totalCT.set(-1);
+        }
+    }
+
+    @Override
+    public void stop() {
+        onStop(totalWT.get(), totalUT.get(), totalCT.get());
+    }
+
+    protected abstract void onStop(long wallTimeNanos, long userTimeNanos, long totalTimeNanos);
+
+    public static class Measure {
+        final long wt;
+        final long ut;
+        final long ct;
+
+        public Measure(long wt, long ut, long ct) {
+            this.ct = ct;
+            this.wt = wt;
+            this.ut = ut;
+        }
+    }
+}

jjava-jupyter/src/main/java/org/dflib/jjava/jupyter/kernel/SimpleEvalBuilder.java

@@ -0,0 +1,30 @@
+package org.dflib.jjava.jupyter.telemetry;
+
+import java.util.concurrent.atomic.AtomicLong;
+
+public abstract class WallTimeCollector implements TelemetryCollector<Long> {
+
+    private final AtomicLong totalWallTime;
+
+    public WallTimeCollector() {
+        this.totalWallTime = new AtomicLong();
+    }
+
+    @Override
+    public Long measurementStart() {
+        return System.nanoTime();
+    }
+
+    @Override
+    public void measurementEnd(Long startState) {
+        long delta = System.nanoTime() - startState;
+        totalWallTime.addAndGet(delta);
+    }
+
+    @Override
+    public void stop() {
+        onStop(totalWallTime.get());
+    }
+
+    protected abstract void onStop(long wallTimeNanos);
+}