jorgenschaefer / emacs-buttercup

Behavior-Driven Emacs Lisp Testing
GNU General Public License v3.0
360 stars 44 forks source link

Trace formatting takes ages (with mutual refs?) #220

Open jscheid opened 2 years ago

jscheid commented 2 years ago

tl;dr backtrace formatting took around ~40 seconds for 10 failed tests and then didn't output any stack.

It's more or less instant and prints a useful stack with this:

(defun buttercup--format-stack-frame--print-limits (orig-fun &rest args)
  "Limit `print-level' and `print-length' in ORIG-FUN, forward ARGS."
  (let ((print-level eval-expression-print-level)
        (print-length eval-expression-print-length))
    (apply orig-fun args)))
(advice-add 'buttercup--format-stack-frame
            :around #'buttercup--format-stack-frame--print-limits)

My best guess is that what happens is the following:

I have mutual references on the stack, something like:

(cl-defstruct a b)
(cl-defstruct b a)
(let ((a (make-a))
      (b (make-b)))
  (setf (a-b a) b)
  (setf (b-a b) a)
  (func-that-errors a))

Because print-level and print-length are nil by default (at least when running in makem), prin1-to-string goes into infinite recursion probably until max-specpdl-size is exhausted.

I've solved this problem for myself but I had to spend an hour or so debugging it. I recommend making a similar setting the default.

snogge commented 2 years ago

Have you tried setting print-circle to t as described by @alphapapa in https://github.com/jorgenschaefer/emacs-buttercup/issues/218#issuecomment-1151658577 ?

jscheid commented 2 years ago

@snogge good idea, I forgot about print-circle, thank you. It seems like it should be exactly what is needed in my case, however I've tried just now and for some reason it doesn't help as much as print-level and print-length as far as wall time performance goes. In fact is seems to add about 1s to the formatting time, not sure why.

snogge commented 2 years ago

It's very possible that print-level and print-length cuts of before print-circle` in this case. Backtraces obviously need some work.

alphapapa commented 2 years ago

Yes, if the recursive structures are large enough, the level and length cutoffs could have a larger effect than print-circle.

It might be good for Buttercup to bind print-circle non-nil by default, anyway (around whatever code prints the backtraces).

In fact is seems to add about 1s to the formatting time, not sure why.

IIUC print-circle uses a hash table to track which items have been seen already, which can be some additional overhead, I guess (though whether that overhead is more than that of printing an item depends on the item, I suppose).