add some additional logging to make tracing resolve easier

src/main/shadow/build.clj

@@ -282,30 +282,39 @@
     (assoc state :build-macros build-macros)
     ))
 
+(defn compile-start [state]
+  (assoc state ::build-info {:compile-start (System/currentTimeMillis)}))
+
+(defn compile-complete [state]
+  (assoc-in state [::build-info :compile-complete] (System/currentTimeMillis)))
+
 (defn compile
   [{::keys [mode] :as state}]
   {:pre [(build-api/build-state? state)]
    :post [(build-api/build-state? %)]}
   (if-not (modules/configured? state)
     ;; flat build, no modules
     (-> state
-        (assoc ::build-info {})
+        (compile-start)
         (process-stage :resolve false)
         (extract-build-macros)
         (process-stage :compile-prepare true)
         (build-api/compile-sources)
         (update-build-info-after-compile)
-        (process-stage :compile-finish true))
+        (process-stage :compile-finish true)
+        (compile-complete))
     ;; :modules based build
     (-> state
-        (assoc ::build-info {})
+        (compile-start)
         (modules/analyze)
         (extract-build-macros)
         (process-stage :compile-prepare true)
         (update-build-info-from-modules)
         (build-api/compile-sources)
         (update-build-info-after-compile)
-        (process-stage :compile-finish true))))
+        (process-stage :compile-finish true)
+        (compile-complete)
+        )))
 
 (defn optimize
   [{::keys [mode skip-optimize] :as state}]
@@ -331,7 +340,9 @@
   [state]
   {:pre [(build-api/build-state? state)]
    :post [(build-api/build-state? %)]}
-  (process-stage state :flush true))
+  (-> state
+      (process-stage :flush true)
+      (assoc-in [::build-info :flush-complete] (System/currentTimeMillis))))
 
 
 (defn log [state log-event]

src/main/shadow/build/modules.clj

@@ -7,7 +7,8 @@
             [shadow.build.resource :as rc]
             [shadow.build.data :as data]
             [clojure.java.io :as io]
-            [shadow.build.classpath :as cp]))
+            [shadow.build.classpath :as cp]
+            [shadow.build.log :as cljs-log]))
 
 (defn topo-sort-modules*
   [{:keys [modules deps visited] :as state} module-id]
@@ -193,6 +194,10 @@
           (update-in [::modules mod-id :sources] conj resource-id)
           ))))
 
+(defmethod cljs-log/event->str ::analyze-module
+  [{:keys [module-id entries] :as event}]
+  (format "Analyzing Module: %s" module-id))
+
 (defn analyze-module
   "resolve all deps for a given module, based on specified :entries
    will update state for each module with :sources, a list of sources needed to compile this module
@@ -202,23 +207,26 @@
          (keyword? module-id)]}
 
   (let [{:keys [entries append-js prepend-js] :as module}
-        (get-in state [::modules module-id])
-
-        [sources state]
-        (res/resolve-entries state entries)]
-
-    (-> state
-        (assoc-in [::modules module-id :sources] sources)
-        (cond->
-          (seq prepend-js)
-          (add-module-pseudo-rc ::prepend module-id prepend-js)
-
-          ;; bootstrap needs to append some load info
-          ;; this ensures that the rc is append correctly
-          ;; it will be modified by shadow.build.bootstrap
-          (or (seq append-js) (:force-append module))
-          (add-module-pseudo-rc ::append module-id (or append-js ""))
-          ))))
+        (get-in state [::modules module-id])]
+
+    (util/with-logged-time [state {:type ::analyze-module
+                                   :entries entries
+                                   :module-id module-id}]
+      (let [[sources state]
+            (res/resolve-entries state entries)]
+
+        (-> state
+            (assoc-in [::modules module-id :sources] sources)
+            (cond->
+              (seq prepend-js)
+              (add-module-pseudo-rc ::prepend module-id prepend-js)
+
+              ;; bootstrap needs to append some load info
+              ;; this ensures that the rc is append correctly
+              ;; it will be modified by shadow.build.bootstrap
+              (or (seq append-js) (:force-append module))
+              (add-module-pseudo-rc ::append module-id (or append-js ""))
+              ))))))
 
 (defn analyze-modules [{::keys [module-order] :as state}]
   (reduce analyze-module state module-order))

src/main/shadow/build/npm.clj

@@ -770,6 +770,7 @@
 (defn start [{:keys [node-modules-dir] :as config}]
   (let [index-ref
         (atom {:files {}
+               :require-cache {}
                :packages {}
                :package-json-cache {}})
 

src/main/shadow/cljs/devtools/server/util.clj

@@ -86,9 +86,9 @@
                (count sources)
                (count compiled)
                (count warnings)
-               (-> (- (or (get-in build-info [:timings :flush :exit])
-                          (get-in build-info [:timings :compile-finish :exit]))
-                      (get-in build-info [:timings :compile-prepare :enter]))
+               (-> (- (or (get build-info :flush-complete)
+                          (get build-info :compile-complete))
+                      (get build-info :compile-start))
                    (double)
                    (/ 1000))))
 

src/repl/shadow/cljs/resolve_test.clj

@@ -9,7 +9,8 @@
             [shadow.build.resolve :as res]
             [shadow.build.data :as data]
             [shadow.build.macros :as macros]
-            [shadow.build.compiler :as impl]))
+            [shadow.build.compiler :as impl]
+            [shadow.build.log :as build-log]))
 
 
 (deftest test-resolve
@@ -219,3 +220,25 @@
       #_(-> resolved-state :npm :index-ref deref :package-json-cache (pprint)))
     (catch Exception e
       (prn (ex-data e)))))
+
+
+(deftest test-resolve-perf
+  (try
+
+    (let [build-state
+          (-> (test-build)
+              (api/with-js-options
+                {:js-provider :shadow}))
+
+          [resolved resolved-state]
+          (time
+            (api/resolve-entries build-state ["semantic-ui-react"]))
+
+          [resolve2 resolved2]
+          (time
+            (api/resolve-entries resolved-state ["semantic-ui-react"]))
+          ]
+      )
+    (catch Exception e
+      (prn (ex-data e))))
+  )