Calculate timing for :event/handler, improve fine precision timing

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

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
 

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]
+    (utils/spy
+      "eventtiming"
       {: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}))
+       :timing/event-handler (get-in match [:timing :re-frame/event-handler-time])
+       :timing/event-effects nil})))
 
 (rf/reg-sub
   :timing/render-time

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?])