Small Clojure core.logic performance gotcha

core-logic-perf-gotcha.md

Seems like when using a logic db in core.logic most of the CPU cicles are spent on manipulating the thead bindings the *logic-dbs* dynamic var. However, it is only used as a wrapper when calling the underlying -run macro. Invoking it directly speeds things up significantly

Let's set up some dummy data:

(require
 '[clojure.core.logic.pldb :as pldb]
 '[clojure.core.logic :as logic])

(pldb/db-rel thingy ^:index id ^:index source a b)

(def facts
  (for [id [1 2] src [1 2] a [1 2] b [1 2]]
    {:id id :source src :a a :b b}))

(def facts*
  (map
   (fn [{:keys [id source a b]}]
     [thingy id source a b])
   facts))

(def facts0 (apply pldb/db facts*))

set up a macro to invoke -run comfortably:

(defmacro run-db*
  "Executes goals until results are exhausted. Uses a specified logic database."
  [db bindings & goals]
  `(logic/-run {:occurs-check true :n false :db [~db]} ~bindings ~@goals))

This macro is identical to core.logic/run-db* but doesn't flatten a wrapped db, which also incurs a significant overhead. (refactor (flatten [~db]) to plain db).

and compare:

(require 'criterium.core)
(require '[clj-async-profiler.core :as prof])

(criterium.core/quick-bench
 (pldb/with-db facts0
   (logic/run* [q]
     (thingy q 2 2 2)
     (logic/== q 1))))

;;; Evaluation count : 694482 in 6 samples of 115747 calls.
;;;              Execution time mean : 861.329340 ns
;;;     Execution time std-deviation : 8.897168 ns
;;;    Execution time lower quantile : 851.002903 ns ( 2.5%)
;;;    Execution time upper quantile : 874.305837 ns (97.5%)
;;;                    Overhead used : 2.303484 ns

(criterium.core/quick-bench
 (run-db*
  facts0 [q]
  (thingy q 2 2 2)
  (logic/== q 1)))

;;; Evaluation count : 17076210 in 6 samples of 2846035 calls.
;;;              Execution time mean : 34.750248 ns
;;;     Execution time std-deviation : 1.749865 ns
;;;    Execution time lower quantile : 32.822843 ns ( 2.5%)
;;;    Execution time upper quantile : 36.758151 ns (97.5%)
;;;                    Overhead used : 2.303484 ns

and voila, about 25x faster.

Run some profiling to see what's going on inside:

(prof/profile
 (dotimes [_ 1e8]
   (pldb/with-db facts0
     (logic/run* [q]
       (thingy q 2 2 2)
       (logic/== q 1)))))

(prof/profile
 (dotimes [_ 1e8]
   (run-db*
    facts0 [q]
    (thingy q 2 2 2)
    (logic/== q 1))))