bug#66288: 29.1; Performance regression using pipe for subprocess

[Chris Hanson]

On 10/2/23 01:36, Eli Zaretskii wrote:
> > Cc: 66288@debbugs.gnu.org
> > Date: Mon, 02 Oct 2023 08:02:14 +0300
> > From: Eli Zaretskii <eliz@gnu.org>
> >
> > > I saw that there were no relevant differences in "xscheme.el" but I
> > > never thought that was relevant.
> > >
> > > I believe this has something to do with how piped subprocesses are being
> > > managed.  I've not looked deeply into the C code for this, but I could
> > > find no mention of anything to do with pipes in NEWS.
> >
> > Because AFAIK we didn't change anything in that department.
>
> I've now identified 3 changes in Emacs 29 which could potentially
> affect your case.  Not sure if they do, but it might be worth your
> while to check them first.
>
> First, Emacs 29 uses posix_spawn by default on systems where it is
> available and usable.  You will see this fragment at the beginning of
> callproc.c:
>
>    /* In order to be able to use `posix_spawn', it needs to support some
>       variant of `chdir' as well as `setsid'.  */
>    #if defined HAVE_SPAWN_H && defined HAVE_POSIX_SPAWN        \
>      && defined HAVE_POSIX_SPAWNATTR_SETFLAGS                  \
>      && (defined HAVE_POSIX_SPAWN_FILE_ACTIONS_ADDCHDIR        \
>         || defined HAVE_POSIX_SPAWN_FILE_ACTIONS_ADDCHDIR_NP) \
>      && defined HAVE_DECL_POSIX_SPAWN_SETSID                   \
>      && HAVE_DECL_POSIX_SPAWN_SETSID == 1                           \
>      /* posix_spawnattr_setflags rejects POSIX_SPAWN_SETSID on \
>         Haiku */                                                    \
>      && !defined HAIKU
>    # include <spawn.h>
>    # define USABLE_POSIX_SPAWN 1
>    #else
>    # define USABLE_POSIX_SPAWN 0
>    #endif
>
> If on your system USABLE_POSIX_SPAWN gets the value 1 here, edit
> callproc.c to force it to zero, then rebuild Emacs, and see if this
> affects the behavior.
>
> Next, we have the following two code fragments in
> wait_reading_process_output, which are new in Emacs 29:
>
> Code fragment#1:
>
>        if ((read_kbd
>            /* The following code doesn't make any sense for just the
>               wait_for_cell case, because detect_input_pending returns
>               whether or not the keyboard buffer isn't empty or there
>               is mouse movement.  Any keyboard input that arrives
>               while waiting for a cell will cause the select call to
>               be skipped, and gobble_input to be called even when
>               there is no input available from the terminal itself.
>               Skipping the call to select also causes the timeout to
>               be ignored.  (bug#46935) */
>            /* || !NILP (wait_for_cell) */)
>           && detect_input_pending ())
>
> Code fragment#2:
>
>    #if !defined USABLE_SIGIO && !defined WINDOWSNT
>             /* If we're polling for input, don't get stuck in select for
>                more than 25 msec. */
>             struct timespec short_timeout = make_timespec (0, 25000000);
>             if ((read_kbd || !NILP (wait_for_cell))
>                 && timespec_cmp (short_timeout, timeout) < 0)
>               timeout = short_timeout;
>    #endif
>
> (I think the second one should not affect you because your system
> should have USABLE_SIGIO defined, but maybe I'm mistaken.)  Compare
> these with Emacs 28, and try reverting to 28.2 code to see if that
> changes anything in your case.

None of the three fragments made any difference.

> Finally, if you describe in plain English how xscheme.el reads
> subprocess output at the stage where you see the slowdown, it might
> give further ideas.  I'm not familiar with xscheme.el, and figuring
> out which code gets executed when one runs "run-scheme" is not
> trivial, so a detailed enough description might help.  Specifically,
> how does xscheme.el decide how much of the subprocess's output to read
> and display?

The process filter has one complexity: it looks for encoded commands 
from the subprocess, which are of the form "ESC <char>" or "ESC <char> 
<string> ESC", depending on the <char>.  There is a small state machine 
to do that, which searches the output string for ESC using 
`string-search'. In this case there are no commands embedded, so that 
should not be relevant.

The ordinary text is inserted into the process buffer using standard 
filter-output code, except it looks for BEL and translates that to 
(beep) if found.  In this case there are no occurrences of BEL in the 
output, so that's not relevant.  So, basically the output string is 
passed to `insert', making sure that process mark and point are updated 
appropriately.

I contrived a small example test and ran it under both editors (see 
below).  It does some printing and then shows the time taken in the 
subprocess.  This should be valid since Scheme will block while waiting 
on Emacs to process the output.

The reported times are in milliseconds, with 28.2 taking 1ms and 29.1 
taking 880ms (increasing the test loop from 20 to 200, the times are 8ms 
and 9974ms respectively).  As I said before, that's pretty dramatic: 
about 3 orders of magnitude.  It feels like that in normal use too -- 
it's like being 30-40 years in the past, when that kind of performance 
was expected.

28.2:
--------------------------------
(show-time
 (lambda ()
   (for-each write-line (iota 20))))
0
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
;process time: 0 (0 RUN + 0 GC); real time: 1
--------------------------------

29.1:
--------------------------------
(show-time
 (lambda ()
   (for-each write-line (iota 20))))
0
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
;process time: 0 (0 RUN + 0 GC); real time: 880
--------------------------------