Improve Timing panel granularity

CHANGELOG.md

@@ -3,7 +3,17 @@ 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 in this version, you will need to upgrade to re-frame 0.10.5.
+
+### Improved
+
+* Improve Timing panel to show more granular timing info.
+
+### Fixed
+
+* View and subscription runtime now only measures self time instead of elapsed time, i.e. we subtract the time of any child subcriptions/renders.
 
 ## [0.1.19] - 2018-02-09
 
@@ -13,14 +23,14 @@ All notable changes to this project will be documented in this file. This change
   * Subscriptions that exist but weren't run, now show up in the subscription panel.
   * Subscription creations and disposals that happen during figwheel reloads or otherwise outside of the re-frame event domino cycle are now correctly handled. If any of these happen, they show up in the new section Inter-Epoch Subscriptions.
   * All of the actions that happen to a subscription within an epoch are now shown. This lets you spot unusual behaviour like a subscription being created but not-run, or a subscription running multiple times.
-  * Present better explanation messages when viewing the diff section for a sub where the value is unchanged, not run yet, or only run once. 
+  * Present better explanation messages when viewing the diff section for a sub where the value is unchanged, not run yet, or only run once.
 
 ### Fixed
 
 * Garden source dependencies are now working if you don't have your own dependency on Garden.
 * New app-db path inspectors default to `"""` instead of `"[]"` so you can see the help text.
 
-## [0.1.18] - 2018-01-31 
+## [0.1.18] - 2018-01-31
 
 ### Fixed
 

README.md

@@ -98,7 +98,7 @@ If you are using leiningen, modify `project.clj` in the following ways. When puz
 
 [![Clojars Project](https://img.shields.io/clojars/v/day8.re-frame/trace.svg)](https://clojars.org/day8.re-frame/trace)
 
-- Update your re-frame dependency to at least `0.10.4` - `[re-frame "0.10.4"]`.
+- Update your re-frame dependency to at least `0.10.5` - `[re-frame "0.10.5"]`.
 
 - Add re-frame-trace as a dev dependency by placing `[day8.re-frame/trace "VERSION"]` within `:profiles :dev :dependencies`. For example:
 

src/day8/re_frame/trace/events.cljs

@@ -25,8 +25,8 @@
                            (get-in context [:effects :db])
                            (get-in context [:coeffects :db]))
                    event (get-in context [:coeffects :event])]
-               (f db event)    ;; call f for side effects
-               context))))     ;; context is unchanged
+               (f db event)                                 ;; call f for side effects
+               context))))                                  ;; context is unchanged
 
 (defn log-trace? [trace]
   (let [render-operation? (or (= (:op-type trace) :render)
@@ -544,14 +544,21 @@
             new-sub-state              (last subscription-match-state)
             timing                     (mapv (fn [match]
                                                ;; TODO: this isn't quite correct, shouldn't be using filtered-traces here
-                                               (let [epoch-traces   (into []
-                                                                          (comp
-                                                                            (utils/id-between-xf (:id (first match)) (:id (last match))))
-                                                                          filtered-traces)
-                                                     start-of-epoch (nth epoch-traces 0)
-                                                     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)}))
+                                               (let [epoch-traces        (into []
+                                                                               (comp
+                                                                                 (utils/id-between-xf (:id (first match)) (:id (last match))))
+                                                                               filtered-traces)
+                                                     start-of-epoch      (nth epoch-traces 0)
+                                                     ;; 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-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)
@@ -131,6 +130,7 @@
 
 (defn subscription? [trace]
   (and (= "sub" (namespace (:op-type trace)))
+       ;; TODO: should we remove cached checks?
        (not (get-in trace [:tags :cached?]))))
 
 (defn subscription-created? [trace]
@@ -167,14 +167,22 @@
        (= 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])))
 
 (defn event-run? [event]
   (= :event (:op-type event)))
 
+(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

@@ -332,19 +332,60 @@
   (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]
-  (fn [frame-traces [_ frame-number]]
-    (let [frames (partition 2 frame-traces)
-          [start end] (first (drop (dec frame-number) frames))]
-      (metam/elapsed-time start end))))
+  :<- [:traces/current-event-traces]
+  (fn [[af-start-end epoch-traces] [_ frame-number]]
+    (let [frame-pairs (partition 2 af-start-end)
+          [start end] (nth frame-pairs (dec frame-number))
+          af-traces   (into [] (metam/id-between-xf (:id start) (:id end)) epoch-traces)
+          total-time  (metam/elapsed-time start end)
+          ;; TODO: these times double count renders/subs that happened as a child of another
+          ;; need to fix either here, at ingestion point, or most preferably in re-frame at tracing point.
+          subs-time   (transduce (comp
+                                   (filter metam/subscription?)
+                                   (map :duration))
+                                 +nil af-traces)
+          render-time (transduce (comp
+                                   (filter metam/render?)
+                                   (map :duration))
+                                 +nil af-traces)]
+      {:timing/animation-frame-total  total-time
+       :timing/animation-frame-subs   subs-time
+       :timing/animation-frame-render render-time
+       ;; TODO: handle rounding weirdness here, make sure it is never below 0.
+       :timing/animation-frame-misc   (- total-time subs-time render-time)})))
 
 (rf/reg-sub
   :timing/event-processing-time
   :<- [:epochs/current-match-state]
   (fn [match]
-    (get-in match [:timing :re-frame/event-time])))
+    (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
+       ;; TODO: look at splitting out interceptors from misc, there was a suspiciously high amount of time
+       ;; in misc on some events, so that needs to be investigated.
+       ; :timing/event-misc (- event-run-time event-time)
+       :timing/event-misc         (- event-run-time event-handler-time event-dofx-time)})))
 
 (rf/reg-sub
   :timing/render-time

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

@@ -9,9 +9,7 @@
 (def timing-styles
   [:#--re-frame-trace--
    [:.timing-details
-    {:background-color common/white-background-color
-     :margin-top       common/gs-31s
-     :padding          common/gs-19}]
+    {:margin-top common/gs-31s}]
    [:.timing-details--line
     {:margin "1em 0"}]
 
@@ -26,12 +24,16 @@
     {:background-color common/disabled-background-color
      :border           (str "1px solid " common/border-line-color)
      :font-weight      "normal"
-     :font-size        "14px"}]
+     :font-size        "14px"
+     :width            "63px"}]
 
