From c3206c2b40c6551115411ddfec33a8bf1df48c99 Mon Sep 17 00:00:00 2001 From: joaopluigi Date: Thu, 18 Dec 2025 15:32:27 -0300 Subject: [PATCH 1/2] initial draft on profile env execution --- src/nodely/data.clj | 32 ++++++++++++++++++++++++++++++++ 1 file changed, 32 insertions(+) diff --git a/src/nodely/data.clj b/src/nodely/data.clj index 0a6bf82..2496b07 100644 --- a/src/nodely/data.clj +++ b/src/nodely/data.clj @@ -170,6 +170,38 @@ ([node f] (catch-node node f {}))) +(comment + (require '[criterium.core :as criterium]) + + (defn time-body + [{:keys [k s]} f] + (fn [args] + (let [start# (criterium/timestamp) + ret# (f args) + finish# (criterium/timestamp)] + (swap! s assoc k (- finish# start#)) + ret#))) + + ; (update-node (leaf #{} #(Thread/sleep 1000)) new-value {}) + + (do + (def my-atom (atom {})) + (def updated-node (env-update-helper (leaf #{} (fn [_] (Thread/sleep 1000))) {:k :x :s my-atom} {} time-body)) + + (def update-node-branch (let [condition (leaf #{} (fn [_] (do (Thread/sleep 1000) true))) + truthy (leaf #{} (fn [_] (Thread/sleep 1000))) + falsey (value 20)] + (env-update-helper (branch condition truthy falsey) {:k :y :s my-atom} {} time-body))) + + {:x {:condition 1000 :truthy 1000 :falsey 1000}} + + ((:nodely.data/fn updated-node) {}) + @my-atom + ; + ) +; + ) + ;; ;; Env Utils ;; From 1190c36432a67652d85b9ec6073a1b540a9440b4 Mon Sep 17 00:00:00 2001 From: Sophia Velten Date: Thu, 15 Jan 2026 16:39:21 -0300 Subject: [PATCH 2/2] add claude code solution --- src/nodely/profile.clj | 245 +++++++++++++++++++++++++++++++++++ test/nodely/profile_test.clj | 210 ++++++++++++++++++++++++++++++ 2 files changed, 455 insertions(+) create mode 100644 src/nodely/profile.clj create mode 100644 test/nodely/profile_test.clj diff --git a/src/nodely/profile.clj b/src/nodely/profile.clj new file mode 100644 index 0000000..ccb6bb3 --- /dev/null +++ b/src/nodely/profile.clj @@ -0,0 +1,245 @@ +(ns nodely.profile + "Time profiling utilities for nodely environments. + + Provides non-invasive profiling that wraps existing environments + to record execution timing for each node without modifying the + core execution logic." + (:refer-clojure :exclude [sequence]) + (:require + [nodely.data :as data])) + +;; Forward declaration for conditional core.async support +(declare make-profiled-async-thunk) + +(defn- normalize-path + "Normalizes a path for use as a key. + Single-element paths become simple keywords, multi-element paths stay as vectors." + [path] + (if (= 1 (count path)) + (first path) + path)) + +(defn- record-timing! + "Records elapsed time in nanoseconds to the profile atom at the given path. + Single-element paths are stored as keywords, multi-element as vectors." + [profile-atom path elapsed-ns] + (swap! profile-atom assoc (normalize-path path) {:elapsed-ns elapsed-ns})) + +(defn- wrap-fn-with-timing + "Wraps a function to record its execution time into the profile atom." + [f profile-atom path] + (fn [args] + (let [start (System/nanoTime) + result (f args) + end (System/nanoTime)] + (record-timing! profile-atom path (- end start)) + result))) + +(defn- channel-leaf-fn? + "Checks if a function is an AsyncThunk (channel-leaf)." + [f] + (and (record? f) (contains? f :channel-fn))) + +(defn- profile-leaf + "Wraps a leaf node to record execution time. + Channel-leaf nodes (AsyncThunk) are wrapped specially to handle async timing." + [leaf profile-atom path] + (let [f (::data/fn leaf)] + (if (channel-leaf-fn? f) + (update leaf ::data/fn #(make-profiled-async-thunk % profile-atom path)) + (update leaf ::data/fn #(wrap-fn-with-timing % profile-atom path))))) + +(defn- profile-sequence + "Wraps a sequence node to record execution time of its process-node. + Note: sequence nodes with value process-nodes (simple fns) cannot be profiled + at the individual element level since the fn is applied by the engine." + [sequence-node profile-atom path] + (let [process-node (::data/process-node sequence-node)] + (case (::data/type process-node) + :value sequence-node ; value process-nodes are just functions stored as values + :leaf (update sequence-node ::data/process-node + #(profile-leaf % profile-atom (conj path :process)))))) + +(declare profile-node) + +(defn- profile-branch + "Wraps a branch node to record execution time of condition, truthy, and falsey paths." + [branch profile-atom path] + (-> branch + (update ::data/condition #(profile-node % profile-atom (conj path :condition))) + (update ::data/truthy #(profile-node % profile-atom (conj path :truthy))) + (update ::data/falsey #(profile-node % profile-atom (conj path :falsey))))) + +(defn profile-node + "Recursively wraps a node for profiling. + + For branches, uses path-aware keys to distinguish condition/truthy/falsey. + Values are not wrapped since they're immediate and require no computation." + [node profile-atom path] + (case (::data/type node) + :value node + :leaf (profile-leaf node profile-atom path) + :sequence (profile-sequence node profile-atom path) + :branch (profile-branch node profile-atom path))) + +(defn profile-env + "Transforms an environment for profiling. + + Returns a tuple of [profiled-env profile-atom] where: + - profiled-env: the environment with timing instrumentation + - profile-atom: an atom that will contain timing data after evaluation + + Example usage: + ```clojure + (let [[profiled-env profile-data] (profile-env my-env)] + (nodely/eval-key profiled-env :target {::nodely/engine :sync.lazy}) + @profile-data) + ;; => {:a {:elapsed-ns 1000234} + ;; :b {:elapsed-ns 2003421} + ;; [:c :condition] {:elapsed-ns 500123}} + ``` + + The profile data uses vector paths for nested nodes: + - Top-level leaf: :key -> {:elapsed-ns n} + - Branch condition: [:key :condition] -> {:elapsed-ns n} + - Branch truthy path: [:key :truthy] -> {:elapsed-ns n} + - Nested branches: [:key :truthy :condition] -> {:elapsed-ns n}" + [env] + (let [profile-atom (atom {})] + [(reduce-kv + (fn [acc k node] + (assoc acc k (profile-node node profile-atom [k]))) + {} + env) + profile-atom])) + +(defn profile-env-with-atom + "Like profile-env, but uses a provided atom for collecting profile data. + + Useful when you want to aggregate profiling data across multiple evaluations + or provide your own storage mechanism." + [env profile-atom] + (reduce-kv + (fn [acc k node] + (assoc acc k (profile-node node profile-atom [k]))) + {} + env)) + +(defn total-time + "Calculates the total time from profile data. + + Note: This is the sum of all node times, which may be greater than + wall-clock time if nodes were evaluated in parallel." + [profile-data] + (->> profile-data + vals + (map :elapsed-ns) + (reduce + 0))) + +(defn slowest-nodes + "Returns the n slowest nodes from profile data, sorted by elapsed time descending. + + Each entry is a map with :path and :elapsed-ns keys." + ([profile-data] + (slowest-nodes profile-data 10)) + ([profile-data n] + (->> profile-data + (map (fn [[path timing]] {:path path :elapsed-ns (:elapsed-ns timing)})) + (sort-by :elapsed-ns >) + (take n)))) + +(defn format-timing + "Formats elapsed nanoseconds as a human-readable string." + [elapsed-ns] + (cond + (< elapsed-ns 1000) (str elapsed-ns " ns") + (< elapsed-ns 1000000) (format "%.2f µs" (/ elapsed-ns 1000.0)) + (< elapsed-ns 1000000000) (format "%.2f ms" (/ elapsed-ns 1000000.0)) + :else (format "%.2f s" (/ elapsed-ns 1000000000.0)))) + +(defn summarize + "Returns a human-readable summary of profile data." + [profile-data] + {:total-time (format-timing (total-time profile-data)) + :node-count (count profile-data) + :slowest (->> (slowest-nodes profile-data 5) + (mapv #(update % :elapsed-ns format-timing)))}) + +;; +;; Async profiling support (requires core.async) +;; + +(defn- try-require-async + "Attempts to require core.async namespaces. Returns true if successful." + [] + (try + (require 'clojure.core.async) + (require 'nodely.engine.core-async.core) + true + (catch Exception _ + false))) + +;; Define the ProfiledAsyncThunk record type when core.async is available +(when (try-require-async) + (eval + '(do + (require '[clojure.core.async :as async]) + (require '[nodely.engine.core-async.core :as core-async]) + + (defrecord ProfiledAsyncThunk [channel-fn profile-atom path] + clojure.lang.IFn + (invoke [_ args] + (let [start (System/nanoTime) + result (async/! (:exception-ch opts) val) + (throw (core-async/user-exception val))) + + (nil? val) + (let [ex (ex-info "channel closed unexpectedly" {:channel orig-ch})] + (async/>! (:exception-ch opts) ex) + (throw (core-async/user-exception ex))) + + :else + (do (nodely.profile/record-timing! profile-atom path (- end start)) + (nodely.data/value val)))))) + (catch clojure.lang.ExceptionInfo e + (when-not (core-async/user-exception? e) + (throw e))))))))))) + +(defn make-profiled-async-thunk + "Creates a profiled wrapper for an AsyncThunk that properly handles + both sync (IFn) and async (FnToChannel) execution contexts." + [async-thunk profile-atom path] + (if (and (try-require-async) + (resolve 'nodely.profile/->ProfiledAsyncThunk)) + (let [constructor (resolve 'nodely.profile/->ProfiledAsyncThunk) + channel-fn (:channel-fn async-thunk)] + (constructor channel-fn profile-atom path)) + ;; Fallback - just wrap for sync timing + (let [channel-fn (:channel-fn async-thunk) + value 1)} + [profiled-env profile-atom] (profile/profile-env env)] + (is (map? profiled-env)) + (is (instance? clojure.lang.Atom profile-atom)) + (is (contains? profiled-env :a))))) + +(deftest profile-leaf-records-timing + (testing "profiled leaf nodes record execution time" + (let [env {:a (nodely/>value 1) + :b (nodely/>leaf (inc ?a))} + [profiled-env profile-atom] (profile/profile-env env) + result (nodely/eval-key profiled-env :b {::nodely/engine :sync.lazy})] + (is (= 2 result)) + (is (contains? @profile-atom :b)) + (is (number? (get-in @profile-atom [:b :elapsed-ns]))) + (is (pos? (get-in @profile-atom [:b :elapsed-ns])))))) + +(deftest profile-value-nodes-unchanged + (testing "value nodes are not modified (no timing needed)" + (let [env {:a (nodely/>value 42)} + [profiled-env profile-atom] (profile/profile-env env) + result (nodely/eval-key profiled-env :a {::nodely/engine :sync.lazy})] + (is (= 42 result)) + ;; Value nodes don't record timing since they're immediate + (is (not (contains? @profile-atom :a)))))) + +(deftest profile-branch-records-condition-and-path + (testing "branch nodes record timing for condition and taken path" + (let [env {:x (nodely/>value 4) + :y (nodely/>value 100) + :z (nodely/>if (nodely/>leaf (even? ?x)) + (nodely/>leaf (+ ?x 1)) + (nodely/>leaf ?y))} + [profiled-env profile-atom] (profile/profile-env env) + result (nodely/eval-key profiled-env :z {::nodely/engine :sync.lazy})] + (is (= 5 result)) + ;; Should have timing for condition + (is (contains? @profile-atom [:z :condition])) + (is (pos? (get-in @profile-atom [[:z :condition] :elapsed-ns]))) + ;; Should have timing for truthy path (since x=4 is even) + (is (contains? @profile-atom [:z :truthy])) + (is (pos? (get-in @profile-atom [[:z :truthy] :elapsed-ns]))) + ;; Falsey path should NOT have timing (not evaluated) + (is (not (contains? @profile-atom [:z :falsey])))))) + +(deftest profile-branch-falsey-path + (testing "branch nodes record timing for falsey path when condition is false" + (let [env {:x (nodely/>value 3) + :y (nodely/>value 100) + :z (nodely/>if (nodely/>leaf (even? ?x)) + (nodely/>leaf (+ ?x 1)) + (nodely/>leaf ?y))} + [profiled-env profile-atom] (profile/profile-env env) + result (nodely/eval-key profiled-env :z {::nodely/engine :sync.lazy})] + (is (= 100 result)) + ;; Should have timing for condition + (is (contains? @profile-atom [:z :condition])) + ;; Should have timing for falsey path (since x=3 is odd) + (is (contains? @profile-atom [:z :falsey])) + ;; Truthy path should NOT have timing (not evaluated) + (is (not (contains? @profile-atom [:z :truthy])))))) + +(deftest profile-sequence-with-value-process-node + (testing "sequence nodes with value process-node (simple fn) work but don't profile the fn" + (let [env {:items (nodely/>value [1 2 3]) + :doubled (nodely/>sequence #(* 2 %) ?items)} + [profiled-env profile-atom] (profile/profile-env env) + result (nodely/eval-key profiled-env :doubled {::nodely/engine :sync.lazy})] + ;; Result should still be correct + (is (= [2 4 6] result)) + ;; No timing recorded for value-type process nodes + (is (not (contains? @profile-atom :doubled))) + (is (not (contains? @profile-atom [:doubled :process])))))) + +(deftest profile-nested-branches + (testing "nested branches record timing at each level" + (let [env {:a (nodely/>value true) + :b (nodely/>value false) + :x (nodely/>value 10) + :y (nodely/>value 20) + :z (nodely/>if (nodely/>leaf ?a) + (nodely/>if (nodely/>leaf ?b) + (nodely/>leaf ?x) + (nodely/>leaf ?y)) + (nodely/>value 0))} + [profiled-env profile-atom] (profile/profile-env env) + result (nodely/eval-key profiled-env :z {::nodely/engine :sync.lazy})] + (is (= 20 result)) + ;; Outer condition + (is (contains? @profile-atom [:z :condition])) + ;; Inner branch condition (truthy path of outer) + (is (contains? @profile-atom [:z :truthy :condition])) + ;; Inner falsey result (since b=false) + (is (contains? @profile-atom [:z :truthy :falsey]))))) + +(deftest profile-multiple-leaves + (testing "multiple leaf nodes all record timing" + (let [env {:a (nodely/>value 1) + :b (nodely/>leaf (+ ?a 1)) + :c (nodely/>leaf (+ ?b 1)) + :d (nodely/>leaf (+ ?c 1))} + [profiled-env profile-atom] (profile/profile-env env) + result (nodely/eval-key profiled-env :d {::nodely/engine :sync.lazy})] + (is (= 4 result)) + (is (contains? @profile-atom :b)) + (is (contains? @profile-atom :c)) + (is (contains? @profile-atom :d))))) + +(deftest profile-env-with-atom-uses-provided-atom + (testing "profile-env-with-atom uses the provided atom" + (let [my-atom (atom {:existing :data}) + env {:a (nodely/>value 1) + :b (nodely/>leaf (inc ?a))} + profiled-env (profile/profile-env-with-atom env my-atom) + _ (nodely/eval-key profiled-env :b {::nodely/engine :sync.lazy})] + ;; Should preserve existing data + (is (= :data (:existing @my-atom))) + ;; Should add new timing data + (is (contains? @my-atom :b))))) + +(deftest total-time-sums-all-timings + (testing "total-time returns sum of all elapsed times" + (let [profile-data {[:a] {:elapsed-ns 1000} + [:b] {:elapsed-ns 2000} + [:c :condition] {:elapsed-ns 500}}] + (is (= 3500 (profile/total-time profile-data)))))) + +(deftest slowest-nodes-returns-sorted-results + (testing "slowest-nodes returns nodes sorted by time descending" + (let [profile-data {[:a] {:elapsed-ns 1000} + [:b] {:elapsed-ns 5000} + [:c] {:elapsed-ns 3000} + [:d] {:elapsed-ns 2000}} + slowest (profile/slowest-nodes profile-data 3)] + (is (= 3 (count slowest))) + (is (= [:b] (:path (first slowest)))) + (is (= [:c] (:path (second slowest)))) + (is (= [:d] (:path (nth slowest 2))))))) + +(deftest format-timing-formats-correctly + (testing "format-timing produces human-readable output" + (is (= "500 ns" (profile/format-timing 500))) + (is (= "1.50 µs" (profile/format-timing 1500))) + (is (= "2.50 ms" (profile/format-timing 2500000))) + (is (= "1.50 s" (profile/format-timing 1500000000))))) + +(deftest summarize-returns-summary-map + (testing "summarize returns a useful summary" + (let [profile-data {[:a] {:elapsed-ns 1000000} + [:b] {:elapsed-ns 2000000} + [:c] {:elapsed-ns 3000000}} + summary (profile/summarize profile-data)] + (is (= "6.00 ms" (:total-time summary))) + (is (= 3 (:node-count summary))) + (is (= 3 (count (:slowest summary)))) + (is (= [:c] (:path (first (:slowest summary)))))))) + +(deftest profile-with-slow-operations + (testing "profiling captures meaningful timing for slow operations" + (let [env {:a (nodely/>value 1) + :b (nodely/>leaf (do (Thread/sleep 10) (inc ?a)))} + [profiled-env profile-atom] (profile/profile-env env) + _ (nodely/eval-key profiled-env :b {::nodely/engine :sync.lazy}) + elapsed-ns (get-in @profile-atom [:b :elapsed-ns])] + ;; Should be at least 10ms (10,000,000 ns) + (is (>= elapsed-ns 10000000))))) + +(deftest profile-works-with-core-async-engine + (testing "profiling works with core-async lazy-scheduling engine" + (let [env {:a (nodely/>value 1) + :b (nodely/>leaf (inc ?a)) + :c (nodely/>leaf (+ ?a ?b))} + [profiled-env profile-atom] (profile/profile-env env) + result (nodely/eval-key profiled-env :c {::nodely/engine :core-async.lazy-scheduling})] + (is (= 3 result)) + (is (contains? @profile-atom :b)) + (is (contains? @profile-atom :c))))) + +(def tricky-env + {:a (nodely/>value 1) + :b (nodely/>leaf (inc ?a)) + :d (api/>channel-leaf + (core.async/go + (core.async/leaf (+ ?a ?b))}) + +(deftest profile-tricky-env-with-channel-leaf + (testing "profiling works with tricky-env containing channel-leaf nodes" + (testing "regular leaf nodes in the dependency chain are profiled correctly" + (let [[profiled-env profile-atom] (profile/profile-env tricky-env) + ;; Evaluate :c which doesn't involve the channel-leaf + result (nodely/eval-key profiled-env :d {::nodely/engine :core-async.lazy-scheduling})] + ;; :c depends on :b and :a + ;; Result should be (+ 1 (inc 1)) = 3 + ;; o + ;; + (is (>= (get-in @profile-atom [:d :elapsed-ns]) 2000000000)) + (is (= 4 result))))))