debug latency

deps/db-sync/src/logseq/db_sync/logging.cljs

@@ -0,0 +1,9 @@
+(ns logseq.db-sync.logging
+  (:require [lambdaisland.glogi :as glogi]
+            [lambdaisland.glogi.console :as glogi-console]))
+
+(defn install!
+  "Installs console logging and sets the root logger level to `:info`."
+  []
+  (glogi-console/install!)
+  (glogi/set-level :glogi/root :info))

deps/db-sync/src/logseq/db_sync/node/server.cljs

@@ -3,8 +3,8 @@
             ["path" :as node-path]
             ["ws" :as ws]
             [lambdaisland.glogi :as log]
-            [lambdaisland.glogi.console :as glogi-console]
             [logseq.db-sync.index :as index]
+            [logseq.db-sync.logging :as logging]
             [logseq.db-sync.node.assets :as assets]
             [logseq.db-sync.node.config :as config]
             [logseq.db-sync.node.dispatch :as dispatch]
@@ -18,7 +18,7 @@
             [logseq.db-sync.worker.presence :as presence]
             [promesa.core :as p]))
 
-(glogi-console/install!)
+(logging/install!)
 
 (defn- make-env [cfg index-db assets-bucket]
   (doto (js-obj)

deps/db-sync/src/logseq/db_sync/worker.cljs

@@ -1,8 +1,8 @@
 (ns logseq.db-sync.worker
   (:require ["cloudflare:workers" :refer [DurableObject]]
             [lambdaisland.glogi :as log]
-            [lambdaisland.glogi.console :as glogi-console]
             [logseq.db-sync.common :as common]
+            [logseq.db-sync.logging :as logging]
             [logseq.db-sync.worker.dispatch :as dispatch]
             [logseq.db-sync.worker.handler.sync :as sync-handler]
             [logseq.db-sync.worker.handler.ws :as ws-handler]
@@ -10,7 +10,7 @@
             [logseq.db-sync.worker.ws :as ws]
             [shadow.cljs.modern :refer (defclass)]))
 
-(glogi-console/install!)
+(logging/install!)
 
 (def worker
   #js {:fetch (fn [request env _ctx]

deps/db-sync/src/logseq/db_sync/worker/handler/index.cljs

@@ -5,6 +5,7 @@
             [logseq.db-sync.worker.auth :as auth]
             [logseq.db-sync.worker.http :as http]
             [logseq.db-sync.worker.routes.index :as routes]
+            [logseq.db-sync.worker.timing :as timing]
             [promesa.core :as p]))
 
 (defn- index-db [^js self]
@@ -285,7 +286,8 @@
         env (.-env self)
         url (js/URL. (.-url request))
         path (.-pathname url)
-        method (.-method request)]
+        method (.-method request)
+        start-ms (common/now-ms)]
     (try
       (cond
         (contains? #{"OPTIONS" "HEAD"} method)
@@ -296,24 +298,41 @@
 
         :else
         (p/let [_ (index/<index-init! db)
+                init-ms (common/now-ms)
                 claims (auth/auth-claims request env)
+                auth-ms (common/now-ms)
                 _ (when claims
-                    (index/<user-upsert! db claims))]
-          (let [route (routes/match-route method path)]
-            (cond
-              (nil? claims)
-              (http/unauthorized)
-
-              route
-              (handle {:db db
-                       :env env
-                       :request request
-                       :url url
-                       :claims claims
-                       :route route})
-
-              :else
-              (http/not-found)))))
+                    (index/<user-upsert! db claims))
+                upsert-ms (common/now-ms)
+                route (routes/match-route method path)
+                response (cond
+                           (nil? claims)
+                           (http/unauthorized)
+
+                           route
+                           (handle {:db db
+                                    :env env
+                                    :request request
+                                    :url url
+                                    :claims claims
+                                    :route route})
+
+                           :else
+                           (http/not-found))
+                handler-end-ms (common/now-ms)
+                end-ms (common/now-ms)]
+          (when (and (= "GET" method) (= "/graphs" path))
+            (prn :db-sync/index-request-timing
+                 (merge {:method method
+                         :path path
+                         :handler (some-> route :handler)}
+                        (timing/summary start-ms
+                                        [[:index-init init-ms]
+                                         [:auth auth-ms]
+                                         [:upsert upsert-ms]
+                                         [:handler handler-end-ms]]
+                                        end-ms))))
+          response))
       (catch :default error
         (log/error :db-sync/index-error error)
         (http/error-response "server error" 500)))))

deps/db-sync/src/logseq/db_sync/worker/timing.cljs

@@ -0,0 +1,20 @@
+(ns logseq.db-sync.worker.timing)
+
+(defn summary
+  "Returns duration summary from `start-ms` to `end-ms` with ordered `steps`.
+
+  `steps` is a vector of `[label ms]` pairs where each `ms` is an absolute
+  timestamp in milliseconds."
+  [start-ms steps end-ms]
+  (let [steps (or steps [])
+        result (reduce (fn [{:keys [prev entries]} [label ms]]
+                         {:prev ms
+                          :entries (conj entries {:label label
+                                                  :ms (- ms prev)})})
+                       {:prev start-ms :entries []}
+                       steps)
+        last-ms (:prev result)
+        tail-ms (- end-ms last-ms)]
+    {:total-ms (- end-ms start-ms)
+     :steps (:entries result)
+     :tail-ms tail-ms}))