Capture scope only on exception

[yuhan0]

I've noticed that "spying" on an expression incurs a significant overhead when used in tight inner loops that undergo many iterations.

Most of the time I want to capture the local scope and be able to recreate it later, only when something exceptional happens. Constantly overwriting the same code site and logging all values is too much overhead.

Here is a simple example:

(reduce (fn [acc x]
          (sc/spy  (+ acc (float (/ 1 x)))))
  0 (range -10000 10000))

This throws a DivideByZero exception 10,000 iterations into the reduce, which exceutes in 3.2ms without being wrapped by spy.

However when the sc/spy macro is used, my REPL output is filled with thousands of logging messages like

  At Execution Point 122810 of Code Site -15, saved scope with locals [start__6136__auto__ acc x]
SPY [122810 -15] /Users/yuhan/scratch/repo.clj:74 
(+ acc (float (/ 1 x)))
=>
-6.189866401342442
SPY [122811 -15] /Users/yuhan/scratch/repo.clj:74 
  At Execution Point 122811 of Code Site -15, saved scope with locals [start__6136__auto__ acc x]
SPY [122811 -15] /Users/yuhan/scratch/repo.clj:74 
(+ acc (float (/ 1 x)))
=>
-6.2398664020875
SPY [122812 -15] /Users/yuhan/scratch/repo.clj:74 
  At Execution Point 122812 of Code Site -15, saved scope with locals [start__6136__auto__ acc x]
SPY [122812 -15] /Users/yuhan/scratch/repo.clj:74 
(+ acc (float (/ 1 x)))
=>
-6.292497981427005
SPY [122813 -15] /Users/yuhan/scratch/repo.clj:74 
  At Execution Point 122813 of Code Site -15, saved scope with locals [start__6136__auto__ acc x]
SPY [122813 -15] /Users/yuhan/scratch/repo.clj:74 
(+ acc (float (/ 1 x)))
=>
-6.348053537396481
...

and execution takes ~4900ms, 3 orders of magnitude slower than the original. (Strangely, spyqt performs even worse, taking ~5400ms to throw the error.)

Of course this becomes unacceptably slow on real examples with many more locals and complicated logic. It would be nice if there was a way to only store and log locals when an exception is thrown, or turn off logging output entirely (I suspect that's where most of the overhead comes from)

[yuhan0]

Update: I traced the source of the logging and tried redefining these functions with no-ops:

• sc.api.logging/log-spy-ep-pre-eval
• sc.api.logging/log-spy-ep-post-eval

That alone reduced the execution time to 51ms, so it turned out the huge majority of the overhead was due to all the println logging.

There doesn't look to be a simple way of switching this logging behaviour off - perhaps a dynamic var of some sort like sc.api/*log-spy-execution* or a separate spying macro? Here's what I'm using for the time being:

(defmacro spy' [& args]
  `(with-redefs [sc.api.logging/log-spy-ep-pre-eval (fn [~'ep])
                 sc.api.logging/log-spy-ep-post-eval (fn [~'ep])]
     (sc/spy ~@args)))

Let me know and I'd be willing to contribute a PR :)

[vvvvalvalval]

Hello, I would not encourage you to use with-redefs for that (or anything), but have you read the customization section from the docs? It's really meant for this sort of use case. You can also pass the inline :sc/spy-ep-pre-eval-logger-fn and :sc/spy-ep-post-eval-logger-fn opts.

When I want to catch on Exceptions only, I usually do it by wrapping the exception in a try/catch and spying inside the catch clause.

Other options are:

1. using a brk, then exiting with an error
2. spying at random: (when (zero? (rand-int 100)) (sc.api/spy))

People have very different opinions regarding such workflow optimizations; this is why I recommend writing your own spy... wrappers in your project's utility namespace.

[yuhan0]

Thanks for all the pointers! That's what I get for digging through the source but not the documentation 😅 Being able to conditionally (spy) anywhere is pretty nice, I had the wrong impression that it had to always be wrapped around an expression.

Here's my modified macro from above, for anyone interested:

(def spysl-opts
  {:sc/spy-ep-post-eval-logger (fn [ep])
   :sc/spy-ep-pre-eval-logger (fn [ep])})

(defmacro spysl
  "Spy silently - do not print anything at execution points."
  ([] (sc.api/spy-emit spysl-opts nil &env &form))
  ([expr] (sc.api/spy-emit spysl-opts expr &env &form))
  ([opts expr] (sc.api/spy-emit (merge spysl-opts opts) expr &env &form)))