+   [".timing-elapsed-panel"
+    {:padding "12px"
+     :margin  common/gs-7s}]
    [".timing-part-panel"
     (merge (common/panel-style "3px")
            {:padding "12px"
-            :margin common/gs-7s})]
+            :margin  common/gs-7s})]
    ])
 
 (defn timing-tag [label]
@@ -42,53 +44,76 @@
   [rc/v-box
    :align :center
    :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 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?])]
+  (let [timing-data-available? @(rf/subscribe [:timing/data-available?])
+        event-processing-time  @(rf/subscribe [:timing/event-processing-time])]
     (if timing-data-available?
       [rc/v-box
        :class "timing-details"
-       :children [
+       :children [[rc/h-box
+                   :class "timing-elapsed-panel"
+                   :align :end
+                   :children [[timing-section "elapsed" @(rf/subscribe [:timing/total-epoch-time])]
+                              [rc/hyperlink-href
+                               :label "guide me to greatness"
+                               :style {:margin-left common/gs-19s}
+                               :attr {:rel "noopener noreferrer"}
+                               :target "_blank"
+                               :href "https://github.com/Day8/re-frame-trace/blob/master/docs/HyperlinkedInformation/UnderstandingTiming.md"]]]
                   [rc/h-box
                    :gap common/gs-12s
                    :class "timing-part-panel"
+                   :align :center
                    :children
-                   [[timing-section "total" @(rf/subscribe [:timing/total-epoch-time])]
-                    [timing-section "event" @(rf/subscribe [:timing/event-processing-time])]
+                   [[rc/v-box
+                     :align :center
+                     :width common/gs-81s
+                     :children [[:span "event"] [:span "processing"]]]
+                    [timing-section "total" (:timing/event-total event-processing-time)]
+                    [:span "="]
+                    [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
                     (for [frame (range 1 (inc @(rf/subscribe [:timing/animation-frame-count])))
-                          :let [frame-time (rf/subscribe [:timing/animation-frame-time frame])]]
+                          :let [frame-time @(rf/subscribe [:timing/animation-frame-time frame])]]
                       (list
                         ;^{:key (str "af-line" frame)}
                         ;[rc/line :class "timing-details--line"]
                         ^{:key (str "af" frame)}
                         [rc/h-box
                          :align :center
                          :class "timing-part-panel"
-                         :gap "25px"
+                         :gap common/gs-12s
                          :children
-                         [[rc/label :label (str "Animation frame #" frame)]
-                          [timing-section "total" @frame-time]
-                          #_[timing-section "subs" 2]
-                          #_[timing-section "views" 3]]])))
-
-                  [rc/line :class "timing-details--line"]
-
-                  [rc/v-box
-                   :children
-                   [[rc/p "Be careful. There are two problems with these numbers:"]
-                    [:ol
-                     [:li "Accurately timing anything in the browser is a nightmare. One moment a given function takes 1ms and the next it takes 10ms, and you'll never know why. So bouncy."]
-                     [:li "You're currently running the dev build, not the production build. So don't freak out too much. Yet."]]
-                    [rc/hyperlink-href
-                     :label "Timing documentation"
-                     :style {:margin-left common/gs-7s}
-                     :attr {:rel "noopener noreferrer"}
-                     :target "_blank"
-                     :href "https://github.com/Day8/re-frame-trace/blob/master/docs/HyperlinkedInformation/UnderstandingTiming.md"]]]]]
+                         [[rc/v-box
+                           :align :center
+                           :width common/gs-81s
+                           :children [[:span "animation"] [:span "frame"] [:span "#" frame]]]
+                          [timing-section "total" (:timing/animation-frame-total frame-time)]
+                          [:span "="]
+                          [timing-section "subs" (:timing/animation-frame-subs frame-time)]
+                          [:span "+"]
+                          [timing-section "views" (:timing/animation-frame-render frame-time)]
+                          [:span "+"]
+                          [timing-section "react, etc" (:timing/animation-frame-misc frame-time)]]])))]]
       [rc/v-box
        :class "timing-details"
        :children [[:h1 "No timing data available currently."]]])))