bug#16875: python, comint-mode: Large output makes Emacs freeze

bug#16875: python, comint-mode: Large output makes Emacs freeze

[Andreas Röhler]

May confirm what is reported here:

http://stackoverflow.com/questions/20128425/can-i-stop-the-repl-locking-up-when-using-emacs-and-python

Form sent is

[[[False] * 200 for i in range(3)] for j in range(200)]

Does only occur with plain Python-shell, not if IPython is running.

IIUC that's because IPython return is passed through a kind of pretty-print, inserting newlines.

Comints dealing with long lines seems the cause.

With process-send-string it works.

bug#16875: python, comint-mode: Large output makes Emacs freeze

[Fabián Ezequiel Gallina]

This looks related to:
http://debbugs.gnu.org/cgi/bugreport.cgi?bug=13675

Some ways to attenuate irresponsiveness:

1. Disable python shell font-locking:
   (setq python-shell-enable-font-lock nil)

2. Use Python's pprint to print such expressions, this makes it behave
   pretty much like iPython:

        >>> import pprint
        >>> pprint.pprint([[[False] * 200 for i in range(3)] for j in range(200)])

From the python.el side there's not much we can do.



Fabián

bug#16875: python, comint-mode: Large output makes Emacs freeze

[Andreas Röhler]

On 25.06.2014 03:19, Fabián Ezequiel Gallina wrote:
>
> This looks related to:
> http://debbugs.gnu.org/cgi/bugreport.cgi?bug=13675
>

To a certain extend.
There some more operations done by comint, which aren't needed when executing Python code from source but may slow down it.

Thus solution in python-mode.el is to surpass comint-mode completely and use "start-process" and "process-send-string"

See py-fast-process.

> Some ways to attenuate irresponsiveness:
>
> 1. Disable python shell font-locking:
>     (setq python-shell-enable-font-lock nil)
>
> 2. Use Python's pprint to print such expressions, this makes it behave
>     pretty much like iPython:
>
>          >>> import pprint
>          >>> pprint.pprint([[[False] * 200 for i in range(3)] for j in range(200)])
>

Indeed, "pprint" should solve it already. Maybe make that the default? IMO looks better anyway.

Andreas

bug#16875: python, comint-mode: Large output makes Emacs freeze

[Stefan Monnier]

>> http://debbugs.gnu.org/cgi/bugreport.cgi?bug=13675
> To a certain extend.
> There some more operations done by comint, which aren't needed when
> executing Python code from source but may slow down it.

I expect the main slowdown comes from font-lock.  But indeed, it''d be
good to try and profile it to see where the time is spent.

Last time I tried to speed up M-x grep, I changed compile.el so that it
only processes (font-lock and friends) the output up to the last \n.
This way, when a very long line is received in 100 chunks, it doesn't
get re-processed 100 times.

Maybe comint.el could do the same (especially since it already assumes
that "text between the last \n and EOB is a prompt").

> Thus solution in python-mode.el is to surpass comint-mode completely and use
> "start-process" and "process-send-string"

If the problem is really in "unneeded comint functionality" (or call it
"bloat"), that's an option, but of course if we don't know where the
performance problem comes, we may end up with the same problem anyway.

> Indeed, "pprint" should solve it already. Maybe make that the default?
> IMO looks better anyway.

[ I don't use Python, so I don't have an opinion on that, but if it
  works, fine by me.  ]

Maybe comint.el could also be changed so that it "wraps" lines if they
get past some arbitrary maximum length (like 10K chars, for example).
It wouldn't be a great solution, but if the performance sucks really bad
past 10K chars, wrapping the line might be a lesser evil.


        Stefan

bug#16875: python, comint-mode: Large output makes Emacs freeze

[Andreas Röhler]

On 25.06.2014 16:26, Stefan Monnier wrote:
[ ... ]
> Maybe comint.el could also be changed so that it "wraps" lines if they
> get past some arbitrary maximum length (like 10K chars, for example).
> It wouldn't be a great solution, but if the performance sucks really bad
> past 10K chars, wrapping the line might be a lesser evil.
>
>
>          Stefan
>

Sounds promising, thanks! As comint is built for human interaction, readability of output matters.

Andreas

bug#16875: python, comint-mode: Large output makes Emacs freeze

[Fabián Ezequiel Gallina]

Andreas Röhler <andreas.roehler@easy-emacs.de> writes:

>> Indeed, "pprint" should solve it already. Maybe make that the default?
>> IMO looks better anyway.

That's changing the Python shell default behavior and I that's out of
the scope of python.el.

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

