Add XTDB_QUERY_DEBUG env variable to log query details

Author: dekkers

README.adoc

@@ -57,6 +57,10 @@ container it will automatically migrate that node to be the first node of the
 multinode container with the name specified by XTDB_MIGRATION_NODE_NAME. If the
 environment variable isn't specified it will default to "_dev".
 
+=== XTDB_QUERY_DEBUG
+
+Setting this variable will log the duration of every query.
+
 === JAVA_TOOL_OPTIONS
 
 This are the options for the JVM. This by default set to `-Xms128M -Xmx512M

src/xtdb_http_multinode/core.clj

@@ -568,6 +568,8 @@
     (when (:help options)
       (println summary)
       (System/exit 0))
+    (when (System/getenv "XTDB_QUERY_DEBUG")
+      (.setLevel (org.slf4j.LoggerFactory/getLogger "xtdb-http-multinode.query") (ch.qos.logback.classic.Level/valueOf "debug")))
     (let [port (:port options)
           host (:host options)
           server (j/run-jetty (rr/ring-handler (->xtdb-router {:http-options {}})

src/xtdb_http_multinode/query.clj

@@ -199,17 +199,20 @@
       (let [{query-params :query body-params :body} (get-in req [:parameters])
             {:keys [valid-time tx-time tx-id query-edn in-args-edn in-args-json]} query-params
             query (or query-edn (get body-params :query))
-            in-args (or in-args-edn in-args-json (get body-params :in-args))]
-        (-> (if (nil? query)
-              (assoc options :no-query? true)
-              (run-query (transform-req query req)
-                         in-args
-                         (assoc options
-                                :valid-time valid-time
-                                :tx-time tx-time
-                                :tx-id tx-id
-                                :xtdb-node (get req :xtdb-node))))
-            (transform-query-resp req)))
+            in-args (or in-args-edn in-args-json (get body-params :in-args))
+            start-time (System/currentTimeMillis)
+            result (-> (if (nil? query)
+                         (assoc options :no-query? true)
+                         (run-query (transform-req query req)
+                                    in-args
+                                    (assoc options
+                                           :valid-time valid-time
+                                           :tx-time tx-time
+                                           :tx-id tx-id
+                                           :xtdb-node (get req :xtdb-node))))
+                       (transform-query-resp req))]
+        (log/debug "duration:" (- (System/currentTimeMillis) start-time) "ms query:" query)
+        result)
 
       (catch java.lang.AssertionError e
         (log/debug e)