Refactor elision utils

src/taoensso/timbre.cljx

@@ -106,6 +106,7 @@
 
   {:level :debug  ; e/o #{:trace :debug :info :warn :error :fatal :report}
 
+   ;; TODO Consider switching to `:ns-pattern` to match Tufte?
    ;; Control log filtering by namespaces/patterns. Useful for turning off
    ;; logging in noisy libraries, etc.:
    :ns-whitelist  [] #_["my-app.foo-ns"]
@@ -151,84 +152,154 @@
 (comment (set-level! :info) *config*)
 
 ;;;; Levels
+;; Note that for historical reasons we don't make a distinction
+;; between form "level"s and config "min-level"s.
 
-(def ordered-levels [:trace :debug :info :warn :error :fatal :report])
+(def ^:const -levels-vec [:trace :debug :info :warn :error :fatal :report])
-(def ^:private scored-levels (zipmap ordered-levels (next (range))))
+(def ^:const -levels-set (set    -levels-vec))
-(def ^:private valid-levels  (set ordered-levels))
+(def ^:const -levels-map (zipmap -levels-vec (next (range))))
-(def ^:private valid-level
-  (fn [level]
-    (or (valid-levels level)
-        (throw (ex-info (str "Invalid logging level: " level) {:level level})))))
 
-(comment (valid-level :info))
+(defn valid-level? [x] (if (-levels-set x) true false))
+(defn valid-level  [x]
+  (or (-levels-set x)
+      (throw (ex-info "Invalid Timbre logging level" {:given x}))))
 
-(defn level>= [x y] (>= ^long (scored-levels (valid-level x))
+(defn level>= [x y]
-                        ^long (scored-levels (valid-level y))))
+  (>= ^long (-levels-map (valid-level x))
+      ^long (-levels-map (valid-level y))))
 
-(comment (qb 10000 (level>= :info :debug)))
+(comment (qb 1e6 (level>= :info :debug))) ; 81.25
 
-#+clj
+;;;; Namespace filtering
-(def ^:private compile-time-level
-  ;; Will stack with runtime level
-  (have [:or nil? valid-level]
-    (when-let [level (keyword ; For back compatibility
-                      (or (enc/read-sys-val "TIMBRE_LEVEL")
-                          (enc/read-sys-val "TIMBRE_LOG_LEVEL")))]
-      (println (str "Compile-time (elision) Timbre level: " level))
-      level)))
 
-;;;; ns filter
+;; Code shared with Tufte
-
+(def compile-ns-filter "Returns (fn [?ns]) -> truthy."
-(def ^:private compile-ns-filters
+  (let [compile1
-  "(fn [whitelist blacklist]) -> (fn [ns]) -> ?unfiltered-ns"
+        (fn [x] ; ns-pattern
-  (let [->re-pattern
+          (cond
-        (fn [x]
+            (enc/re-pattern? x) (fn [ns-str] (re-find x ns-str))
-          (enc/cond!
-            (enc/re-pattern? x) x
             (string? x)
-            (let [s (-> (str "^" x "$")
+            (if (enc/str-contains? x "*")
+              (let [re
+                    (re-pattern
+                      (-> (str "^" x "$")
                           (str/replace "." "\\.")
-                        (str/replace "*" "(.*)"))]
+                          (str/replace "*" "(.*)")))]
-              (re-pattern s))))]
+                (fn [ns-str] (re-find re ns-str)))
+              (fn [ns-str] (= ns-str x)))
 
-    (enc/memoize_
+            :else (throw (ex-info "Unexpected ns-pattern type"
-      (fn [whitelist blacklist]
+                           {:given x :type (type x)}))))]
-        (let [whitelist* (mapv ->re-pattern whitelist)
-              blacklist* (mapv ->re-pattern blacklist)
 
-              white-filter
+    (fn self
+      ([ns-pattern] ; Useful for user-level matching
+       (let [x ns-pattern]
          (cond
-                ;; (nil? whitelist)  (fn [ns] false) ; Might be surprising
+           (map? x) (self (:whitelist x) (:blacklist x))
-                (empty?  whitelist*) (fn [ns] true)
+           (or (vector? x) (set? x)) (self x nil)
-                :else (fn [ns] (some #(re-find % ns) whitelist*)))
+           (= x "*") (fn [?ns] true)
+           :else
+           (let [match? (compile1 x)]
+             (fn [?ns] (if (match? (str ?ns)) true))))))
 
-              black-filter
+      ([whitelist blacklist]
+       (let [white
+             (when (seq whitelist)
+               (let [match-fns (mapv compile1 whitelist)
+                     [m1 & mn] match-fns]
+                 (if mn
+                   (fn [ns-str] (enc/rsome #(% ns-str) match-fns))
+                   (fn [ns-str] (m1 ns-str)))))
+
+             black
+             (when (seq blacklist)
+               (let [match-fns (mapv compile1 blacklist)
+                     [m1 & mn] match-fns]
+                 (if mn
+                   (fn [ns-str] (not (enc/rsome #(% ns-str) match-fns)))
+                   (fn [ns-str] (not (m1 ns-str))))))]
          (cond
-                (empty? blacklist*) (fn [ns] true)
+           (and white black)
-                :else (fn [ns] (not (some #(re-find % ns) blacklist*))))]
+           (fn [?ns]
+             (let [ns-str (str ?ns)]
+               (if (white ns-str)
+                 (if (black ns-str)
+                   true))))
 
-          (fn [ns] (when (and (white-filter ns) (black-filter ns)) ns)))))))
+           white (fn [?ns] (if (white (str ?ns)) true))
+           black (fn [?ns] (if (black (str ?ns)) true))
+           :else (fn [?ns] true) ; Common case
+           ))))))
+
+(def ^:private -compile-ns-filter (enc/memoize_ compile-ns-filter))
 
 (def ^:private ns-filter
-  "(fn [whitelist blacklist ns]) -> ?unfiltered-ns"
+  "Returns true iff given ns passes white/black lists."
   (enc/memoize_
     (fn [whitelist blacklist ?ns]
-      {:pre [(have? [:or nil? string?] ?ns)]}
+      ((-compile-ns-filter whitelist blacklist) ?ns))))
-      ((compile-ns-filters whitelist blacklist) (or ?ns "")))))
 
 (comment
-  (qb 10000 (ns-filter ["foo.*"] ["foo.baz"] "foo.bar"))
+  (qb 1e6 (ns-filter ["foo.*"] ["foo.baz"] "foo.bar")) ; 238.33
   (ns-filter nil nil "")
   (ns-filter nil nil nil))
 
+;;;; Combo filtering
+
+#+clj
+(def ^:private compile-time-level
+  (when-let [level (or (enc/read-sys-val "TIMBRE_LEVEL")
+                       (enc/read-sys-val "TIMBRE_LOG_LEVEL"))]
+    (println (str "Compile-time (elision) Timbre level: " level))
+    (let [;; Back compatibility
+          level (if (string? level) (keyword level) level)]
+      (valid-level level))))
+
 #+clj
 (def ^:private compile-time-ns-filter
-  ;; Will stack with runtime ns filters
+  (if-let [ns-pattern (enc/read-sys-val "TIMBRE_NS_PATTERN")]
+    (do
+      (println (str "Compile-time (elision) Timbre ns-pattern: " ns-pattern))
+      (-compile-ns-filter ns-pattern))
+
+    ;; Back compatibility
     (let [whitelist (have [:or nil? vector?] (enc/read-sys-val "TIMBRE_NS_WHITELIST"))
           blacklist (have [:or nil? vector?] (enc/read-sys-val "TIMBRE_NS_BLACKLIST"))]
       (when whitelist (println (str "Compile-time (elision) Timbre ns whitelist: " whitelist)))
       (when blacklist (println (str "Compile-time (elision) Timbre ns blacklist: " blacklist)))
-    (fn [ns] (ns-filter whitelist blacklist ns))))
+      (-compile-ns-filter whitelist blacklist))))
+
+#+clj ; Called only at macro-expansiom time
+(defn -elide? [level-form ns-str-form]
+  (not
+    (and
+      (or ; Level okay
+        (nil? compile-time-level)
+        (not (valid-level? level-form)) ; Not a compile-time level const
+        (level>= level-form compile-time-level))
+
+      (or ; Namespace okay
+        (not (string? ns-str-form)) ; Not a compile-time ns-str const
+        (compile-time-ns-filter ns-str-form)))))
+
+(defn may-log?
+  "Runtime check: would Timbre currently log at the given logging level?
+    * `?ns-str` arg required to support ns filtering
+    * `config`  arg required to support non-global config"
+  ([level                ] (may-log? level nil     nil))
+  ([level ?ns-str        ] (may-log? level ?ns-str nil))
+  ([level ?ns-str ?config]
+   (let [config    (or  ?config *config*)
+         min-level (get  config :level :report)]
+     (and
+       (level>= level min-level)
+       (ns-filter
+         (get config :ns-whitelist)
+         (get config :ns-blacklist)
+         ?ns-str)
+       true))))
+
+(comment (qb 1e5 (may-log? :info))) ; 34.13
 
 ;;;; Utils
 
@@ -266,45 +337,11 @@
 
 (def ^:dynamic *context*
   "General-purpose dynamic logging context. Context will be included in
-  appender data map at logging time." nil)
+  appender data map at logging time."
+  nil)
 
-(defmacro with-context [context & body] `(binding [*context* ~context] ~@body))
+(defmacro with-context [context & body]
-
+  `(binding [*context* ~context] ~@body))
-(defn log?
-  "Runtime check: would Timbre currently log at the given logging level?
-    * `?ns-str` arg required to support ns filtering
-    * `config`  arg required to support non-global config"
-  ([level               ] (log? level nil     nil))
-  ([level ?ns-str       ] (log? level ?ns-str nil))
-  ([level ?ns-str config]
-   (let [config       (or  config *config*)
-         active-level (get config :level :report)]
-     (and
-       (level>= level active-level)
-       (ns-filter (get config :ns-whitelist) (get config :ns-blacklist) ?ns-str)
-       true))))
-
-(comment
-  (set-level! :debug)
-  (log? :trace)
-  (with-level :trace (log? :trace))
-  (qb 10000
-    (log? :trace)
-    (log? :trace "foo")
-    (tracef "foo")
-    (when false "foo"))
-  ;; [1.38 1.42 2.08 0.26]
-
-  ;;; Full benchmarks
-  (defmacro with-sole-appender [appender & body]
-    `(with-config (assoc *config* :appenders {:appender ~appender}) ~@body))
-
-  (with-sole-appender {:enabled? true :fn (fn [data] nil)}
-    (qb 10000 (info "foo"))) ; ~88ms ; Time to delays ready
-
-  (with-sole-appender {:enabled? true :fn (fn [data] ((:output-fn data) data))}
-    (qb 10000 (info "foo"))) ; ~218ms ; Time to output ready
-  )
 
 (defn-   next-vargs [v] (if (> (count v) 1) (subvec v 1) []))
 (defn- vargs->margs
@@ -369,7 +406,7 @@
   ([config level ?ns-str ?file ?line msg-type ?err vargs_
     ?base-data callsite-id]
 
-  (when (log? level ?ns-str config) ; Runtime check
+  (when (may-log? level ?ns-str config)
     (let [instant (enc/now-dt)
           context *context*
           vargs   @vargs_
@@ -504,21 +541,7 @@
   (-log! *config* :info nil nil nil :p :auto
     (delay [(do (println "hi") :x) :y]) nil "callsite-id"))
 
-(defmacro -with-elision
+#+clj (defn- fline [and-form] (:line (meta and-form)))
-  "Implementation detail.
-  Executes body iff given level and ns pass compile-time elision."
-  [level-form ns-str-form & body]
-  (when (or (nil? compile-time-level)
-            (not (valid-levels level-form)) ; Not a compile-time level const
-            (level>= level-form compile-time-level))
-
-    (when (or (not (string? ns-str-form)) ; Not a compile-time ns-str const
-              (compile-time-ns-filter ns-str-form))
-      `(do ~@body))))
-
-(comment (-with-elision :info "ns" (println "foo")))
-
-(defn- fline [and-form] (:line (meta and-form)))
 
 (defmacro log! ; Public wrapper around `-log!`
   "Core low-level log macro. Useful for tooling, etc.
@@ -532,9 +555,8 @@
   [level msg-type args & [opts]]
   (have sequential? args) ; To allow -> (delay [~@args])
   (let [{:keys [?ns-str] :or {?ns-str (str *ns*)}} opts]
-    (-with-elision
+    ;; level, ns may/not be compile-time consts:
-      level   ; level-form  (may/not be a compile-time kw const)
+    (when-not (-elide? level ?ns-str)
-      ?ns-str ; ns-str-form (may/not be a compile-time str const)
       (let [{:keys [config ?err ?file ?line ?base-data]
              :or   {config 'taoensso.timbre/*config*
                     ?err   :auto ; => Extract as err-type v0
@@ -559,6 +581,29 @@
   (macroexpand '(log! :info :p ["foo"]))
   (macroexpand '(log! :info :p ["foo"] {:?line 42})))
 
+;;;; Benchmarking
+
+(comment
+  (set-level! :debug)
+  (may-log? :trace)
+  (with-level :trace (log? :trace))
+  (qb 10000
+    (may-log? :trace)
+    (may-log? :trace "foo")
+    (tracef "foo")
+    (when false "foo"))
+  ;; [1.38 1.42 2.08 0.26]
+
+  (defmacro with-sole-appender [appender & body]
+    `(with-config (assoc *config* :appenders {:appender ~appender}) ~@body))
+
+  (with-sole-appender {:enabled? true :fn (fn [data] nil)}
+    (qb 10000 (info "foo"))) ; ~74.58 ; Time to delays ready
+
+  (with-sole-appender {:enabled? true :fn (fn [data] (force (:output_ data)))}
+    (qb 10000 (info "foo"))) ; ~136.68 ; Time to output ready
+  )
+
 ;;;; Main public API-level stuff
 ;; TODO Have a bunch of cruft here trying to work around CLJ-865 to some extent
 
@@ -737,7 +782,9 @@
 ;;;; Deprecated
 
 #+cljs (def console-?appender core-appenders/console-appender)
-(defn logging-enabled? [level compile-time-ns] (log? level (str compile-time-ns)))
+(def ordered-levels -levels-vec)
+(def log? may-log?)
+(defn logging-enabled? [level compile-time-ns] (may-log? level (str compile-time-ns)))
 (defn str-println      [& xs] (str-join xs))
 (defmacro with-log-level      [level  & body] `(with-level  ~level  ~@body))
 (defmacro with-logging-config [config & body] `(with-config ~config ~@body))

src/taoensso/timbre/profiling.clj

@@ -238,7 +238,7 @@
   (let [id (qualified-kw *ns* id)]
     (if elide-profiling?
       `(do ~@body)
-      `(if (timbre/log? ~level ~(str *ns*)) ; Runtime check
+      `(if (timbre/may-log? ~level ~(str *ns*)) ; Runtime check
          (profiled (do ~@body) [stats# result#]
            (let [stats-str# (-format-stats stats#)]
              (timbre/log! ~level :p

src/taoensso/timbre/tools/logging.clj

@@ -15,7 +15,7 @@
 
   (enabled? [_ level]
     ;; No support for per-call config
-    (timbre/log? level logger-ns-str timbre-config))
+    (timbre/may-log? level logger-ns-str timbre-config))
 
   (write! [_ level throwable message]
     (timbre/log! level :p