bug#21077: 24.5; Slow printing in inferior python buffer with python-shell-enable-font-lock

bug#21077: 24.5; Slow printing in inferior python buffer with python-shell-enable-font-lock

[Ista Zahn]

From: Ista Zahn <istazahn@gmail.com>
To: bug-gnu-emacs@gnu.org
Subject: 24.5; Slow printing in inferior python buffer with
python-shell-enable-font-lock
--text follows this line--

1. Start emacs with 'emacs -Q'
2. Start inferior python process with 'M-x run-python'
3. Run 'print(list(range(9999)))' in the *Python* buffer

Result: emacs grinds to a halt and has to be killed.

Setting '(setq python-shell-enable-font-lock nil)' after step 1 fixes
the problem.

In GNU Emacs 24.5.1 (x86_64-unknown-linux-gnu, GTK+ Version 3.16.2)
 of 2015-04-20 on bitzer.hoetzel.info
Windowing system distributor `The X.Org Foundation', version 11.0.11702000
Configured using:
 `configure --prefix=/usr --sysconfdir=/etc --libexecdir=/usr/lib
 --localstatedir=/var --with-x-toolkit=gtk3 --with-xft
 'CFLAGS=-march=x86-64 -mtune=generic -O2 -pipe -fstack-protector-strong
 --param=ssp-buffer-size=4' CPPFLAGS=-D_FORTIFY_SOURCE=2
 LDFLAGS=-Wl,-O1,--sort-common,--as-needed,-z,relro'

Important settings:
  value of $LANG: en_US.UTF-8
  locale-coding-system: utf-8-unix

Major mode: Inferior Python

Minor modes in effect:
  compilation-shell-minor-mode: t
  tooltip-mode: t
  electric-indent-mode: t
  mouse-wheel-mode: t
  tool-bar-mode: t
  menu-bar-mode: t
  file-name-shadow-mode: t
  global-font-lock-mode: t
  font-lock-mode: t
  blink-cursor-mode: t
  auto-composition-mode: t
  auto-encryption-mode: t
  auto-compression-mode: t
  line-number-mode: t
  transient-mark-mode: t

