Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improve backtrace looks and performance #249

Merged
merged 9 commits into from
Sep 4, 2024

Conversation

snogge
Copy link
Collaborator

@snogge snogge commented Aug 12, 2024

Make the backtrace prints better - less unwanted output - with a lot better performance.
Fixes #247
Fixes #220

Instead of discarding all frames before `buttercup--debugger', use the
base argument of `backtrace-frame' to start at the frame after
`buttercup--debugger'.
@snogge
Copy link
Collaborator Author

snogge commented Aug 12, 2024

@alphapapa @doublep @jcs090218
I did some major surgery on the backtrace code which really help with performance.
I'll give you a few days to check it out before I merge. Let me know if I broke anything.

@alphapapa
Copy link
Contributor

Hi Ola,

Thanks for the heads-up. I just did a quick test on the org-ql repo, both with all tests passing and with 104 out of 437 specs failing, and performance was excellent: instead of taking minutes to finish outputting the results and the backtraces, it happened in a matter of seconds. This is a great improvement. Thank you for working on it!

@jcs090218
Copy link
Contributor

jcs090218 commented Aug 13, 2024

Thank you for notifying me. I've done a quick test, and it is working fine. :)

I've opened a PR in #250 to test downstream Eask and see if it works. This could make you more confident about the changes. 🤔

@doublep
Copy link
Contributor

doublep commented Aug 13, 2024

No tests in Eldev seem to broken with these changes.

However, it looks like the backtraces are not cut by Buttercup itself anymore (i.e. this is not because of Eldev). After intentionally corrupting one test, this is what I got in the branch (just ran make test, this is not through Eldev):

The buttercup--enclosed-expr function should handle expressions wrapped by buttercup--wrap-expr

Traceback (most recent call last):
  normal-top-level()
  command-line()
  command-line-1(("-L" "." "-l" "buttercup" "-f" "buttercup-run-discover" "-...
  buttercup-run-discover()
  buttercup-run()
  buttercup--run-suites((#s(buttercup-suite "The buttercup--enclosed-expr fu...
  mapc(buttercup--run-suite (#s(buttercup-suite "The buttercup--enclosed-exp...
  buttercup--run-suite(#s(buttercup-suite "The buttercup--enclosed-expr func...
  buttercup--run-suite(#s(buttercup-suite "should handle" #s(buttercup-suite...
  buttercup--run-spec(#s(buttercup-spec "expressions wrapped by buttercup--w...
  buttercup--update-with-funcall(#s(buttercup-spec "expressions wrapped by b...
  apply(buttercup--funcall (closure (t) nil (condition-case err (progn (butt...
  buttercup--funcall((closure (t) nil (condition-case err (progn (buttercup-...
  apply((closure (t) nil (condition-case err (progn (buttercup-expect (let (...
  (closure (t) nil (condition-case err (progn (buttercup-expect (let ((temp0...
  (condition-case err (progn (buttercup-expect (let ((temp0 '(buttercup--enc...
  (progn (buttercup-expect (let ((temp0 '(buttercup--enclosed-expr (buttercu...
  buttercup-expect((closure ((:type . buttercup--thunk) (expr buttercup--enc...
  buttercup-fail("%s" "Expected `(buttercup--enclosed-expr (buttercup--wrap-...
  signal(buttercup-failed "Expected `(buttercup--enclosed-expr (buttercup--w...
FAILED: Expected `(buttercup--enclosed-expr (buttercup--wrap-expr-and-eval '(ignore)))' to be `equal' to `(INTENTIONALLY-BROKEN-TEST)', but instead it was `(ignore)' which does not match because: (list-elt 0 (different-atoms ignore INTENTIONALLY-BROKEN-TEST)).

Ran 283 out of 284 specs, 1 failed, in 138.17ms.

For comparison, in master I get this instead:

The buttercup--enclosed-expr function should handle expressions wrapped by buttercup--wrap-expr

Traceback (most recent call last):
  buttercup-fail("%s" "Expected `(buttercup--enclosed-expr (buttercup--wrap-...
  signal(buttercup-failed "Expected `(buttercup--enclosed-expr (buttercup--w...
FAILED: Expected `(buttercup--enclosed-expr (buttercup--wrap-expr-and-eval '(ignore)))' to be `equal' to `(INTENTIONALLY-BROKEN-TEST)', but instead it was `(ignore)' which does not match because: (list-elt 0 (different-atoms ignore INTENTIONALLY-BROKEN-TEST)).

Also, the branch doesn't seem to add any new tests, which is suspicious for a big change.

@snogge
Copy link
Collaborator Author

snogge commented Aug 14, 2024

@doublep , how can I recreate that?

@doublep
Copy link
Contributor

doublep commented Aug 14, 2024

~/git/buttercup$ git diff
diff --git a/tests/test-buttercup.el b/tests/test-buttercup.el
index 5172c46..02420b3 100644
--- a/tests/test-buttercup.el
+++ b/tests/test-buttercup.el
@@ -172,7 +172,7 @@ before it's processed by other functions."
   (describe "should handle"
     (it "expressions wrapped by buttercup--wrap-expr"
       (expect (buttercup--enclosed-expr (buttercup--wrap-expr-and-eval '(ignore)))
-              :to-equal '(ignore)))
+              :to-equal '(INTENTIONALLY-BROKEN-TEST)))
     (it "a closure with expression copy?"
       ;; This is for before Oclosures were added, and is not testable
       ;; once interpreted-function types were added in Emacs 30.
~/git/buttercup$ emacs --version
GNU Emacs 29.4.50
Development version c0ef9e766eb1 on emacs-29 branch; build date 2024-06-28.
Copyright (C) 2024 Free Software Foundation, Inc.
GNU Emacs comes with ABSOLUTELY NO WARRANTY.
You may redistribute copies of GNU Emacs
under the terms of the GNU General Public License.
For more information about these matters, see the file named COPYING.
~/git/buttercup$ make test
./bin/buttercup -L . tests 
[...]

Traceback (most recent call last):
  normal-top-level()
  command-line()
  command-line-1(("-L" "." "-l" "buttercup" "-f" "buttercup-run-discover" "-...
  buttercup-run-discover()
  buttercup-run()
  buttercup--run-suites((#s(buttercup-suite "The buttercup--enclosed-expr fu...
  mapc(buttercup--run-suite (#s(buttercup-suite "The buttercup--enclosed-exp...
  buttercup--run-suite(#s(buttercup-suite "The buttercup--enclosed-expr func...
  buttercup--run-suite(#s(buttercup-suite "should handle" #s(buttercup-suite...
  buttercup--run-spec(#s(buttercup-spec "expressions wrapped by buttercup--w...
  buttercup--update-with-funcall(#s(buttercup-spec "expressions wrapped by b...
  apply(buttercup--funcall (closure (t) nil (condition-case err (progn (butt...
  buttercup--funcall((closure (t) nil (condition-case err (progn (buttercup-...
  apply((closure (t) nil (condition-case err (progn (buttercup-expect (let (...
  (closure (t) nil (condition-case err (progn (buttercup-expect (let ((temp0...
  (condition-case err (progn (buttercup-expect (let ((temp0 '(buttercup--enc...
  (progn (buttercup-expect (let ((temp0 '(buttercup--enclosed-expr (buttercu...
  buttercup-expect((closure ((:type . buttercup--thunk) (expr buttercup--enc...
  buttercup-fail("%s" "Expected `(buttercup--enclosed-expr (buttercup--wrap-...
  signal(buttercup-failed "Expected `(buttercup--enclosed-expr (buttercup--w...
FAILED: Expected `(buttercup--enclosed-expr (buttercup--wrap-expr-and-eval '(ignore)))' to be `equal' to `(INTENTIONALLY-BROKEN-TEST)', but instead it was `(ignore)' which does not match because: (list-elt 0 (different-atoms ignore INTENTIONALLY-BROKEN-TEST)).

Ran 283 out of 284 specs, 1 failed, in 138.10ms.
buttercup-run failed: ""
make: *** [Makefile:12: check-buttercup] Error 255

@snogge
Copy link
Collaborator Author

snogge commented Aug 16, 2024

I think that is because of buttercup nesting itself. It fails to find the correct bounds of the backtrace because there are two sets of them. While this is annoying, it feels less important than normal use. If you can recreate it with another package I would really like to know about it.
For the original problem in org-ql I see the opposite:

org-ql View saving/loading Links Buffers/Files Can search multiple files by filename

Traceback (most recent call last):
  #[899 "\306\307\"A@\306\310\"A@\306\311\"\206\312\302\242DA@\306\313...
  #[771 "rq\210\300 \210\301 \210\302c\210c\210\303u\210\211\204\304\305...
  with-simulated-input-1(#[0 "\300 \207" [org-open-at-point] 1] nil)
  signal(invalid-function (("\"ORG-QL-TEST\"")))
error: (invalid-function ("\"ORG-QL-TEST\""))

instead of

org-ql View saving/loading Links Buffers/Files Can search multiple files by filename
/
Traceback (most recent call last):
  normal-top-level()
  command-line()
  command-line-1(("--title" "makem.sh: org-ql (sandbox: sandbox/31.0.50)" "-...
  eval((progn (setq backtrace-on-error-noninteractive nil) (buttercup-run)) t)
  (progn (setq backtrace-on-error-noninteractive nil) (buttercup-run))
  buttercup-run()
  apply(makem-buttercup-run #[256 \203	\30\"\207\211\203\302\207\303...
  makem-buttercup-run(#[256 \203	\30\"\207\211\203\302\207\303\304!\...
  (if buttercup-suites (progn (apply oldfun r)))
  (progn (apply oldfun r))
  apply(#[256 \203	\30\"\207\211\203\302\207\303\304!\207" [buttercu...
  #[256 \203	\30\"\207\211\203\302\207\303\304!\207" [buttercup-suit...
  buttercup--run-suites((#s(buttercup-suite "org-ql" nil passed org-ql-test-...
  mapc(buttercup--run-suite (#s(buttercup-suite "org-ql" nil passed org-ql-t...
  buttercup--run-suite(#s(buttercup-suite "org-ql" nil passed org-ql-test-or...
  buttercup--run-suite(#s(buttercup-suite "View saving/loading" #s(buttercup...
  buttercup--run-suite(#s(buttercup-suite "Links" #s(buttercup-suite "View s...
  buttercup--run-suite(#s(buttercup-suite "Buffers/Files" #s(buttercup-suite...
  buttercup--run-spec(#s(buttercup-spec "Can search multiple files by filena...
  buttercup--update-with-funcall(#s(buttercup-spec "Can search multiple file...
  apply(buttercup--funcall #[0 "\3031 \3041�\305\306\307\310\300\301\302%\...
  buttercup--funcall(#[0 "\3031 \3041�\305\306\307\310\300\301\302%\311\30...
  apply(#[0 "\3031 \3041�\305\306\307\310\300\301\302%\311\306\312\313\302...
  #[0 "\3031 \3041�\305\306\307\310\300\301\302%\311\306\312\313\302##00\2...
  buttercup-expect(#[0 "\302\304\303\301\305\306%\207" [(var-after-link-save...
  buttercup--apply-matcher(:to-equal (#[0 "\302\304\303\301\305\306%\207" [(...
  apply(#[514 "\300\301D\"\211G\302U\203\211A\262\242\202\303\304\30...
  #[514 "\300\301D\"\211G\302U\203\211A\262\242\202\303\304\305GD\"...
  mapcar(buttercup--expr-and-value (#[0 "\302\304\303\301\305\306%\207" [(va...
  buttercup--expr-and-value(#[0 "\302\304\303\301\305\306%\207" [(var-after-...
  #[0 "\302\304\303\301\305\306%\207" [(var-after-link-save-open 'org-ql-vie...
  #[899 "\306\307\"A@\306\310\"A@\306\311\"\206\312\302\242DA@\306\313...
  #[771 "rq\210\300 \210\301 \210\302c\210c\210\303u\210\211\204\304\305...
  with-simulated-input-1(#[0 "\300 \207" [org-open-at-point] 1] nil)
  signal(invalid-function (("\"ORG-QL-TEST\"")))
error: (invalid-function ("\"ORG-QL-TEST\""))

@snogge
Copy link
Collaborator Author

snogge commented Aug 16, 2024

Hmm, but that specific test is not nested. I'll have to look further.

@doublep
Copy link
Contributor

doublep commented Aug 16, 2024

If you can recreate it with another package I would really like to know about it.

I originally noticed it with test/project-e in Eldev's test suite. I did run Buttercup inside Eldev, so initially I suspected that something got broken in my integration code because of these changes. Then I retested it without Eldev at all, on Buttercup directly, and saw the same problem. So, I'm pretty sure that it's a problem with this branch and most likely it's not about nesting level, because it seems to happen both in Buttercup and in unrelated projects.

@snogge
Copy link
Collaborator Author

snogge commented Aug 18, 2024

I think I'm on to something now.
The new code works great for unexpected errors in code called from within an except statement. That's why it works for the failing org-ql tests - there was a bug in org-ql that caused invalid-function errors.
Code outside except is not handled well on this branch.
The problem with the failing test in buttercup is actually different. That is just a test-mismatch and should really not collect any backtrace at all. What's a meaningful backtrace for (expect 1 :to-equal 0)?
There are a few other corner cases that have to be handled as well, like errors in the matcher or in before/after blocks.

@snogge snogge force-pushed the fix-247 branch 3 times, most recently from c0616be to bb77c5d Compare August 22, 2024 22:34
snogge added 8 commits August 27, 2024 22:55
This will limit the backtrace for errors signalled from within a
wrapped expression.  There is still a set of other conditions that
have to be handled in buttercup--backtrace.
There is no reason to collect backtraces for expect form where the
matcher detects a mismatch.  It's all buttercup infrastructure at that
point.
The first uninteresting frame is identified by a new
`buttercup--stackframe-marker' in a let statement:

   (let ((buttercup--stackframe-marker 1)) ...

This let-form is added to the buttercup-with-converted-ert-signals
macro, not because it has anything to do with ert signal conversion,
but because it is the last wrapper around the spec code given by the
user.
The "should not generate backtraces for skipped specs" had a lot of
similarties to the two specs in the "should not be collected or
printed for" suite.  Move it into that suite, not only for shared code
but also because they belong together.
Fake the last frame to show the matchers name.
Recent changes in the backtrace code has made
`buttercup--mark-stackframe' redundant.  Remove all uses and mentions
in code and tests.
@snogge
Copy link
Collaborator Author

snogge commented Aug 27, 2024

Newer and even more improved.
Now also with tests.
@doublep, the problems you reported should be fixed now.
@jcs090218 , the tests in #250 passes on this branch.

@snogge snogge merged commit 789570c into jorgenschaefer:master Sep 4, 2024
17 checks passed
@snogge
Copy link
Collaborator Author

snogge commented Sep 4, 2024

No comments for more than a week, merging this now.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Inexplicable hang on Emacs 30 snapshot Trace formatting takes ages (with mutual refs?)
4 participants