GNU bug report logs - #36566
27.0.50; debug is sometimes horribly slow

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 36566 in the body.
You can then email your comments to 36566 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: Michael Heerdegen <michael_heerdegen <at> web.de>
To: bug-gnu-emacs <at> gnu.org
Cc: Gemini Lasswell <gazally <at> runbox.com>
Subject: 27.0.50; debug is sometimes horribly slow
Date: Wed, 10 Jul 2019 05:09:24 +0200

Hi,

sometimes it takes 10 or 20 seconds until the debugger pops up.  I
debugged code using widgets (who are complicated long lists).  But both
the number of frames and the length of the printed lists were not
exorbitant - a quite normal situation.

When I revert

e09120d68694272ea5efbe13b16936b4382389d8
Add backtrace-mode and use it in the debugger, ERT and Edebug

the debugger becomes fast again and pops up in a reasonable time.  With
the commit, the debugger is quite unusable in some cases: stepping
(`debugger-step-through') takes ten seconds per hit etc.  Not good.

FWIW, I think I very much appreciate the cited commit - I didn't yet
make use of the added features but it seems to be cool.  I hope we can
find a solution here.  At least there should be a way to get a faster
behavior.  BTW, I used the profiler and found that most of the time is
spent while garbage collecting.  My first thought was that cl-print may
be the culprit but that doesn't seem to be the case.

TIA,

Michael.

Message #8 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Drew Adams <drew.adams <at> oracle.com>
To: Michael Heerdegen <michael_heerdegen <at> web.de>, 36566 <at> debbugs.gnu.org
Cc: Gemini Lasswell <gazally <at> runbox.com>
Subject: RE: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Tue, 9 Jul 2019 20:18:10 -0700 (PDT)

> sometimes it takes 10 or 20 seconds until the debugger pops up.  I
> debugged code using widgets (who are complicated long lists).  But both
> the number of frames and the length of the printed lists were not
> exorbitant - a quite normal situation.
> 
> When I revert
> 
> e09120d68694272ea5efbe13b16936b4382389d8
> Add backtrace-mode and use it in the debugger, ERT and Edebug
> 
> the debugger becomes fast again and pops up in a reasonable time.  With
> the commit, the debugger is quite unusable in some cases: stepping
> (`debugger-step-through') takes ten seconds per hit etc.  Not good.
> 
> FWIW, I think I very much appreciate the cited commit - I didn't yet
> make use of the added features but it seems to be cool.  I hope we can
> find a solution here.  At least there should be a way to get a faster
> behavior.  BTW, I used the profiler and found that most of the time is
> spent while garbage collecting.  My first thought was that cl-print may
> be the culprit but that doesn't seem to be the case.

BTW:
Is there a way to "turn off" the feature introduced
by the commit, even if most people want it on most
of the time?  (I'm not familiar with the feature,
but it sounds like something some users might want
to turn off sometimes.)

Message #11 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Noam Postavsky <npostavs <at> gmail.com>
To: Michael Heerdegen <michael_heerdegen <at> web.de>
Cc: Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Wed, 10 Jul 2019 07:20:14 -0400

Michael Heerdegen <michael_heerdegen <at> web.de> writes:
>
> sometimes it takes 10 or 20 seconds until the debugger pops up.  I
> debugged code using widgets (who are complicated long lists).  But both
> the number of frames and the length of the printed lists were not
> exorbitant - a quite normal situation.

Can you give an example recipe that produces the slowness?  It's not
usually slow, right?  (When I trigger the debugger in master right now,
I don't notice problem.)

Message #14 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Michael Heerdegen <michael_heerdegen <at> web.de>
To: Noam Postavsky <npostavs <at> gmail.com>
Cc: Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Thu, 11 Jul 2019 00:46:00 +0200

[Message part 1 (text/plain, inline)]

Noam Postavsky <npostavs <at> gmail.com> writes:

> > sometimes it takes 10 or 20 seconds until the debugger pops up.  I
> > debugged code using widgets (who are complicated long lists).  But both
> > the number of frames and the length of the printed lists were not
> > exorbitant - a quite normal situation.
>
> Can you give an example recipe that produces the slowness?  It's not
> usually slow, right?  (When I trigger the debugger in master right now,
> I don't notice problem.)

I investigated a bit and found that the main factor of the sluggishness
seems to be my private (global) setting of print-gensym -> t: I can
toggle sluggishness in both the Emacs with my setup and emacs -Q just by
toggling this variable.  My debugger use case involves gensyms (see
later).  Ok, so it's probably mainly a printing issue.

Here is my use case: load the attached file (don't compile, I made it
contain a bug).  M-x find-cmd-widget, and insert a "links" expression
by hitting the INS button and select "links" with the "expr" button.

With print-gemsym -> nil, the debugger needs approx. 2 seconds here to
pop up, and with print-gemsym -> t, approx. 12.  So I wonder why this
setting makes it that slow - I would expect a small time penalty, but
such a big difference?

BTW, extra points if the debugger provided commands/ a menu to tune such
settings (like printing variables) live when using it.

[find-cmd-widget.el (application/emacs-lisp, attachment)]

[Message part 3 (text/plain, inline)]

Thanks,

Michael.

Message #17 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Gemini Lasswell <gazally <at> runbox.com>
To: Michael Heerdegen <michael_heerdegen <at> web.de>
Cc: 36566 <at> debbugs.gnu.org, Noam Postavsky <npostavs <at> gmail.com>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sat, 13 Jul 2019 17:02:19 -0700

Michael Heerdegen <michael_heerdegen <at> web.de> writes:

> With print-gemsym -> nil, the debugger needs approx. 2 seconds here to
> pop up, and with print-gemsym -> t, approx. 12.  So I wonder why this
> setting makes it that slow - I would expect a small time penalty, but
> such a big difference?

The C printing code builds hash tables to match gensyms to the numbers
they are printed with.  So it is building and discarding these hash
tables which causes the garbage collection and the slowdown.  Emacs 26's
backtrace printing is also significantly slower with print-gensym turned
on.

The reason master is so much slower than Emacs 26 is because of the
adaptive abbreviating I added to reduce problems with really long lines.
In Emacs 26 it's hard to debug things like magit or org-mode because
lines in the backtrace can easily get to be thousands or millions of
characters long and display gets really slow.  When I added
backtrace-mode, I gave it a target line length and a function which
starts with guesses at the appropriate values of print-length and
print-level, and which iteratively prints using those values, and if the
length of the printed representation is over the target, it reduces
print-length and print-level and tries again.  That reprinting, and
consequential repeated construction of gensym hash tables, is what's
making master slower than Emacs 26 in this case.

I remember when I was writing that function thinking that it was a
heuristic sort of algorithm and would likely need tweaking, so here we
are.

The easy fix for you for today is to set backtrace-line-length to 100 or
less, which will make the initial values of print-length and print-level
so low that little reprinting will be done.  Then use
backtrace-expand-ellipsis (bound to "."), with or without C-u, on the
lines where you want to see the full data structure.  And try "+" and
"-" if you haven't already.

I'll experiment with tweaking the heuristic to reduce the amount of
reprinting it does, and let you know what I come up with.

> BTW, extra points if the debugger provided commands/ a menu to tune such
> settings (like printing variables) live when using it.

There is such a command for print-circle (bound to "#") and it would be
easy to add one for print-gensym, although I could use a keybinding
suggestion.  backtrace-line-length is a defcustom.

Message #20 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Michael Heerdegen <michael_heerdegen <at> web.de>
To: Gemini Lasswell <gazally <at> runbox.com>
Cc: 36566 <at> debbugs.gnu.org, Noam Postavsky <npostavs <at> gmail.com>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Mon, 15 Jul 2019 04:05:07 +0200

Gemini Lasswell <gazally <at> runbox.com> writes:

> The easy fix for you for today is to set backtrace-line-length to 100 or
> less, which will make the initial values of print-length and print-level
> so low that little reprinting will be done.  Then use
> backtrace-expand-ellipsis (bound to "."), with or without C-u, on the
> lines where you want to see the full data structure.  And try "+" and
> "-" if you haven't already.

Ok, will have a look at these commands.  I've simply turned print-gensym
off for now in the debugger.


> I'll experiment with tweaking the heuristic to reduce the amount of
> reprinting it does, and let you know what I come up with.

Ok, great, tia.  Dunno if it would be worth it to optimize this test
printing, e.g. by turning print-gensym temporarily off.

> > BTW, extra points if the debugger provided commands/ a menu to tune such
> > settings (like printing variables) live when using it.
>
> There is such a command for print-circle (bound to "#") and it would be
> easy to add one for print-gensym, although I could use a keybinding
> suggestion.

You could use ":".  Or "# #" for print-circle and "# :" for print-gensym
(i.e. make "#" a prefix command).  This is inspired by print-circle
references looking like #N# and print syntax of gensyms looking like
#:NAME.

In any case, _please_ add both to the menu for discoverability, maybe
also the "global" version (i.e. 4 entries in sum).


BTW, when I eval this

(let ((x '#1=(1 . #1#)))
  (debug)
  (cons x x))

I get a backtrace like

Debugger entered: nil
  (let ((x '(1 . #6))) (debug) (cons x x))
  eval((let ((x '(1 . #7))) (debug) (cons x x)) t)

whereby when I hit C-u # all references get number 1, or start from 1
for every frame:

Debugger entered: nil
  (let ((x '#1=(1 . #1#))) (debug) (cons x x))
  eval((let ((x '#1=(1 . #1#))) (debug) (cons x x)) t)

Just a minor inconvenience, though.

Anyway, thanks for improving the debugger in this way so far, this is
very useful.


Michael.

Message #23 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Gemini Lasswell <gazally <at> runbox.com>
To: Michael Heerdegen <michael_heerdegen <at> web.de>
Cc: 36566 <at> debbugs.gnu.org, Noam Postavsky <npostavs <at> gmail.com>,
 Stefan Monnier <monnier <at> IRO.UMontreal.CA>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Wed, 31 Jul 2019 17:53:17 -0700

[Message part 1 (text/plain, inline)]

Gemini Lasswell <gazally <at> runbox.com> writes:

> The reason master is so much slower than Emacs 26 is because of the
> adaptive abbreviating I added to reduce problems with really long lines.

That statement turned out to be true, however once I improved the
adaptive abbreviating algorithm it became apparent to me that backtrace
printing was creating an excessive amount of garbage in both Emacs 26
and 27 when either print-circle or print-gensym was set.

As part of my investigating process I made a patch which added a
hash-tables-consed variable along the lines of strings-consed et al,
which I incremented in Fmake_hash_table to count the number of hash
tables created, and got the following interesting result:

(let ((print-gensym t))
  (list hash-tables-consed (princ "hello") hash-tables-consed))
=>
hello
(814064 "hello" 814065)

This is relevant to backtrace printing because backtrace printing uses
cl-prin1, which prints Lisp data structures using

(princ "(" stream)

to print the parentheses, which was making for a lot of created and
destroyed hash tables whenever print-circle or print-gensym was set.

The third patch attached below fixes that by adding a macro to
cl-print.el to wrap the printing of all the simple things with
let-bindings of print-circle and print-gensym to nil.

Patch #2 improves cl-print-to-string-with-limit's adaptive fitting of a
printed representation into a given line length by making it reduce
print-level and print-length more rapidly when the result of a test
printing is very long.

Patch #1 improves the backtrace-mode UI by adding a command to toggle
print-gensym, and puts both that and its print-circle toggle command on
the menu, and adds an echo area message to both to let you know what
they did.

Here's how long Michael's use case takes to render the backtrace
buffer on my machine, with print-gensym non-nil, in various versions of
Emacs:

Emacs 26.2: 4.1s
Emacs 27, before patches: 9.4s
Emacs 27, with patch #2: 5.6s
Emacs 27, with patches #2 and #3: 1.2s.

Patch #3 has the advantage of being straightforward logically and not
breaking anything which doesn't use cl-prin1, but it undoubtedly also
slows down cl-prin1 in the probably more common case that print-gensym
and print-circle are both nil.  There are other ways to fix this, such
as by adding a new entry point in print.c for printing simple strings,
or by modifying the logic in print_preprocess to not create a hash table
if the top-level object is a string with no properties.  I'm not sure
what the best choice is here, so let me know what you think.

[0001-Improve-print-output-options-commands-in-backtrace-m.patch (text/plain, attachment)]

[0002-Improve-performance-of-backtrace-printing-bug-36566.patch (text/plain, attachment)]

[0003-Fix-excessive-hash-table-creation-in-cl-prin1-bug-36.patch (text/plain, attachment)]

Message #26 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Noam Postavsky <npostavs <at> gmail.com>
To: Gemini Lasswell <gazally <at> runbox.com>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>, 36566 <at> debbugs.gnu.org,
 Stefan Monnier <monnier <at> IRO.UMontreal.CA>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Wed, 31 Jul 2019 21:05:01 -0400

Gemini Lasswell <gazally <at> runbox.com> writes:

> The third patch attached below fixes that by adding a macro to
> cl-print.el to wrap the printing of all the simple things with
> let-bindings of print-circle and print-gensym to nil.

> Patch #3 has the advantage of being straightforward logically and not
> breaking anything which doesn't use cl-prin1, but it undoubtedly also
> slows down cl-prin1 in the probably more common case that print-gensym
> and print-circle are both nil.  There are other ways to fix this, such
> as by adding a new entry point in print.c for printing simple strings,
> or by modifying the logic in print_preprocess to not create a hash table
> if the top-level object is a string with no properties.

This last idea sounds like a straightforward win to me, with no obvious
drawbacks.  I mean, no point in allocating a hash table if we can
cheaply detect it will never be used, right?

Message #29 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Gemini Lasswell <gazally <at> runbox.com>
To: Michael Heerdegen <michael_heerdegen <at> web.de>
Cc: 36566 <at> debbugs.gnu.org, Noam Postavsky <npostavs <at> gmail.com>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Wed, 31 Jul 2019 18:06:10 -0700

Michael Heerdegen <michael_heerdegen <at> web.de> writes:

> BTW, when I eval this
>
> (let ((x '#1=(1 . #1#)))
>   (debug)
>   (cons x x))
>
> I get a backtrace like
>
> Debugger entered: nil
>   (let ((x '(1 . #6))) (debug) (cons x x))
>   eval((let ((x '(1 . #7))) (debug) (cons x x)) t)
>
> whereby when I hit C-u # all references get number 1, or start from 1
> for every frame:
>
> Debugger entered: nil
>   (let ((x '#1=(1 . #1#))) (debug) (cons x x))
>   eval((let ((x '#1=(1 . #1#))) (debug) (cons x x)) t)
>
> Just a minor inconvenience, though.

Without print-circle turned on, no hash table gets built to identify
objects, so the #<number> is only an indicator that a loop was found in
the data structure, not an indicator of any particular object. The
number printed comes from the depth of nested data structures at the
point the loop is detected.

Message #32 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Gemini Lasswell <gazally <at> runbox.com>
To: Noam Postavsky <npostavs <at> gmail.com>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>, 36566 <at> debbugs.gnu.org,
 Stefan Monnier <monnier <at> IRO.UMontreal.CA>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Mon, 05 Aug 2019 12:53:08 -0700

[Message part 1 (text/plain, inline)]

Noam Postavsky <npostavs <at> gmail.com> writes:

>>
>> ...by modifying the logic in print_preprocess to not create a hash table
>> if the top-level object is a string with no properties.
>
> This last idea sounds like a straightforward win to me, with no obvious
> drawbacks.  I mean, no point in allocating a hash table if we can
> cheaply detect it will never be used, right?

I made that change, and then, in studying the uses of
print-number-table, found more cases in which allocated hash tables were
never used.  Since 2011 when byte-compile-disable-print-circle was
marked obsolete and 2012 when commit 4ae29f89be changed the logic in
print_object, the only time print-number-table gets used is when
print-circle is non-nil.

Because of that observation, I have added a patch which makes it so that
print_preprocess is only called to create print-number-table when
print_circle is non-nil.  The patch also simplifies print_preprocess
accordingly.  In order to test that change thoroughly I added a couple
new print tests and reorganized the existing print tests so that all
functionality common between print.c and cl-print.el is now tested by
the same tests, located in src/print-tests.el.

Michael's use case is down to 0.7s on my machine.

[0001-Improve-print-output-options-commands-in-backtrace-m.patch (text/plain, attachment)]

[0002-Improve-performance-of-backtrace-printing-bug-36566.patch (text/plain, attachment)]

[0003-Fix-unnecessary-hash-table-creation-in-cl-prin1-bug-.patch (text/plain, attachment)]

[0004-Create-common-tests-for-print.c-and-cl-print.el.patch (text/plain, attachment)]

[0005-Don-t-build-print-number-table-unless-it-will-be-use.patch (text/plain, attachment)]

Message #35 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Noam Postavsky <npostavs <at> gmail.com>
To: Gemini Lasswell <gazally <at> runbox.com>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>, 36566 <at> debbugs.gnu.org,
 Stefan Monnier <monnier <at> IRO.UMontreal.CA>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sun, 18 Aug 2019 21:30:56 -0400

Gemini Lasswell <gazally <at> runbox.com> writes:

>>> ...by modifying the logic in print_preprocess to not create a hash table
>>> if the top-level object is a string with no properties.
>>
>> This last idea sounds like a straightforward win to me, with no obvious
>> drawbacks.  I mean, no point in allocating a hash table if we can
>> cheaply detect it will never be used, right?
>
> I made that change, and then, in studying the uses of
> print-number-table, found more cases in which allocated hash tables were
> never used.  Since 2011 when byte-compile-disable-print-circle was
> marked obsolete and 2012 when commit 4ae29f89be changed the logic in
> print_object, the only time print-number-table gets used is when
> print-circle is non-nil.

> Michael's use case is down to 0.7s on my machine.

> Subject: [PATCH 2/5] Improve performance of backtrace printing (bug#36566)
>
> * lisp/emacs-lisp/cl-print.el (cl-print-to-string-with-limit): Reduce
> print-level and print-length more quickly when the structure being
> printed is very large.

Is this one still needed?  I tried reverting it, and it seems to make no
noticeable difference now (I didn't really measure though, I can't think
of a straightforward way of doing that), at least for the case that
Michael posted.

> Subject: [PATCH 4/5] Create common tests for print.c and cl-print.el
>
> * test/lisp/emacs-lisp/cl-print-tests.el:
                                          ^
Extra colon.

> (cl-print--test, cl-print-tests-1, cl-print-tests-2)
> (cl-print-tests-3, cl-print-tests-4, cl-print-tests-5)
> (cl-print-tests-strings, cl-print-circle, cl-print-circle-2):
> Remove.

> Subject: [PATCH 5/5] Don't build print-number-table unless it will be used
>
> There are only a few users of print-number-table, and none of them use
> it when print-circle is nil.  A couple of them used to.  print_object
> was changed to not use print-number-table unless print-circle is non-nil
> in commit 4ae29f89be.  byte-compile-output-docform which uses[...]

We try not to use hashes to reference commits (e.g., so that ChangeLogs
can be read without accessing the git repo).  I prefer date+subject, as
in

    There are only a few users of print-number-table, and none of them use
    it when print-circle is nil.  A couple of them used to.  print_object
    was changed in 2012-04-20 "* src/print.c (print_preprocess): Only check
    print_depth if print-circle is nil".  byte-compile-output-docform which
    uses[...]

You can also use "Action Stamps" though I find those not so human-readable
(theoretically, it's more machine-readable).

Message #38 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Gemini Lasswell <gazally <at> runbox.com>
To: Noam Postavsky <npostavs <at> gmail.com>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>, 36566 <at> debbugs.gnu.org,
 Stefan Monnier <monnier <at> IRO.UMontreal.CA>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Fri, 06 Sep 2019 09:41:05 -0700

Noam Postavsky <npostavs <at> gmail.com> writes:

>> Subject: [PATCH 2/5] Improve performance of backtrace printing (bug#36566)
>>
>> * lisp/emacs-lisp/cl-print.el (cl-print-to-string-with-limit): Reduce
>> print-level and print-length more quickly when the structure being
>> printed is very large.
>
> Is this one still needed?  I tried reverting it, and it seems to make no
> noticeable difference now (I didn't really measure though, I can't think
> of a straightforward way of doing that), at least for the case that
> Michael posted.

My straightforward way of doing that is

M-: (benchmark-run (revert-buffer))  RET

while the backtrace buffer is current.

I tried, with and without the patch, these steps:

Navigate to org-export--prune-tree in ox.el.
C-M-x to instrument it with Edebug.
Open a 150K org-mode file.
C-c C-e h H
Edebug to line 2728 of ox.el (inside the lambda bound to 'walk-data').
Use 'd' to get a backtrace. 
M-: (benchmark-run (revert-buffer)) RET

With the patch: (0.594630583 9 0.31395808699999783)
Without the patch: (0.925387816 15 0.5158638049999986)

I would expect that debugging deeper into org-mode export (so that there
are more frames to display containing the org parse tree) with a larger
org-mode file would exaggerate the difference.

Edebug is very sluggish debugging org-export--prune-tree because it is
sending some 400K lines to the echo area, and then those make *Messages*
redisplay slow.  I will work on another patch to improve Edebug's
behavior in this case.

>> Subject: [PATCH 4/5] Create common tests for print.c and cl-print.el
>
> Extra colon.
>
>> Subject: [PATCH 5/5] Don't build print-number-table unless it will be used
>
> We try not to use hashes to reference commits
>

I'll fix the patch comments as you suggest.

Message #41 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Noam Postavsky <npostavs <at> gmail.com>
To: Gemini Lasswell <gazally <at> runbox.com>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>, 36566 <at> debbugs.gnu.org,
 Stefan Monnier <monnier <at> IRO.UMontreal.CA>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Tue, 10 Sep 2019 22:54:07 -0400

Gemini Lasswell <gazally <at> runbox.com> writes:

> Noam Postavsky <npostavs <at> gmail.com> writes:
>
>>> Subject: [PATCH 2/5] Improve performance of backtrace printing (bug#36566)
>>>
>>> * lisp/emacs-lisp/cl-print.el (cl-print-to-string-with-limit): Reduce
>>> print-level and print-length more quickly when the structure being
>>> printed is very large.
>>
>> Is this one still needed?  I tried reverting it, and it seems to make no
>> noticeable difference now (I didn't really measure though, I can't think
>> of a straightforward way of doing that), at least for the case that
>> Michael posted.
>
> My straightforward way of doing that is
>
> M-: (benchmark-run (revert-buffer))  RET
>
> while the backtrace buffer is current.

I actually get 0.9 vs 1.3 seconds (the latter being with patch 2/5
reverted) with Michael's example, which is more of a difference than I
expected based on my non-timed trials.

> I tried, with and without the patch, these steps:
>
> Navigate to org-export--prune-tree in ox.el.
> C-M-x to instrument it with Edebug.
> Open a 150K org-mode file.
> C-c C-e h H
> Edebug to line 2728 of ox.el (inside the lambda bound to 'walk-data').
> Use 'd' to get a backtrace. 
> M-: (benchmark-run (revert-buffer)) RET
>
> With the patch: (0.594630583 9 0.31395808699999783)
> Without the patch: (0.925387816 15 0.5158638049999986)
>
> I would expect that debugging deeper into org-mode export (so that there
> are more frames to display containing the org parse tree) with a larger
> org-mode file would exaggerate the difference.

Alright, it's probably enough to justify this.

> Edebug is very sluggish debugging org-export--prune-tree because it is
> sending some 400K lines to the echo area, and then those make *Messages*
> redisplay slow.  I will work on another patch to improve Edebug's
> behavior in this case.
>
>>> Subject: [PATCH 4/5] Create common tests for print.c and cl-print.el
>>
>> Extra colon.
>>
>>> Subject: [PATCH 5/5] Don't build print-number-table unless it will be used
>>
>> We try not to use hashes to reference commits
>>
>
> I'll fix the patch comments as you suggest.

Okay, there's nothing more from my side, so I guess you can go ahead and
push when ready.

Message #44 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Gemini Lasswell <gazally <at> runbox.com>
To: Noam Postavsky <npostavs <at> gmail.com>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>, 36566 <at> debbugs.gnu.org,
 Stefan Monnier <monnier <at> IRO.UMontreal.CA>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Fri, 13 Sep 2019 14:08:24 -0700

Noam Postavsky <npostavs <at> gmail.com> writes:

>
> Okay, there's nothing more from my side, so I guess you can go ahead and
> push when ready.

Pushed.  I'll leave this bug open for the remaining performance problem
in Edebug.

Message #47 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Mauro Aranda <maurooaranda <at> gmail.com>
To: Gemini Lasswell <gazally <at> runbox.com>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>, Stefan Monnier <monnier <at> iro.umontreal.ca>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sat, 14 Sep 2019 10:44:23 -0300

[Message part 1 (text/plain, inline)]

After commit 6eaf39d21b70802e6bc607ee2fc2fff67b79231a
Fix unnecessary hash table creation in cl-prin1 (bug#36566)

I can't build emacs with configure option
--enable-check-lisp-object-type.

This is the compilation error I get:
  CC       print.o
print.c: In function ‘print_preprocess’:
print.c:1155:4: error: invalid operands to binary || (have ‘int’ and
‘Lisp_Object {aka struct Lisp_Object}’)
    || Vprint_continuous_numbering))     \
    ^
print.c:1188:7: note: in expansion of macro ‘PRINT_CIRCLE_CANDIDATE_P’
   if (PRINT_CIRCLE_CANDIDATE_P (obj))
       ^
print.c: In function ‘print_object’:
print.c:1155:4: error: invalid operands to binary || (have ‘int’ and
‘Lisp_Object {aka struct Lisp_Object}’)
    || Vprint_continuous_numbering))     \
    ^
print.c:1866:12: note: in expansion of macro ‘PRINT_CIRCLE_CANDIDATE_P’
   else if (PRINT_CIRCLE_CANDIDATE_P (obj))
            ^
Makefile:402: recipe for target 'print.o' failed
make[1]: *** [print.o] Error 1
make[1]: Leaving directory '/home/tbb/emacs/emacs/src'
Makefile:424: recipe for target 'src' failed
make: *** [src] Error 2

However, using plain ./configure && make
builds succesfully.

Previous commit builds, using the same option.
I add system information, as output by `report-emacs-bug':

In GNU Emacs 27.0.50 (build 4, i686-pc-linux-gnu, GTK+ Version 3.18.9)
 of 2019-09-14 built on the-blackbeard
Repository revision: 5c40c21a47062782bc983f41e8eeb97180dca693
Repository branch: HEAD
Windowing system distributor 'The X.Org Foundation', version 11.0.11906000
System Description: Ubuntu 16.04.6 LTS

Configured using:
 'configure --enable-check-lisp-object-type'

[Message part 2 (text/html, inline)]

Message #50 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Eli Zaretskii <eliz <at> gnu.org>
To: Mauro Aranda <maurooaranda <at> gmail.com>
Cc: michael_heerdegen <at> web.de, gazally <at> runbox.com, 36566 <at> debbugs.gnu.org,
 npostavs <at> gmail.com, monnier <at> iro.umontreal.ca
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sat, 14 Sep 2019 17:05:24 +0300

> From: Mauro Aranda <maurooaranda <at> gmail.com>
> Date: Sat, 14 Sep 2019 10:44:23 -0300
> Cc: Michael Heerdegen <michael_heerdegen <at> web.de>, 36566 <at> debbugs.gnu.org,
>  Noam Postavsky <npostavs <at> gmail.com>, Stefan Monnier <monnier <at> iro.umontreal.ca>
> 
> After commit 6eaf39d21b70802e6bc607ee2fc2fff67b79231a
> Fix unnecessary hash table creation in cl-prin1 (bug#36566)
> 
> I can't build emacs with configure option
> --enable-check-lisp-object-type.
> 
> This is the compilation error I get:
>   CC       print.o
> print.c: In function ‘print_preprocess’:
> print.c:1155:4: error: invalid operands to binary || (have ‘int’ and ‘Lisp_Object {aka struct Lisp_Object}’)
>     || Vprint_continuous_numbering))     \
>     ^

Thanks.  Please try again, I think I fixed this.

Message #53 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Mauro Aranda <maurooaranda <at> gmail.com>
To: Eli Zaretskii <eliz <at> gnu.org>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>,
 Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>, Stefan Monnier <monnier <at> iro.umontreal.ca>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sat, 14 Sep 2019 11:16:04 -0300

[Message part 1 (text/plain, inline)]

Eli Zaretskii <eliz <at> gnu.org> writes:

>> From: Mauro Aranda <maurooaranda <at> gmail.com>
>> Date: Sat, 14 Sep 2019 10:44:23 -0300
>> Cc: Michael Heerdegen <michael_heerdegen <at> web.de>, 36566 <at> debbugs.gnu.org,
>>  Noam Postavsky <npostavs <at> gmail.com>, Stefan Monnier <
monnier <at> iro.umontreal.ca>
>>
>> After commit 6eaf39d21b70802e6bc607ee2fc2fff67b79231a
>> Fix unnecessary hash table creation in cl-prin1 (bug#36566)
>>
>> I can't build emacs with configure option
>> --enable-check-lisp-object-type.
>>
>> This is the compilation error I get:
>>   CC       print.o
>> print.c: In function ‘print_preprocess’:
>> print.c:1155:4: error: invalid operands to binary || (have ‘int’ and
‘Lisp_Object {aka struct Lisp_Object}’)
>>     || Vprint_continuous_numbering))     \
>>     ^
>
> Thanks.  Please try again, I think I fixed this.

Builds succesfully now.  Thank you.

[Message part 2 (text/html, inline)]

Message #56 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Eli Zaretskii <eliz <at> gnu.org>
To: Mauro Aranda <maurooaranda <at> gmail.com>
Cc: michael_heerdegen <at> web.de, gazally <at> runbox.com, 36566 <at> debbugs.gnu.org,
 npostavs <at> gmail.com, monnier <at> iro.umontreal.ca
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sat, 14 Sep 2019 18:47:51 +0300

> From: Mauro Aranda <maurooaranda <at> gmail.com>
> Date: Sat, 14 Sep 2019 11:16:04 -0300
> Cc: Gemini Lasswell <gazally <at> runbox.com>, Michael Heerdegen <michael_heerdegen <at> web.de>, 36566 <at> debbugs.gnu.org, 
> 	Noam Postavsky <npostavs <at> gmail.com>, Stefan Monnier <monnier <at> iro.umontreal.ca>
> 
> >>   CC       print.o
> >> print.c: In function ‘print_preprocess’:
> >> print.c:1155:4: error: invalid operands to binary || (have ‘int’ and ‘Lisp_Object {aka struct Lisp_Object}’)
> >>     || Vprint_continuous_numbering))     \
> >>     ^
> >
> > Thanks.  Please try again, I think I fixed this.
> 
> Builds succesfully now.  Thank you.

Great, thanks for testing.

Message #59 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Lars Ingebrigtsen <larsi <at> gnus.org>
To: Gemini Lasswell <gazally <at> runbox.com>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>, Stefan Monnier <monnier <at> IRO.UMontreal.CA>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Mon, 25 Apr 2022 16:41:44 +0200

Gemini Lasswell <gazally <at> runbox.com> writes:

> Pushed.  I'll leave this bug open for the remaining performance problem
> in Edebug.

(I'm going through old bug reports that unfortunately weren't resolved
at the time.)

Skimming this bug report, it's not immediately clear to me what the
remaining performance problems were.  Does anybody have a simple test
case that illustrates the problem (if, indeed, it's still present in the
current Emacs -- this was two years ago).

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

Message #64 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Michael Heerdegen <michael_heerdegen <at> web.de>
To: Lars Ingebrigtsen <larsi <at> gnus.org>
Cc: Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>, Stefan Monnier <monnier <at> IRO.UMontreal.CA>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Tue, 26 Apr 2022 01:23:07 +0200

Lars Ingebrigtsen <larsi <at> gnus.org> writes:

> Skimming this bug report, it's not immediately clear to me what the
> remaining performance problems were.  Does anybody have a simple test
> case that illustrates the problem (if, indeed, it's still present in the
> current Emacs -- this was two years ago).

I didn't see performance problems with my setup since then AFAIR.
Didn't play much with the newly introduced debugger settings and
commands though.

Let's wait for Gemini's answer.

Michael.

Message #67 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Gemini Lasswell <gazally <at> runbox.com>
To: Lars Ingebrigtsen <larsi <at> gnus.org>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>,
 Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>, Stefan Monnier <monnier <at> IRO.UMontreal.CA>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Tue, 26 Apr 2022 17:37:41 -0700

Lars Ingebrigtsen <larsi <at> gnus.org> writes:

> Skimming this bug report, it's not immediately clear to me what the
> remaining performance problems were.  Does anybody have a simple test
> case that illustrates the problem (if, indeed, it's still present in the
> current Emacs -- this was two years ago).

I followed these steps, found in one of my emails from two years ago,
using Emacs 28 downloaded from my distro and launched with '-Q', and a
bigger org file of about 250K, cause that's what I had handy:

Navigate to org-export--prune-tree in ox.el.
C-M-x to instrument it with Edebug.
Open a 150K org-mode file.
C-c C-e h H
Press Space repeatedly to step with Edebug

Result: stepping over any evaluation of the variable  `data` takes a few
seconds.

Two years ago I called Edebug "very sluggish" in these circumstances but
I would not call it that today, so I think you can go ahead and close
this.

Message #70 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Michael Heerdegen <michael_heerdegen <at> web.de>
To: Gemini Lasswell <gazally <at> runbox.com>
Cc: Lars Ingebrigtsen <larsi <at> gnus.org>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>, Stefan Monnier <monnier <at> IRO.UMontreal.CA>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Wed, 27 Apr 2022 06:42:15 +0200

Gemini Lasswell <gazally <at> runbox.com> writes:

> Press Space repeatedly to step with Edebug

When I replied I missed that the report partly diverged into Edebug (my
original report was about the backtrace based debugger).

> Result: stepping over any evaluation of the variable  `data` takes a few
> seconds.

Is that time spent in printing?  I experience that from time to time,
too, but I thought it might be related to my config.  Should we maybe
create a new report for that and close this one?

Thanks,

Michael.

Message #73 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Lars Ingebrigtsen <larsi <at> gnus.org>
To: Michael Heerdegen <michael_heerdegen <at> web.de>
Cc: Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>, Stefan Monnier <monnier <at> IRO.UMontreal.CA>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Wed, 27 Apr 2022 14:28:31 +0200

Michael Heerdegen <michael_heerdegen <at> web.de> writes:

>> Result: stepping over any evaluation of the variable  `data` takes a few
>> seconds.
>
> Is that time spent in printing?  I experience that from time to time,
> too, but I thought it might be related to my config.  Should we maybe
> create a new report for that and close this one?

Yup, sounds good to me, so I'm closing this one.

A case to reproduce the problem that doesn't require org files would be
nice.  `data' in the example here is a parse tree, so perhaps the
slowness is in printing tree-like structures?  (But I haven't actually
tried to debug this.)

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

Message #78 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Gemini Lasswell <gazally <at> runbox.com>
To: Lars Ingebrigtsen <larsi <at> gnus.org>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>,
 Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>, Stefan Monnier <monnier <at> IRO.UMontreal.CA>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Thu, 28 Apr 2022 10:56:26 -0700

Lars Ingebrigtsen <larsi <at> gnus.org> writes:

> A case to reproduce the problem that doesn't require org files would be
> nice.  `data' in the example here is a parse tree, so perhaps the
> slowness is in printing tree-like structures?  (But I haven't actually
> tried to debug this.)

The slowness does come from printing large tree-like structures. Here is
a small example to reproduce the problem.  Paste the following code into
*scratch*:

(defun my-make-a-tree (depth)
  (if (natnump depth)
      (list (my-make-a-tree (1- depth)) (my-make-a-tree (1- depth)))
    (list 'leaf)))

(defun my-func ()
  (let ((tree (my-make-a-tree 13)))
    tree))

(my-func)

Evaluate the first form using C-M-x and the second using C-u C-M-x.
Then evaluate the third form with C-M-x.  You will enter Edebug; press
space to step through.

Result: Each step takes a few seconds and creates a message of about
150K characters.

Message #81 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Lars Ingebrigtsen <larsi <at> gnus.org>
To: Gemini Lasswell <gazally <at> runbox.com>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>, Stefan Monnier <monnier <at> IRO.UMontreal.CA>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Fri, 13 May 2022 18:01:02 +0200

Gemini Lasswell <gazally <at> runbox.com> writes:

> The slowness does come from printing large tree-like structures. Here is
> a small example to reproduce the problem.  Paste the following code into
> *scratch*:
>
> (defun my-make-a-tree (depth)
>   (if (natnump depth)
>       (list (my-make-a-tree (1- depth)) (my-make-a-tree (1- depth)))
>     (list 'leaf)))
>
> (defun my-func ()
>   (let ((tree (my-make-a-tree 13)))
>     tree))
>
> (my-func)
>
> Evaluate the first form using C-M-x and the second using C-u C-M-x.
> Then evaluate the third form with C-M-x.  You will enter Edebug; press
> space to step through.
>
> Result: Each step takes a few seconds and creates a message of about
> 150K characters.

Thanks for the recipe; I can reproduce the issue here, too.  I'm not
quite sure what the correct shortening would be here...  anybody got any
ideas?

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

Message #84 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Michael Heerdegen <michael_heerdegen <at> web.de>
To: Lars Ingebrigtsen <larsi <at> gnus.org>
Cc: Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>, Stefan Monnier <monnier <at> IRO.UMontreal.CA>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sat, 14 May 2022 05:57:07 +0200

Lars Ingebrigtsen <larsi <at> gnus.org> writes:

> Thanks for the recipe; I can reproduce the issue here, too.  I'm not
> quite sure what the correct shortening would be here...  anybody got any
> ideas?

Changing `edebug-print-level' helps... Maybe the default is too
large?

Michael.

Message #87 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Lars Ingebrigtsen <larsi <at> gnus.org>
To: Michael Heerdegen <michael_heerdegen <at> web.de>
Cc: Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>, Stefan Monnier <monnier <at> IRO.UMontreal.CA>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sat, 14 May 2022 13:35:39 +0200

Michael Heerdegen <michael_heerdegen <at> web.de> writes:

> Changing `edebug-print-level' helps... Maybe the default is too
> large?

Changing it to 20 doesn't seem to have much effect, but at 10, things
are pretty speedy.  The problem then is that the output is all dots:

Result: ((((((((((... ...) (... ...)) ((... ...) (... ...))) (((... ...) (... ...)) ((... ...) (... ...)))) ((((... ...) (... ...)) ((... ...) (... ...))) (((... ...) (... ...)) ((... ...) (... ...))))) (((((... ...) (... ...)) ((... ...) (... ...))) (((... ...) (... ...)) ((... ...) (... ...)))) ((((... ...) (... ...)) ((... ...) (... ...))) (((... ...) (... ...)) ((... ...) (... ...)))))) ((((((... ...) (... ...)) ((... ...) (... ...))) (((... ...) (... ...)) ((... ...) (... ...)))) ((((... ...) (... ...)) ((... ...) (... ...))) (((... ...) (... ...)) ((... ...) (... ...))))) (((((... ...) (... ...)) ((... ...) (... ...))) (((... 

It goes on like that for 6K.

I suspect that we need a better algorithm for identifying and dealing
with tree structures.  That is, if we determine that we're not really
printing a list, but a tree (that shouldn't be too difficult,
statistically), then edebug could flip a printing switch and do this...
differently.

(Hand-wavey details left as an exercise for the reader.) 

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

Message #90 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Stefan Monnier <monnier <at> iro.umontreal.ca>
To: Lars Ingebrigtsen <larsi <at> gnus.org>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>,
 Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sat, 14 May 2022 09:52:32 -0400

>> Changing `edebug-print-level' helps... Maybe the default is too
>> large?
> Changing it to 20 doesn't seem to have much effect, but at 10, things
> are pretty speedy.  The problem then is that the output is all dots:

How 'bout using a `print-char-length` limit after which we truncate?
The truncation could "respect trees" in the sense that we'd truncate

    (((a b c) (d e f) (g h k)))

to something like

    (((a b c) (d e ...) ...))

rather than to

    (((a b c) (d e ...

if the `print-char-length` is 14.

I suspect that with such a limit we should eliminate "all" performance
issues, because printing should then have a complexity
O(print-char-length) rather than O(sizeof(object)), except for the
`print--preprocess` part which would still be O(sizeof(object)), but
since that one is all written in C (and performs a lot less work) the
constant is such much lower that it rarely dominates.


        Stefan

Message #93 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Lars Ingebrigtsen <larsi <at> gnus.org>
To: Stefan Monnier <monnier <at> iro.umontreal.ca>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>,
 Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sat, 14 May 2022 17:45:01 +0200

Stefan Monnier <monnier <at> iro.umontreal.ca> writes:

> How 'bout using a `print-char-length` limit after which we truncate?
> The truncation could "respect trees" in the sense that we'd truncate
>
>     (((a b c) (d e f) (g h k)))
>
> to something like
>
>     (((a b c) (d e ...) ...))
>
> rather than to
>
>     (((a b c) (d e ...
>
> if the `print-char-length` is 14.
>
> I suspect that with such a limit we should eliminate "all" performance
> issues, because printing should then have a complexity
> O(print-char-length) rather than O(sizeof(object)), except for the
> `print--preprocess` part which would still be O(sizeof(object)), but
> since that one is all written in C (and performs a lot less work) the
> constant is such much lower that it rarely dominates.

Hm...  that sounds really attractive, I think.  I'm trying to think of
any circumstances I'd rather see the current print-length algo instead
of this one, and I'm coming up blank.  😀

The only issue is "oh no, not yet another printing variable" (that
people will be setting to 14 in ~/.emacs and then everything that does
`prin1' to write out data will fail).

I did suggest (in conjunction with another bug report in this area) that
we should just extend `prin1{,-to-string}' with a parameter that would
set (on the C level) an equivalent variable.  So we'd have
(prin1 object fun `((char-length . ,edebug-print-char-length)))
etc.  (And `t' would be "all defaults".)

Perhaps I should just implement that stuff first.

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

Message #96 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Stefan Monnier <monnier <at> iro.umontreal.ca>
To: Lars Ingebrigtsen <larsi <at> gnus.org>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>,
 Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sat, 14 May 2022 12:05:42 -0400

> The only issue is "oh no, not yet another printing variable" (that
> people will be setting to 14 in ~/.emacs and then everything that does
> `prin1' to write out data will fail).

As someone requested long ago, we should have some way to "reset" the
printing config context in a single step without having to mention
individually each and every var.

But maybe for this specific issue we could make it so
`print-char-length` is only obeyed by `cl-print` (and only when
`cl-print-readably` is nil) and not `prin1` (which is the function that
prints in a machine-readable way and should hence arguably never
truncate).

> I did suggest (in conjunction with another bug report in this area) that
> we should just extend `prin1{,-to-string}' with a parameter that would
> set (on the C level) an equivalent variable.  So we'd have
> (prin1 object fun `((char-length . ,edebug-print-char-length)))
> etc.  (And `t' would be "all defaults".)

Some kind of "print context" object would be good, indeed.
Being able to set/modify this context "at a distance" via dynamic
scoping is quite handy, tho, so we probably want to still support that
as well.

Here's an idea: a print context could include an `inherit` setting which
says whether to "keep looking for more settings from the context".
Then we printing we use settings from:
- the explicit context passed as arg (if present).
- the currently existing `print-<foo>` vars (if there isn't an explicit
  context arg whose `inherit` says not to do that).
We could even go crazy and add an intermediate step to check
a `print-context` var which contains such an object.


        Stefan

Message #99 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Lars Ingebrigtsen <larsi <at> gnus.org>
To: Stefan Monnier <monnier <at> iro.umontreal.ca>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>,
 Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sat, 14 May 2022 18:18:39 +0200

Stefan Monnier <monnier <at> iro.umontreal.ca> writes:

> But maybe for this specific issue we could make it so
> `print-char-length` is only obeyed by `cl-print` (and only when
> `cl-print-readably` is nil) and not `prin1` (which is the function that
> prints in a machine-readable way and should hence arguably never
> truncate).

Ah, yes, that's true...  it's not really that big a deal with the new
variable if we do it that way.

>> I did suggest (in conjunction with another bug report in this area) that
>> we should just extend `prin1{,-to-string}' with a parameter that would
>> set (on the C level) an equivalent variable.  So we'd have
>> (prin1 object fun `((char-length . ,edebug-print-char-length)))
>> etc.  (And `t' would be "all defaults".)
>
> Some kind of "print context" object would be good, indeed.
> Being able to set/modify this context "at a distance" via dynamic
> scoping is quite handy, tho, so we probably want to still support that
> as well.
>
> Here's an idea: a print context could include an `inherit` setting which
> says whether to "keep looking for more settings from the context".
> Then we printing we use settings from:
> - the explicit context passed as arg (if present).
> - the currently existing `print-<foo>` vars (if there isn't an explicit
>   context arg whose `inherit` says not to do that).
> We could even go crazy and add an intermediate step to check
> a `print-context` var which contains such an object.

I was thinking something along the lines of

(prin1 object nil '((depth . 4) (circle . t)))

to "bind" only those two, and t as a special value for "all the
defaults" (i.e., print-length/depth/etc to nil), but you can also mix
and match:

(prin1 object nil '(t (depth . 4) (circle . t)))

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

Message #102 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Lars Ingebrigtsen <larsi <at> gnus.org>
To: Stefan Monnier <monnier <at> iro.umontreal.ca>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>,
 Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sat, 14 May 2022 18:54:24 +0200

Lars Ingebrigtsen <larsi <at> gnus.org> writes:

> I was thinking something along the lines of
>
> (prin1 object nil '((depth . 4) (circle . t)))

OK, I've now done a rough implementation:

(let ((print-length 10))
  (prin1 (make-list 20 t) (current-buffer) t)
  nil)
(t t t t t t t t t t t t t t t t t t t t)

(let ((print-length 10))
  (prin1 (make-list 20 t) (current-buffer) '((length . 5)))
  nil)
(t t t t t ...)

Don't have time for more today, but I think this has promise.  And this
means that we can introduce more printer settings without introducing
more global dynamic variables.

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

Message #105 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Stefan Monnier <monnier <at> iro.umontreal.ca>
To: Lars Ingebrigtsen <larsi <at> gnus.org>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>,
 Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sat, 14 May 2022 14:55:52 -0400

> Don't have time for more today, but I think this has promise.  And this
> means that we can introduce more printer settings without introducing
> more global dynamic variables.

Not sure how to do it for `cl-print`, tho.  I suspect we'll end up
having to use dynamic vars internally otherwise it'll break the existing
signature of `cl-print-object` (we can't so easily add an optional arg
to a generic function).


        Stefan

Message #108 received at submit <at> debbugs.gnu.org (full text, mbox):

From: Rudolf Schlatte <rudi <at> constantly.at>
To: bug-gnu-emacs <at> gnu.org
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sun, 15 May 2022 09:47:27 +0200

Stefan Monnier via "Bug reports for GNU Emacs, the Swiss army knife of
text editors" <bug-gnu-emacs <at> gnu.org> writes:

>> The only issue is "oh no, not yet another printing variable" (that
>> people will be setting to 14 in ~/.emacs and then everything that does
>> `prin1' to write out data will fail).
>
> As someone requested long ago, we should have some way to "reset" the
> printing config context in a single step without having to mention
> individually each and every var.

Common Lisp uses with-standard-io-syntax for this purpose
(http://clhs.lisp.se/Body/m_w_std_.htm).

Message #111 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Lars Ingebrigtsen <larsi <at> gnus.org>
To: Stefan Monnier <monnier <at> iro.umontreal.ca>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>,
 Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sun, 15 May 2022 14:25:09 +0200

Stefan Monnier <monnier <at> iro.umontreal.ca> writes:

> Not sure how to do it for `cl-print`, tho.  I suspect we'll end up
> having to use dynamic vars internally otherwise it'll break the existing
> signature of `cl-print-object` (we can't so easily add an optional arg
> to a generic function).

Yes.

But this reminds me -- why do we have `cl-print' anyway?  Shouldn't the
C version handle printing things nicely?

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

Message #114 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Lars Ingebrigtsen <larsi <at> gnus.org>
To: Rudolf Schlatte <rudi <at> constantly.at>
Cc: 36566 <at> debbugs.gnu.org
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sun, 15 May 2022 14:28:54 +0200

Rudolf Schlatte <rudi <at> constantly.at> writes:

>> As someone requested long ago, we should have some way to "reset" the
>> printing config context in a single step without having to mention
>> individually each and every var.
>
> Common Lisp uses with-standard-io-syntax for this purpose
> (http://clhs.lisp.se/Body/m_w_std_.htm).

That would be OK, but doesn't help with the "setting non Lisp world
variables", and a parameter gives us both of these things.

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

Message #117 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Lars Ingebrigtsen <larsi <at> gnus.org>
To: Stefan Monnier <monnier <at> iro.umontreal.ca>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>,
 Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sun, 15 May 2022 15:33:05 +0200

I've now finished the implementation and pushed to the trunk.  It's not
really that relevant to this discussion since we're using cl-prin1
anyway, but anyway.

I wondered whether to keep the mapping variable all on the C side.  I
marked print--variable-mapping as a constant, but somebody may just
setcdr it anyway, so it's not really constant in any meaningful way, and
users shouldn't modify it.  But I thought it might be vaguely useful to
be able to inspect that variable so that it's less mysterious what's
happening.

But writing this, I think I'm changing my mind, and I think I may remove
that DEFVAR_LISP...  Hm.

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

Message #120 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Stefan Monnier <monnier <at> iro.umontreal.ca>
To: Lars Ingebrigtsen <larsi <at> gnus.org>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>,
 Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sun, 15 May 2022 12:13:19 -0400

Lars Ingebrigtsen [2022-05-15 14:25:09] wrote:
> Stefan Monnier <monnier <at> iro.umontreal.ca> writes:
>> Not sure how to do it for `cl-print`, tho.  I suspect we'll end up
>> having to use dynamic vars internally otherwise it'll break the existing
>> signature of `cl-print-object` (we can't so easily add an optional arg
>> to a generic function).
> Yes.
> But this reminds me -- why do we have `cl-print' anyway?

Because we want to let packages use `cl-defmethod` to provide their own
output syntax for their objects.

> Shouldn't the C version handle printing things nicely?

The C code doesn't really know about cl-defstructs (or advice objects).


        Stefan

Message #123 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Lars Ingebrigtsen <larsi <at> gnus.org>
To: Stefan Monnier <monnier <at> iro.umontreal.ca>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>,
 Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sun, 15 May 2022 18:25:11 +0200

Stefan Monnier <monnier <at> iro.umontreal.ca> writes:

>> But this reminds me -- why do we have `cl-print' anyway?
>
> Because we want to let packages use `cl-defmethod` to provide their own
> output syntax for their objects.
>
>> Shouldn't the C version handle printing things nicely?
>
> The C code doesn't really know about cl-defstructs (or advice objects).

Wouldn't it make sense to teach the C `prin1' about those (and also call
out to the Lisp level for the objects that have a specialised print
syntax)?  We've got something vaguely similar with
`print-unreadable-function', for instance.

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

Message #126 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Stefan Monnier <monnier <at> iro.umontreal.ca>
To: Lars Ingebrigtsen <larsi <at> gnus.org>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>,
 Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sun, 15 May 2022 12:52:44 -0400

Lars Ingebrigtsen [2022-05-15 18:25:11] wrote:
> Stefan Monnier <monnier <at> iro.umontreal.ca> writes:
>>> But this reminds me -- why do we have `cl-print' anyway?
>> Because we want to let packages use `cl-defmethod` to provide their own
>> output syntax for their objects.
>>> Shouldn't the C version handle printing things nicely?
>> The C code doesn't really know about cl-defstructs (or advice objects).
> Wouldn't it make sense to teach the C `prin1' about those (and also call
> out to the Lisp level for the objects that have a specialised print
> syntax)?

Maybe it would.  I tend to think we should focus the C code on printing
data quickly and in a `read`able way (i.e. in sync with `lread.c`) and
benefit from the comfort of ELisp for the implementation of the
human-readable version of the printout where performance is not as
important because we will truncate long outputs anyway.

> We've got something vaguely similar with `print-unreadable-function',
> for instance.

This var is bound to the notion of `read`able, not "human readable",
which is why it belong in the C code (because sadly not everything can
be printed in a `read`able way).


        Stefan

Message #129 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Lars Ingebrigtsen <larsi <at> gnus.org>
To: Stefan Monnier <monnier <at> iro.umontreal.ca>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>,
 Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Mon, 16 May 2022 03:00:45 +0200

Stefan Monnier <monnier <at> iro.umontreal.ca> writes:

> Maybe it would.  I tend to think we should focus the C code on printing
> data quickly and in a `read`able way (i.e. in sync with `lread.c`) and
> benefit from the comfort of ELisp for the implementation of the
> human-readable version of the printout where performance is not as
> important because we will truncate long outputs anyway.

Well, OK...  but why does edebug use cl-prin1 then when stepping through
code?  Stepping through code should be fast, and we don't really care
that much about the prettiness of the values were displaying then.

Using cl-prin1 would is fine in `edebug-eval-expression' etc, but I
don't quite see the point when stepping?

So if we use prin1 when stepping, we could implement `char-length'
purely as an OVERRIDE element, and not do that in cl-prin1.

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

Message #132 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Michael Heerdegen <michael_heerdegen <at> web.de>
To: Lars Ingebrigtsen <larsi <at> gnus.org>
Cc: Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Stefan Monnier <monnier <at> iro.umontreal.ca>, Noam Postavsky <npostavs <at> gmail.com>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Mon, 16 May 2022 03:39:55 +0200

Lars Ingebrigtsen <larsi <at> gnus.org> writes:

> Well, OK...  but why does edebug use cl-prin1 then when stepping through
> code?  Stepping through code should be fast, and we don't really care
> that much about the prettiness of the values were displaying then.
>
> Using cl-prin1 would is fine in `edebug-eval-expression' etc, but I
> don't quite see the point when stepping?

Especially in stepping I don't want to see the inwards, I want a
representation that is easy to grasp.

Michael.

Message #135 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Stefan Monnier <monnier <at> iro.umontreal.ca>
To: Lars Ingebrigtsen <larsi <at> gnus.org>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>,
 Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Sun, 15 May 2022 21:44:47 -0400

Lars Ingebrigtsen [2022-05-16 03:00:45] wrote:
> Stefan Monnier <monnier <at> iro.umontreal.ca> writes:
>> Maybe it would.  I tend to think we should focus the C code on printing
>> data quickly and in a `read`able way (i.e. in sync with `lread.c`) and
>> benefit from the comfort of ELisp for the implementation of the
>> human-readable version of the printout where performance is not as
>> important because we will truncate long outputs anyway.
> Well, OK...  but why does edebug use cl-prin1 then when stepping through
> code?

Because what is printed is intended to be read by a human rather than by `read`.

> Stepping through code should be fast, and we don't really care
> that much about the prettiness of the values were displaying then.

I think we do care to see closures printed in a human-understandable
way, for example.

And with a `char-length` constraint the output should always be fast.


        Stefan

Message #141 received at 36566 <at> debbugs.gnu.org (full text, mbox):

From: Lars Ingebrigtsen <larsi <at> gnus.org>
To: Stefan Monnier <monnier <at> iro.umontreal.ca>
Cc: Michael Heerdegen <michael_heerdegen <at> web.de>,
 Gemini Lasswell <gazally <at> runbox.com>, 36566 <at> debbugs.gnu.org,
 Noam Postavsky <npostavs <at> gmail.com>
Subject: Re: bug#36566: 27.0.50; debug is sometimes horribly slow
Date: Mon, 16 May 2022 14:11:13 +0200

Stefan Monnier <monnier <at> iro.umontreal.ca> writes:

>> Stepping through code should be fast, and we don't really care
>> that much about the prettiness of the values were displaying then.
>
> I think we do care to see closures printed in a human-understandable
> way, for example.
>
> And with a `char-length` constraint the output should always be fast.

Well, OK.  cl-prin1 could have its own Lisp variable for this, I
guess -- cl-print-char-length.

-- 
(domestic pets only, the antidote for overdose, milk.)
   bloggy blog: http://lars.ingebrigtsen.no

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.