>>> http://debbugs.gnu.org/cgi/bugreport.cgi?bug=13675
>> To a certain extend.
>> There some more operations done by comint, which aren't needed when
>> executing Python code from source but may slow down it.
>
> I expect the main slowdown comes from font-lock.  But indeed, it''d be
> good to try and profile it to see where the time is spent.
>

From profiling, a lot of time spent on font-locking while another bunch
is spent at `comint-postoutput-scroll-to-bottom' (default member of
`comint-output-filter-functions').

After disabling both, the output is sent pretty quickly and Emacs, while
it's a bit slower, it's still responsive.

WRT the font-lock slowness I must say I'm not happy the way it's
implemented, there should be a better way to just fontify the text after
the current prompt.  That should avoid any extreme fontification cases.

>
> If the problem is really in "unneeded comint functionality" (or call it
> "bloat"), that's an option, but of course if we don't know where the
> performance problem comes, we may end up with the same problem anyway.
>

Now about the `comint-postoutput-scroll-to-bottom', this alone can also
make Emacs be extremely irresponsive (pretty much like with the
font-locking enabled).  The real culprit of it's slowness is `recenter'
function which seems to get really slow with long lines.  Here are the
elp-results with font-lock disabled (with a smaller sample of output):

comint-output-filter                             103         29.795948749  0.2892810558
comint-postoutput-scroll-to-bottom               104         28.636891969  0.2753547304
recenter                                         104         28.635311547  0.2753395341
python-pdbtrack-comint-output-filter-function    104         0.990129131   0.0095204724
comint-watch-for-password-prompt                 104         0.0924025480  0.0008884860

> Maybe comint.el could also be changed so that it "wraps" lines if they
> get past some arbitrary maximum length (like 10K chars, for example).
> It wouldn't be a great solution, but if the performance sucks really bad
> past 10K chars, wrapping the line might be a lesser evil.
>

Disabling font-lock and avoiding the `recenter' calls works pretty well,
so I rather focus on improving those than modifying comint to workaround
this.

As a final related note, to avoid unnecessary filters, I think the
`inferior-python-mode' should set the `comint-output-filter-functions'
to a minimum and point users to append custom desired filters using the
`inferior-python-mode-hook'.



Regards,
Fabián

bug#16875: python, comint-mode: Large output makes Emacs freeze

[Andreas Röhler]

On 21.07.2014 00:27, Fabián Ezequiel Gallina wrote:
>
[ ... ]
> Disabling font-lock and avoiding the `recenter' calls works pretty well,
> so I rather focus on improving those than modifying comint to workaround
> this.
>

Given font-locking is an issue only when triggered while output arrives, maybe there is a way to disable it alongside with RET, but enabling it as soon no output is pending?

Andreas

bug#16875: python, comint-mode: Large output makes Emacs freeze

[Fabián Ezequiel Gallina]

Fixed in revno 117582 in trunk

Emacs is still slow, but at least responds to commands.  I feel that
everything that could be optimized on the comint side is pretty much
there and that the slowness being experienced is in fact related to the
long-lines slowness bug mentioned before[0].

Here's the current output for elp-results:

    comint-output-filter                                  206         3.5420630980  0.0171944810
    python-pdbtrack-comint-output-filter-function         207         2.5283979559  0.0122144828
    ansi-color-filter-apply                               618         1.5662161150  0.0025343302
    python-comint-postoutput-scroll-to-bottom             207         0.400739811   0.0019359411
    comint-postoutput-scroll-to-bottom                    1           0.365398304   0.365398304
    recenter                                              1           0.365378877   0.365378877
    python-shell-comint-end-of-output-p                   412         0.0554427629  0.0001345698
    python-shell-font-lock-comint-output-filter-function  207         0.032279105   0.0001559377
    ansi-color-process-output                             207         0.0107249640  5.181...e-05
    ansi-color-apply-on-region                            207         0.0098468030  4.756...e-05
    comint-carriage-motion                                206         0.0014299259  6.941...e-06
    python-shell-font-lock-post-command-hook              3           0.00034127    0.0001137566
    process-mark                                          828         0.000202256   2.442...e-07
    process-kill-buffer-query-function                    206         0.0001694799  8.227...e-07
    comint-send-input                                     1           0.000149412   0.000149412
    ansi-color--find-face                                 207         8.6848e-05    4.195...e-07
    process-status                                        208         7.752...e-05  3.727...e-07
    process-buffer                                        207         7.367...e-05  3.558...e-07
    ansi-color-apply-overlay-face                         207         6.695...e-05  3.234...e-07
    python-util-text-properties-replace-name              1           4.8394e-05    4.8394e-05
    comint-simple-send                                    1           3.8879e-05    3.8879e-05
    python-shell-font-lock-cleanup-buffer                 1           2.344e-05     2.344e-05
    comint-send-string                                    1           2.2201e-05    2.2201e-05
    process-send-string                                   1           1.5571e-05    1.5571e-05
    comint-add-to-input-history                           1           1.2823e-05    1.2823e-05
    comint-adjust-window-point                            1           4.201e-06     4.201e-06
    comint-preinput-scroll-to-bottom                      3           2.708e-06     9.026...e-07
    python-util-comint-last-prompt                        6           2.490...e-06  4.150...e-07
    comint-snapshot-last-prompt                           2           2.462e-06     1.231e-06


