diff --git a/src/day8/re_frame/trace/events.cljs b/src/day8/re_frame/trace/events.cljs index feffeb9..f57f4e9 100644 --- a/src/day8/re_frame/trace/events.cljs +++ b/src/day8/re_frame/trace/events.cljs @@ -549,9 +549,11 @@ (utils/id-between-xf (:id (first match)) (:id (last match)))) filtered-traces) start-of-epoch (nth epoch-traces 0) + event-handler-trace (utils/spy (first (filter metam/event-handler? epoch-traces))) finish-run (or (first (filter metam/finish-run? epoch-traces)) (utils/last-in-vec epoch-traces))] - {:re-frame/event-time (metam/elapsed-time start-of-epoch finish-run)})) + {:re-frame/event-time (metam/elapsed-time start-of-epoch finish-run) + :re-frame/event-handler-time (:duration event-handler-trace)})) new-matches) new-matches (map (fn [match sub-match t] {:match-info match diff --git a/src/day8/re_frame/trace/metamorphic.cljc b/src/day8/re_frame/trace/metamorphic.cljc index cb90052..8eb357d 100644 --- a/src/day8/re_frame/trace/metamorphic.cljc +++ b/src/day8/re_frame/trace/metamorphic.cljc @@ -168,7 +168,9 @@ (= 2 (get sub :layer)))) -(defn finish-run? [event] +(defn finish-run? + "Marks the end of event processing running." + [event] (and (fsm-trigger? event) (= (:operation event) [:running :finish-run]))) @@ -176,6 +178,9 @@ (defn event-run? [event] (= :event (:op-type event))) +(defn event-handler? [trace] + (= :event/handler (:op-type trace))) + (defn start-of-epoch? "Detects the start of a re-frame epoch diff --git a/src/day8/re_frame/trace/subs.cljs b/src/day8/re_frame/trace/subs.cljs index 5cd7de4..094449b 100644 --- a/src/day8/re_frame/trace/subs.cljs +++ b/src/day8/re_frame/trace/subs.cljs @@ -332,6 +332,14 @@ (fn [frame-traces] (count (filter metam/request-animation-frame? frame-traces)))) +(defn ^number +nil + "Returns the sum of nums. (+) returns nil (not 0 like in cljs.core)." + ([] nil) + ([x] x) + ([x y] (cljs.core/+ x y)) + ([x y & more] + (reduce + (cljs.core/+ x y) more))) + (rf/reg-sub :timing/animation-frame-time :<- [:timing/animation-frame-traces] @@ -346,15 +354,13 @@ subs-time (transduce (comp (filter metam/subscription?) (map :duration)) - + af-traces) + +nil af-traces) render-time (transduce (comp (filter metam/render?) (map :duration)) - + af-traces) + +nil af-traces) ] ;; TODO: where should rounding happen? In metam/elapsed-time? - ;(js/console.log "start" start "end" end af-traces) - (js/console.log "tsubs" subs-time "subs" subs-time) {:timing/animation-frame-total total-time :timing/animation-frame-subs subs-time :timing/animation-frame-render render-time @@ -365,10 +371,12 @@ :timing/event-processing-time :<- [:epochs/current-match-state] (fn [match] - {:timing/event-total (get-in match [:timing :re-frame/event-time]) - ;;; TODO: calculate handler and effects timing separately - :timing/event-handler -1 - :timing/event-effects -1})) + (utils/spy + "eventtiming" + {:timing/event-total (get-in match [:timing :re-frame/event-time]) + ;;; TODO: calculate handler and effects timing separately + :timing/event-handler (get-in match [:timing :re-frame/event-handler-time]) + :timing/event-effects nil}))) (rf/reg-sub :timing/render-time diff --git a/src/day8/re_frame/trace/view/timing.cljs b/src/day8/re_frame/trace/view/timing.cljs index 4ef0350..28c93dc 100644 --- a/src/day8/re_frame/trace/view/timing.cljs +++ b/src/day8/re_frame/trace/view/timing.cljs @@ -45,7 +45,14 @@ :gap "3px" ;; TODO: detect <1 ms timing here, to distinguish between none at all, and rounding to 0. :children [[rc/label :class "bm-textbox-label" :label label] - [timing-tag (str (js/Math.round time) "ms")]]]) + [timing-tag (cond + (nil? time) "-" + (= time 0) (str "0ms") + (< time 0.1) (str "<0.1ms") + (< time 1) (str (.toFixed time 1) "ms") + (some? time) (str (js/Math.round time) "ms") + + )]]]) (defn render [] (let [timing-data-available? @(rf/subscribe [:timing/data-available?])