Provide more granular timing info

CHANGELOG.md

@@ -3,6 +3,10 @@ All notable changes to this project will be documented in this file. This change
 
 ## [0.1.20] - Unreleased
 
+### Upgrade notes
+
+To take advantage of the more granular timing info, you will need to upgrade to re-frame 0.10.5.
+
 ### Improved
 
 * Improve Timing panel to show more granular timing info.

src/day8/re_frame/trace/events.cljs

@@ -549,11 +549,16 @@
                                                                                  (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)))
+                                                     ;; TODO: optimise trace searching
+                                                     event-handler-trace (first (filter metam/event-handler? epoch-traces))
+                                                     dofx-trace          (first (filter metam/event-dofx? epoch-traces))
+                                                     event-trace         (first (filter metam/event-run? 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-handler-time (:duration event-handler-trace)}))
+                                                 {:re-frame/event-run-time      (metam/elapsed-time start-of-epoch finish-run)
+                                                  :re-frame/event-time         (:duration event-trace)
+                                                  :re-frame/event-handler-time (:duration event-handler-trace)
+                                                  :re-frame/event-dofx-time    (:duration dofx-trace)}))
                                              new-matches)
 
             new-matches                (map (fn [match sub-match t] {:match-info match

src/day8/re_frame/trace/metamorphic.cljc

@@ -73,8 +73,7 @@
   (let [start-of-epoch (:start ev1)
         end-of-epoch   (:end ev2)]
     (when (and (some? start-of-epoch) (some? end-of-epoch))
-      #?(:cljs (js/Math.round (- end-of-epoch start-of-epoch))
-         :clj  (Math/round ^double (- end-of-epoch start-of-epoch))))))
+      (- end-of-epoch start-of-epoch))))
 
 (defn run-queue? [event]
   (and (fsm-trigger? event)
@@ -181,6 +180,9 @@
 (defn event-handler? [trace]
   (= :event/handler (:op-type trace)))
 
+(defn event-dofx? [trace]
+  (= :event/do-fx (:op-type trace)))
+
 (defn start-of-epoch?
   "Detects the start of a re-frame epoch
 

src/day8/re_frame/trace/subs.cljs

@@ -358,9 +358,7 @@
           render-time (transduce (comp
                                    (filter metam/render?)
                                    (map :duration))
-                                 +nil af-traces)
-          ]
-      ;; TODO: where should rounding happen? In metam/elapsed-time?
+                                 +nil af-traces)]
       {:timing/animation-frame-total  total-time
        :timing/animation-frame-subs   subs-time
        :timing/animation-frame-render render-time
@@ -371,12 +369,20 @@
   :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 (get-in match [:timing :re-frame/event-handler-time])
-       :timing/event-effects nil})))
+    (let [{:re-frame/keys [event-time event-handler-time event-dofx-time event-run-time]} (get match :timing)
+          ;; The scope of tracing is:
+          ;; event-run-time
+          ;;   event-time
+          ;;     event-handler-time
+          ;;     event-dofx-time
+          ;;     <other stuff>
+          ;;   <other stuff>
+          remaining-interceptors (- event-time event-handler-time event-dofx-time)]
+      {:timing/event-total        event-run-time
+       :timing/event-handler      event-handler-time
+       :timing/event-effects      event-dofx-time
+       :timing/event-interceptors remaining-interceptors
+       :timing/event-misc         (- event-run-time event-time)})))
 
 (rf/reg-sub
   :timing/render-time

src/day8/re_frame/trace/view/timing.cljs

@@ -80,6 +80,10 @@
                     [timing-section "handler" (:timing/event-handler event-processing-time)]
                     [:span "+"]
                     [timing-section "effects" (:timing/event-effects event-processing-time)]
+                    [:span "+"]
+                    [timing-section "other int." (:timing/event-interceptors event-processing-time)]
+                    [:span "+"]
+                    [timing-section "misc" (:timing/event-misc event-processing-time)]
 
                     ]]
                   (doall