Re: Excessive redisplay from lots of process output

[Spencer Baugh]

On Fri, Feb 24, 2023 at 2:34 PM Eli Zaretskii <eliz@gnu.org> wrote:
>
> > From: Spencer Baugh <sbaugh@janestreet.com>
> > Date: Fri, 24 Feb 2023 14:14:55 -0500
> > Cc: emacs-devel@gnu.org,
> >   azeng@janestreet.com
> >
> > On Fri, Feb 17, 2023 at 11:06 AM Eli Zaretskii <eliz@gnu.org> wrote:
> > >
> > > > From: Spencer Baugh <sbaugh@janestreet.com>
> > > > Cc: azeng@janestreet.com
> > > > Date: Fri, 17 Feb 2023 10:16:11 -0500
> > > >
> > > > Emacs calls redisplay every time it reads process output.  This causes
> > > > Emacs to become painfully slow when these two conditions are met:
> > > >
> > > > - When redisplay is expensive (e.g. when using ssh X forwarding)
> > > >
> > > > - And when there is frequent process output, say hundreds or thousands
> > > >   of times a second (e.g. ERC receiving network traffic, shells
> > > >   running commands which log heavily, other things which run in the
> > > >   background)
> > >
> > > This cannot be the whole story, because usually redisplay exits almost
> > > immediately after being called, having determined that nothing needs
> > > to be changed on display.
> > >
> > > So the important part of your situation that you didn't disclose is:
> > > why does Emacs in your case perform the expensive redisplay each time
> > > redisplay is entered?  Can you figure that out by stepping through
> > > redisplay_internal?  (Let me know if you need guidance.)
> >
> > Actually, I'm looking a bit more into it, and I think there is still
> > some issue causing excessive X traffic when there's lots of process
> > output to be read.  On emacs -Q with Emacs 28, flush_frame/XFlush is
> > called on every redisplay, and does seem to be actually writing X
> > requests on the X socket every time.
> >
> > Here's a backtrace of where flush_frame/XFlush is being called from:
> >
> > #0  0x00007ffff4abc5c0 in XFlush () at /lib64/libX11.so.6
> > #1  0x00000000004d23d6 in x_flush (f=<optimized out>) at xterm.c:250
> > #2  0x00000000004d2416 in x_flip_and_flush (f=0xf956d0) at xterm.c:246
> > #3  0x00000000004d2416 in x_flip_and_flush (f=0xf956d0) at xterm.c:1230
> > #4  0x0000000000461374 in redisplay_preserve_echo_area (f=<optimized
> > out>) at frame.h:1700
> > #5  0x0000000000461374 in redisplay_preserve_echo_area
> > (from_where=from_where@entry=12) at xdisp.c:16527
> > #6  0x00000000005bee33 in wait_reading_process_output
> > (time_limit=time_limit@entry=0, nsecs=nsecs@entry=0,
> > read_kbd=read_kbd@entry=-1, do_display=true,
> > wait_for_cell=wait_for_cell@entry=0x0, wait_proc=wait_proc@entry=0x0,
> > just_wait_proc=just_wait_proc@entry=0) at process.c:5808
> > #7  0x000000000050aea4 in read_char (end_time=0x0,
> > used_mouse_menu=0x7fffffffda5b, kbp=<synthetic pointer>) at
> > keyboard.c:3926
> > #8  0x000000000050aea4 in read_char (used_mouse_menu=<optimized out>,
> > local_getcjmp=<optimized out>, end_time=<optimized out>) at
> > keyboard.c:2198
> > #9  0x000000000050aea4 in read_char (used_mouse_menu=<optimized out>,
> > prev_event=<optimized out>, local_getcjmp=<optimized out>,
> > end_time=<optimized out>) at keyboard.c:2261
> > #10 0x000000000050aea4 in read_char (commandflag=commandflag@entry=1,
> > map=map@entry=0x127fed3, prev_event=<optimized out>,
> > used_mouse_menu=used_mouse_menu@entry=0x7fffffffda5b,
> > end_time=end_time@entry=0x0) at keyboard.c:2892
> > #11 0x000000000050cc5e in read_key_sequence
> > (keybuf=keybuf@entry=0x7fffffffdb60, prompt=prompt@entry=0x0,
> > dont_downcase_last=dont_downcase_last@entry=false,
> > can_return_switch_frame=can_return_switch_frame@entry=true,
> > fix_current_buffer=fix_current_buffer@entry=true,
> > prevent_redisplay=prevent_redisplay@entry=false) at keyboard.c:9635
> > #12 0x000000000050e390 in command_loop_1 () at keyboard.c:1392
> > #13 0x0000000000578754 in internal_condition_case
> > (bfun=bfun@entry=0x50e180 <command_loop_1>,
> > handlers=handlers@entry=0x90, hfun=hfun@entry=0x504990 <cmd_error>) at
> > eval.c:1450
> > #14 0x00000000004ff4aa in command_loop_2
> > (handlers=handlers@entry=0x90) at keyboard.c:1133
> > #15 0x0000000000578704 in internal_catch (tag=tag@entry=0xe850,
> > func=func@entry=0x4ff490 <command_loop_2>, arg=arg@entry=0x90) at
> > eval.c:1181
> > #16 0x00000000004ff46a in command_loop () at keyboard.c:1111
> > #17 0x00000000005045cb in recursive_edit_1 () at keyboard.c:720
> > #18 0x00000000005048e5 in Frecursive_edit () at keyboard.c:803
> > #19 0x000000000041e909 in main (argc=4, argv=<optimized out>) at 
> > emacs.c:2361
> >
> > What could be causing this?
>
> This says that Emacs have read some stuff from the sub-process.  When
> that happens, we always perform a relatively-thorough redisplay, which
> is what you see.
>
> This is normal.

Just to make sure I understand, you said earlier:

>There are many variables and flags Emacs uses to decide when something
>changed that needs the display to be updated.  Those should generally
>prevent Emacs from running the expensive parts of redisplay if they
>are unnecessary.  The question is why this doesn't work in your case.

Are you saying this does not apply in the case of reading from
process output? That after reading process output, we always do
an expensive redisplay?

If so, it seems to me that this could be substantially improved.
Why do we always do an expensive redisplay after reading process
output, even if nothing has been changed to make it necessary?

I would like to improve this so that my Emacs does not do
expensive redisplay whenever it reads process output, which is
substantially hurting performance for me when there's lots of
process output to read.