Recent messages:
Making python-shell-interpreter local to *Python* while let-bound!
Making python-shell-interpreter-args local to *Python* while let-bound!
Sent python-shell-completion-setup-code
Sent python-ffap-setup-code
Sent python-eldoc-setup-code
Making completion list...
Quit
Type "q" in help window to restore its previous buffer.
You can run the command `describe-function' with C-h f
Type "q" in help window to restore its previous buffer.
command-execute: Command attempted to use minibuffer while in minibuffer

Load-path shadows:
None found.

Features:
(shadow sort gnus-util mail-extr emacsbug message format-spec rfc822 mml
mml-sec mm-decode mm-bodies mm-encode mail-parse rfc2231 mailabbrev
gmm-utils mailheader sendmail rfc2047 rfc2045 ietf-drums mm-util
mail-prsvr mail-utils help-fns help-mode compile cl-extra python
easymenu json comint ring cl-loaddefs cl-lib ansi-color time-date
tooltip electric uniquify ediff-hook vc-hooks lisp-float-type mwheel
x-win x-dnd tool-bar dnd fontset image regexp-opt fringe tabulated-list
newcomment lisp-mode prog-mode register page menu-bar rfn-eshadow timer
select scroll-bar mouse jit-lock font-lock syntax facemenu font-core
frame cham georgian utf-8-lang misc-lang vietnamese tibetan thai
tai-viet lao korean japanese hebrew greek romanian slovak czech european
ethiopic indian cyrillic chinese case-table epa-hook jka-cmpr-hook help
simple abbrev minibuffer nadvice loaddefs button faces cus-face macroexp
files text-properties overlay sha1 md5 base64 format env code-pages mule
custom widget hashtable-print-readable backquote make-network-process
dbusbind gfilenotify dynamic-setting system-font-setting
font-render-setting move-toolbar gtk x-toolkit x multi-tty emacs)

Memory information:
((conses 16 85167 7385)
 (symbols 48 19060 0)
 (miscs 40 66 149)
 (strings 32 12981 4007)
 (string-bytes 1 392970)
 (vectors 16 10694)
 (vector-slots 8 403996 7441)
 (floats 8 69 390)
 (intervals 56 271 19)
 (buffers 960 14)
 (heap 1024 41397 1140))

bug#21077: 24.5; Slow printing in inferior python buffer with python-shell-enable-font-lock

[Eli Zaretskii]

> From: Ista Zahn <istazahn@gmail.com>
> Date: Thu, 16 Jul 2015 12:42:39 -0400
> 
> 1. Start emacs with 'emacs -Q'
> 2. Start inferior python process with 'M-x run-python'
> 3. Run 'print(list(range(9999)))' in the *Python* buffer
> 
> Result: emacs grinds to a halt and has to be killed.

No, it doesn't: it just becomes very slow, and you need to wait longer
for it to finish.  In my case, it took a whopping 14 minutes, and
produced this in the *Messages* buffer:

  Error during redisplay: (jit-lock-function 52112) signaled (error "Stack overflow in regexp matcher")
  Error during redisplay: (jit-lock-function 56220) signaled (error "Stack overflow in regexp matcher")
  Error during redisplay: (jit-lock-function 57879) signaled (error "Stack overflow in regexp matcher")

bug#21077: 24.5; Slow printing in inferior python buffer with python-shell-enable-font-lock

[Ista Zahn]

On Thu, Jul 16, 2015 at 2:34 PM, Eli Zaretskii <eliz@gnu.org> wrote:
>> From: Ista Zahn <istazahn@gmail.com>
>> Date: Thu, 16 Jul 2015 12:42:39 -0400
>>
>> 1. Start emacs with 'emacs -Q'
>> 2. Start inferior python process with 'M-x run-python'
>> 3. Run 'print(list(range(9999)))' in the *Python* buffer
>>
>> Result: emacs grinds to a halt and has to be killed.
>
> No, it doesn't: it just becomes very slow, and you need to wait longer
> for it to finish.  In my case, it took a whopping 14 minutes,

Either way this is not good. Clearly there is something wrong here.
Nitpicking about whether it requires killing emacs or not doesn't seem
helpful to me.

--Ista

and
> produced this in the *Messages* buffer:
>
>   Error during redisplay: (jit-lock-function 52112) signaled (error "Stack overflow in regexp matcher")
>   Error during redisplay: (jit-lock-function 56220) signaled (error "Stack overflow in regexp matcher")
>   Error during redisplay: (jit-lock-function 57879) signaled (error "Stack overflow in regexp matcher")

bug#21077: 24.5; Slow printing in inferior python buffer with python-shell-enable-font-lock

[Eli Zaretskii]

> From: Ista Zahn <istazahn@gmail.com>
> Date: Thu, 16 Jul 2015 15:09:19 -0400
> Cc: 21077@debbugs.gnu.org
> 
> Either way this is not good. Clearly there is something wrong here.
> Nitpicking about whether it requires killing emacs or not doesn't seem
> helpful to me.

I thought I was doing fine by providing additional details about the
problem.  Now I'm beginning to think I maybe should have kept my mouth
shut.

bug#21077: 24.5; Slow printing in inferior python buffer with python-shell-enable-font-lock

[Ista Zahn]

On Thu, Jul 16, 2015 at 3:34 PM, Eli Zaretskii <eliz@gnu.org> wrote:
>> From: Ista Zahn <istazahn@gmail.com>
>> Date: Thu, 16 Jul 2015 15:09:19 -0400
>> Cc: 21077@debbugs.gnu.org
>>
>> Either way this is not good. Clearly there is something wrong here.
>> Nitpicking about whether it requires killing emacs or not doesn't seem
>> helpful to me.
>
> I thought I was doing fine by providing additional details about the
> problem.  Now I'm beginning to think I maybe should have kept my mouth
> shut.

I'm sorry, I came of sounding nasty there. I felt you were minimizing
the seriousness of the issue, which I see now may not have been your
intent. And even if it was there was no reason for me to be so
ill-tempered. So, my apologies.

Best,
Ista

bug#21077: 24.5; Slow printing in inferior python buffer with python-shell-enable-font-lock

[Eli Zaretskii]

> From: Ista Zahn <istazahn@gmail.com>
> Date: Thu, 16 Jul 2015 15:50:05 -0400
> Cc: 21077@debbugs.gnu.org
> 
> On Thu, Jul 16, 2015 at 3:34 PM, Eli Zaretskii <eliz@gnu.org> wrote:
> >> From: Ista Zahn <istazahn@gmail.com>
> >> Date: Thu, 16 Jul 2015 15:09:19 -0400
> >> Cc: 21077@debbugs.gnu.org
> >>
> >> Either way this is not good. Clearly there is something wrong here.
> >> Nitpicking about whether it requires killing emacs or not doesn't seem
> >> helpful to me.
> >
> > I thought I was doing fine by providing additional details about the
> > problem.  Now I'm beginning to think I maybe should have kept my mouth
> > shut.
> 
> I'm sorry, I came of sounding nasty there. I felt you were minimizing
> the seriousness of the issue, which I see now may not have been your
> intent.

It wasn't.  Something is clearly wrong with the regexps involved in
this recipe, at least.

> And even if it was there was no reason for me to be so
> ill-tempered. So, my apologies.

No sweat.  Misunderstandings happen.

bug#21077: 24.5; Slow printing in inferior python buffer with python-shell-enable-font-lock

[Stefan Monnier]

> It wasn't.  Something is clearly wrong with the regexps involved in
> this recipe, at least.

The trigger is simple and a well-known problem in Emacs: the command you
pass to Python outputs one very long line, and Emacs assumes at various places
that lines aren't too long.  One such assumption is in font-lock itself,
another appears to be in one of the regexps used in the font-lock config
of inferior python mode.


        Stefan

bug#21077: 24.5; Slow printing in inferior python buffer with python-shell-enable-font-lock

[Rasmus]

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

>> It wasn't.  Something is clearly wrong with the regexps involved in
>> this recipe, at least.
>
> The trigger is simple and a well-known problem in Emacs: the command you
> pass to Python outputs one very long line, and Emacs assumes at various places
> that lines aren't too long.  One such assumption is in font-lock itself,
> another appears to be in one of the regexps used in the font-lock config
> of inferior python mode.

The problem is also very much present in the R interface provided by ESS.

The R package data.table has a pretty good solution to long output IMO.
E.g.

R> data.table(x=1:1000000)
                x
       1:       1
       2:       2
       3:       3
       4:       4
       5:       5
      ---        
  999996:  999996
  999997:  999997
  999998:  999998
  999999:  999999
 1000000: 1000000

As I remember Python Pandas does something similar.

Would it be feasible to implement a generalized version of cutting output
for comint-like output if exceeding N lines?

Rasmus

-- 
Warning: Everything saved will be lost

bug#21077: 24.5; Slow printing in inferior python buffer with python-shell-enable-font-lock

[Ista Zahn]

On Fri, Jul 17, 2015 at 4:33 AM, Stefan Monnier
<monnier@iro.umontreal.ca> wrote:
>> It wasn't.  Something is clearly wrong with the regexps involved in
>> this recipe, at least.
>
> The trigger is simple and a well-known problem in Emacs: the command you
> pass to Python outputs one very long line, and Emacs assumes at various places
> that lines aren't too long.  One such assumption is in font-lock itself,
> another appears to be in one of the regexps used in the font-lock config
> of inferior python mode.

Sorry for the delay in responding. I think a reasonable short term
measure is to set python-shell-enable-font-lock to nil by default, and
perhaps add a warning to the doc string to the effect that setting it
to a non-nil value can dramatically slow down printing.

Best,
Ista



>
>
>         Stefan

bug#21077: 24.5; Slow printing in inferior python buffer with python-shell-enable-font-lock

[Stefan Monnier]

> Sorry for the delay in responding. I think a reasonable short term
> measure is to set python-shell-enable-font-lock to nil by default, and
> perhaps add a warning to the doc string to the effect that setting it
> to a non-nil value can dramatically slow down printing.

As mentioned, font-lock is but one of the parts of Emacs that slow down
as lines get longer.

In the case of comint modes, rather than disable font-lock we should
refrain from font-locking the text after the last \n (since that's the
line that keeps getting expanded, so we end up re-font-locking it O(N)
times for a line of length N, for a total amount of work of O(N^2)).
IIRC I have a similar hack in grep.el or compile.el.


        Stefan

bug#21077: 24.5; Slow printing in inferior python buffer with python-shell-enable-font-lock

[Ista Zahn]

[-- Attachment #1: Type: text/plain, Size: 1264 bytes --]

On Jul 30, 2015 7:19 PM, "Stefan Monnier" <monnier@iro.umontreal.ca> wrote:
>
> > Sorry for the delay in responding. I think a reasonable short term
> > measure is to set python-shell-enable-font-lock to nil by default, and
> > perhaps add a warning to the doc string to the effect that setting it
> > to a non-nil value can dramatically slow down printing.
>
> As mentioned, font-lock is but one of the parts of Emacs that slow down
> as lines get longer.

python-shell-enable-font-lock is the only place I've encountered were
things become unusable. I'm not all that concerned with things slowing down
slightly, but I do think the cases (like this one) that render emacs
unusable need to be fixed or worked around.
>
> In the case of comint modes, rather than disable font-lock we should
> refrain from font-locking the text after the last \n (since that's the
> line that keeps getting expanded, so we end up re-font-locking it O(N)
> times for a line of length N, for a total amount of work of O(N^2)).
> IIRC I have a similar hack in grep.el or compile.el.

OK, but unless there are clear plans to fix this soon the default value of
python-shell-enable-font-lock should be changed to nil until such time as a
fix is in place.

Best,
Ista
>
>
>         Stefan

[-- Attachment #2: Type: text/html, Size: 1578 bytes --]

bug#21077: 24.5; Slow printing in inferior python buffer with python-shell-enable-font-lock

[Stefan Monnier]

>> As mentioned, font-lock is but one of the parts of Emacs that slow down
>> as lines get longer.
> I'm not all that concerned with things slowing down slightly,

Neither am I.  All the others I care about also end up rendering
Emacs unusable.  They just show up at different times, or start biting
you at different line lengths.

>> In the case of comint modes, rather than disable font-lock we should
>> refrain from font-locking the text after the last \n (since that's the
>> line that keeps getting expanded, so we end up re-font-locking it O(N)
>> times for a line of length N, for a total amount of work of O(N^2)).
>> IIRC I have a similar hack in grep.el or compile.el.
> OK, but unless there are clear plans to fix this soon the default value of
> python-shell-enable-font-lock should be changed to nil until such time as a
> fix is in place.

I disagree.  All comint modes suffer from this problem, AFAIK, and
I don't see why Python programs would be more likely to generate long
lines than programs in other languages.

But yes, I'd really be happy to see some tentative patch along the lines
I outlined above.


        Stefan

bug#21077: 24.5; Slow printing in inferior python buffer with python-shell-enable-font-lock

[Ista Zahn]

On Fri, Jul 31, 2015 at 6:07 PM, Stefan Monnier
<monnier@iro.umontreal.ca> wrote:
>>> As mentioned, font-lock is but one of the parts of Emacs that slow down
>>> as lines get longer.
>> I'm not all that concerned with things slowing down slightly,
>
> Neither am I.  All the others I care about also end up rendering
> Emacs unusable.  They just show up at different times, or start biting
> you at different line lengths.
>
>>> In the case of comint modes, rather than disable font-lock we should
>>> refrain from font-locking the text after the last \n (since that's the
>>> line that keeps getting expanded, so we end up re-font-locking it O(N)
>>> times for a line of length N, for a total amount of work of O(N^2)).
>>> IIRC I have a similar hack in grep.el or compile.el.
>> OK, but unless there are clear plans to fix this soon the default value of
>> python-shell-enable-font-lock should be changed to nil until such time as a
>> fix is in place.
>
> I disagree.  All comint modes suffer from this problem, AFAIK, and
> I don't see why Python programs would be more likely to generate long
> lines than programs in other languages.

Try this with the currently released version of emacs:

1. Start emacs with 'emacs -Q'
2. Type 'M-x ielm' then '(number-sequence 1 9999)'
3. Type 'M-x eshell' then 'number-sequence 1 9999 RET'
4. Type 'M-x shell' then 'python -c "print(list(range(9999)))" RET'
5. Type 'M-x run-python' then 'print(list(range(9999))) RET'

For me 1-3 print relatively quickly, 4 prints relatively slowly, and
_only_ 5 is so slow that I consider it non-functional. This bug report
is about issue 5 above.

Of course if you have a patch to make 4 faster as well that's great.
But 5 is the bug I'm reporting here, and I would really appreciate it
someone would either accept my suggestion for fixing it or provide an
alternative fix that does the job better.

Best,
Ista



>
> But yes, I'd really be happy to see some tentative patch along the lines
> I outlined above.
>
>
>         Stefan

bug#21077: 24.5; Slow printing in inferior python buffer with python-shell-enable-font-lock

[Wolfgang Jenkner]

On Fri, Jul 31 2015, Ista Zahn wrote:

> 1. Start emacs with 'emacs -Q'
> 2. Type 'M-x ielm' then '(number-sequence 1 9999)'
> 3. Type 'M-x eshell' then 'number-sequence 1 9999 RET'
> 4. Type 'M-x shell' then 'python -c "print(list(range(9999)))" RET'
> 5. Type 'M-x run-python' then 'print(list(range(9999))) RET'
>
> For me 1-3 print relatively quickly, 4 prints relatively slowly, and
> _only_ 5 is so slow that I consider it non-functional. This bug report
> is about issue 5 above.

I tested this with the current (bdd370b) vanilla emacs -Q master and
also a slightly older (78c3e14, not quite vanilla) version and I find
that 5 takes about 20 seconds while 4 takes about 30 seconds to print
the whole list (and the next prompt).  So, the reason for the behaviour
you reported (and Eli confirmed) might be elsewhere than in
font-locking?

I compiled emacs with

./configure --prefix=/usr/opt --with-x --with-x-toolkit=no --without-rsvg --without-cairo --without-gsettings --with-file-notification=no --without-compress-install

and the beginning of the python buffer is

Python 2.7.10 (default, Jul  4 2015, 12:57:42) 
[GCC 4.2.1 Compatible FreeBSD Clang 3.4.1 (tags/RELEASE_34/dot1-final 208032)] on freebsd10
Type "help", "copyright", "credits" or "license" for more information.
>>> python.el: readline is available
>>> python.el: sent setup code
>>> print(list(range(9999)))

I've also a ~/.pythonrc.py which contains

import rlcompleter, readline
readline.parse_and_bind('tab: complete')

bug#21077: 24.5; Slow printing in inferior python buffer with python-shell-enable-font-lock

[Wolfgang Jenkner]

On Thu, Jul 30 2015, Stefan Monnier wrote:

> In the case of comint modes, rather than disable font-lock we should
> refrain from font-locking the text after the last \n (since that's the
> line that keeps getting expanded, so we end up re-font-locking it O(N)
> times for a line of length N, for a total amount of work of O(N^2)).
> IIRC I have a similar hack in grep.el or compile.el.

But comint-output-filter does

(font-lock-prepend-text-property prompt-start (point)
					       'font-lock-face
					       'comint-highlight-prompt)

So keyword fontification seems to be inhibited anyway.  Is this done in
a particularly inefficient way?

Wolfgang (who ought to go read the source)

bug#21077: 24.5; Slow printing in inferior python buffer with python-shell-enable-font-lock

[Ista Zahn]

On Sat, Aug 1, 2015 at 8:36 AM, Wolfgang Jenkner <wjenkner@inode.at> wrote:
> On Fri, Jul 31 2015, Ista Zahn wrote:
>
>> 1. Start emacs with 'emacs -Q'
>> 2. Type 'M-x ielm' then '(number-sequence 1 9999)'
>> 3. Type 'M-x eshell' then 'number-sequence 1 9999 RET'
>> 4. Type 'M-x shell' then 'python -c "print(list(range(9999)))" RET'
>> 5. Type 'M-x run-python' then 'print(list(range(9999))) RET'
>>
>> For me 1-3 print relatively quickly, 4 prints relatively slowly, and
>> _only_ 5 is so slow that I consider it non-functional. This bug report
>> is about issue 5 above.
>
> I tested this with the current (bdd370b) vanilla emacs -Q master and
> also a slightly older (78c3e14, not quite vanilla) version and I find
> that 5 takes about 20 seconds while 4 takes about 30 seconds to print
> the whole list (and the next prompt).  So, the reason for the behaviour
> you reported (and Eli confirmed) might be elsewhere than in
> font-locking?

This bug report is against emacs 24.5; I think you'll find very
different results there.

Nevertheless it is good to know that things are improved in recent
development versions; I have confirmed that this is true on my system
as well. So at least we can look forward to this being fixed in the
25.0 release. I'm not sure when that is expected, but unless it is
expected to be released soon I think it would be a good idea to
backport a fix to 24.5.

Best,

>
> I compiled emacs with
>
> ./configure --prefix=/usr/opt --with-x --with-x-toolkit=no --without-rsvg --without-cairo --without-gsettings --with-file-notification=no --without-compress-install
>
> and the beginning of the python buffer is
>
> Python 2.7.10 (default, Jul  4 2015, 12:57:42)
> [GCC 4.2.1 Compatible FreeBSD Clang 3.4.1 (tags/RELEASE_34/dot1-final 208032)] on freebsd10
> Type "help", "copyright", "credits" or "license" for more information.
>>>> python.el: readline is available
>>>> python.el: sent setup code
>>>> print(list(range(9999)))
>
> I've also a ~/.pythonrc.py which contains
>
> import rlcompleter, readline
> readline.parse_and_bind('tab: complete')

bug#21077: 24.5; Slow printing in inferior python buffer with python-shell-enable-font-lock

[Stefan Monnier]

>> In the case of comint modes, rather than disable font-lock we should
>> refrain from font-locking the text after the last \n (since that's the
>> line that keeps getting expanded, so we end up re-font-locking it O(N)
>> times for a line of length N, for a total amount of work of O(N^2)).
>> IIRC I have a similar hack in grep.el or compile.el.

> But comint-output-filter does

> (font-lock-prepend-text-property prompt-start (point)
> 					       'font-lock-face
> 					       'comint-highlight-prompt)

> So keyword fontification seems to be inhibited anyway.  Is this done in
> a particularly inefficient way?

That doesn't inhibit keyword fontification per se.  It just makes most
keyword rules ineffective, but the test is done after the hard work
anyway, so in a way yes, it's done in an inefficient way (tho skipping
some keywords by checking font-lock-face would in general be
even more inefficient).


        Stefan

bug#21077: 24.5; Slow printing in inferior python buffer with python-shell-enable-font-lock

[Wolfgang Jenkner]

On Sat, Aug 01 2015, Ista Zahn wrote:

> Nevertheless it is good to know that things are improved in recent
> development versions;

For the record, this bug was previously discussed in bug#16875

http://debbugs.gnu.org/cgi/bugreport.cgi?bug=16875

and the author of python.el fixed it in 60cc81a

Date:   Sat Jul 26 20:43:51 2014 -0300

    Robust shell syntax highlighting.  (Bug#18084, Bug#16875)

and the following commits.

bug#21077: 24.5; Slow printing in inferior python buffer with python-shell-enable-font-lock

[npostavs]

tags 21077 fixed
close 21077 25.1
quit

Ista Zahn <istazahn@gmail.com> writes:
>
> This bug report is against emacs 24.5; I think you'll find very
> different results there.
>
> Nevertheless it is good to know that things are improved in recent
> development versions; I have confirmed that this is true on my system
> as well. So at least we can look forward to this being fixed in the
> 25.0 release. I'm not sure when that is expected, but unless it is
> expected to be released soon I think it would be a good idea to
> backport a fix to 24.5.

Emacs 24.5 is not being maintained (i.e., there will be no 24.6), so I'm
closing this bug report.