[0] http://debbugs.gnu.org/cgi/bugreport.cgi?bug=13675


Cheers,
Fabián

bug#16875: python, comint-mode: Large output makes Emacs freeze

[Eli Zaretskii]

> From: fgallina@gnu.org (Fabián Ezequiel Gallina)
> Date: Sat, 26 Jul 2014 23:22:41 -0300
> 
> 
> Emacs is still slow, but at least responds to commands.  I feel that
> everything that could be optimized on the comint side is pretty much
> there and that the slowness being experienced is in fact related to the
> long-lines slowness bug mentioned before[0].

That bug is about displaying long lines.  Is the code that is slow
involved in displaying such lines?  If there's no display involved,
then the discussion you point to is not relevant.

Also, please tell how long are your lines, on the average.

bug#16875: python, comint-mode: Large output makes Emacs freeze

[Stefan Monnier]

> Emacs is still slow, but at least responds to commands.  I feel that
> everything that could be optimized on the comint side is pretty much
> there and that the slowness being experienced is in fact related to the
> long-lines slowness bug mentioned before[0].

Have you tried to ensure that font-lock is only applied once a line is
complete (i.e. after seeing the corresponding \n)?


        Stefan

bug#16875: python, comint-mode: Large output makes Emacs freeze

[Fabián Ezequiel Gallina]

Eli Zaretskii <eliz@gnu.org> writes:

>> From: fgallina@gnu.org (Fabián Ezequiel Gallina)
>> Date: Sat, 26 Jul 2014 23:22:41 -0300
>> 
>> 
>> Emacs is still slow, but at least responds to commands.  I feel that
>> everything that could be optimized on the comint side is pretty much
>> there and that the slowness being experienced is in fact related to the
>> long-lines slowness bug mentioned before[0].
>
> That bug is about displaying long lines.  Is the code that is slow
> involved in displaying such lines?  If there's no display involved,
> then the discussion you point to is not relevant.
>
> Also, please tell how long are your lines, on the average.
>

Yes, such code outputs a long line consisting of 841601 chars.

One way to get that output in a file for testing is executing the
following shell command:

    python -c 'print ([[[False] * 200 for i in range(3)] for j in range(200)])' > /tmp/out.log

Even opening that file in fundamental-mode makes Emacs slow.  For
instance calling `previous-line' from the end of buffer several times
takes 1.1 seconds on average to complete.

    previous-line  30          33.263101639  1.1087700546

Next line is a bit more responsive though:

    next-line      30          14.028573178  0.4676191059

Operations seem to take longer and longer as point moves away from the
beginning of buffer.


Cheers,
Fabián

bug#16875: python, comint-mode: Large output makes Emacs freeze

[Eli Zaretskii]

> From: fgallina@gnu.org (Fabián Ezequiel Gallina)
> Cc: 16875@debbugs.gnu.org,  andreas.roehler@easy-emacs.de
> Date: Mon, 28 Jul 2014 18:35:09 -0300
> 
> Eli Zaretskii <eliz@gnu.org> writes:
> 
> >> From: fgallina@gnu.org (Fabián Ezequiel Gallina)
> >> Date: Sat, 26 Jul 2014 23:22:41 -0300
> >> 
> >> 
> >> Emacs is still slow, but at least responds to commands.  I feel that
> >> everything that could be optimized on the comint side is pretty much
> >> there and that the slowness being experienced is in fact related to the
> >> long-lines slowness bug mentioned before[0].
> >
> > That bug is about displaying long lines.  Is the code that is slow
> > involved in displaying such lines?  If there's no display involved,
> > then the discussion you point to is not relevant.
> >
> > Also, please tell how long are your lines, on the average.
> >
> 
> Yes, such code outputs a long line consisting of 841601 chars.

In that case, yes, that's the "long line display slowness" problem.
If you profile Emacs with 'profiler-start' and 'profiler-report', you
should see that most of the time is spent in redisplay.

> Operations seem to take longer and longer as point moves away from the
> beginning of buffer.

That's expected, although the time should level out after some number
of lines.