bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems

bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems

[hylophile]

Hi,

while doing my first steps in Guile and porting a small shell script, I 
noticed that capturing stdout from a subshell is very slow:

$ time guile -c '(begin (use-modules (ice-9 popen) (ice-9 rdelim)) 
(display (read-delimited "" (open-input-pipe "ls"))))'
#<eof>
real	0m0,313s
user	0m0,008s
sys	0m0,007s

It takes around 300ms where I would expect around 40ms. The slowness 
happens on one of my machines, but not the other (at least not 
noticeably). However, I am fairly sure that my machine is not at fault, 
because this doesn't happen with other languages. Additionally, another 
Guile user tried this on their machines and also noticed slowness 
(around 200ms) on one of their machines. We did notice that the machines 
where the operation runs fast also run on better hardware, but the stark 
difference is still unexpected. Unfortunately I am not sure what exactly 
causes the issue, but I am happy to provide any further information 
needed.

The mentioned Guile user was able to pinpoint the delay to be between 
two read system calls by going through an strace. To reproduce:
1. Create an empty folder with one file named "testfile" in it

2. Run:
$ strace -o ice-9.trace -s 256 --timestamps=format:time,precision:ms 
guile -c '(begin (use-modules (ice-9 popen) (ice-9 rdelim)) (display 
(read-delimited "" (open-input-pipe "ls"))))'

3. In the resulting ice-9.trace, search for "testfile" and go up to the 
first read call which reads the output of ls. Between the first and the 
second read call, there is a noticeable delay. For one of my systems 
it's around 300ms, for the other it's around 90ms:

18:37:08.880 close(6)                   = 0
18:37:08.880 read(5, "i", 1)            = 1
18:37:09.189 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, 
si_pid=188843, si_uid=1000, si_status=0, si_utime=15 /* 0.15 s */, 
si_stime=14 /* 0.14 s */} ---
18:37:09.189 read(5, "c", 1)            = 1
18:37:09.189 read(5, "e", 1)            = 1

Regards,
Nate

System information:

guile (GNU Guile) 3.0.8

I am using the Arch Linux guile package, I believe the build 
configuration can be found here:
https://github.com/archlinux/svntogit-packages/blob/packages/guile/trunk/PKGBUILD#L23

Output of config.guess:
x86_64-pc-linux-gnu

bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems

[Andrew Whatson]

Hi Nate,

Thanks for reporting this!  I'm able to reproduce on my systems, and
have identified the culprit:

 > strace -c -f guile -c '(begin (use-modules (ice-9 popen) (ice-9
rdelim)) (display (read-delimited "" (open-input-pipe "ls"))))'

 % time     seconds  usecs/call     calls    errors syscall
 ------ ----------- ----------- --------- --------- ------------------
  93.38    0.309261           1    250107    249994 close
   4.61    0.015268         135       113        21 futex
   0.52    0.001730           4       430       270 newfstatat
   0.38    0.001263           6       183           mmap
   0.29    0.000953           4       197        92 openat
   0.16    0.000542         180         3           execve
 <...snip...>

These close calls are from the start_child routine in libguile/posix.c:

 static pid_t
 start_child (const char *exec_file, char **exec_argv,
          int reading, int c2p[2], int writing, int p2c[2],
              int in, int out, int err)
 {
   int pid;
   int max_fd = 1024;

 #if defined (HAVE_GETRLIMIT) && defined (RLIMIT_NOFILE)
   {
     struct rlimit lim = { 0, 0 };
     if (getrlimit (RLIMIT_NOFILE, &lim) == 0)
       max_fd = lim.rlim_cur;
   }
 #endif

 <...snip...>
   /* Close all file descriptors in ports inherited from the parent
      except for in, out, and err.  Heavy-handed, but robust.  */
   while (max_fd--)
     if (max_fd != in && max_fd != out && max_fd != err)
       close (max_fd);
 <...snip...>

On my system, `ulimit -n` shows the maximum number of open files as
250000, explaining the 250000 calls to close shown by strace.

Testing a build of guile with the max_fd loop commented out shows the
expected performance:

 # unmodified guile
 > time guile -c '(begin (use-modules (ice-9 popen) (ice-9 rdelim))
(display (read-delimited "" (open-input-pipe "ls"))))'
 real 0m0.202s

 # guile patched to remove max_fd loop
 > time guile -c '(begin (use-modules (ice-9 popen) (ice-9 rdelim))
(display (read-delimited "" (open-input-pipe "ls"))))'
 real 0m0.056s

Forcibly closing file descriptors like this shouldn't be necessary if
the application has properly opened descriptors with the FD_CLOEXEC
flag.  It would be good to get input from some more experienced Guile
hackers on the potential consequences of this change.

Cheers,
Andrew

bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems

[tomas]

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

On Fri, Nov 18, 2022 at 02:49:05PM +1000, Andrew Whatson wrote:
> Hi Nate,
> 
> Thanks for reporting this!  I'm able to reproduce on my systems, and
> have identified the culprit:

[250k calls to close()]

Well spotted.

Here [1] is a good discussion on the problem. Spoiler alert:
there is no nice, simple and portable way around it. There
may be complex, platform-dependent solutions (like, for
example, under Linux go look in /proc/<PID>/fd; BSD has other
tricks).

Of course, that doesn't mean that one should give up trying :)

Cheers

[1] https://stackoverflow.com/questions/56650579/why-should-i-close-all-file-descriptors-after-calling-fork-and-prior-to-callin

-- 
t

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 195 bytes --]

bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems

[Ludovic Courtès]

Hi,

Andrew Whatson <whatson@gmail.com> skribis:

> Forcibly closing file descriptors like this shouldn't be necessary if
> the application has properly opened descriptors with the FD_CLOEXEC
> flag.  It would be good to get input from some more experienced Guile
> hackers on the potential consequences of this change.

Libguile opens all its own file descriptors at O_CLOEXEC (one omission
was recently fixed in 0aa1a9976fc3c6af4d1087e59d728cb8fe7d369a) so it
may be possible to remove that FD-closing loop.  There’s still the
possibility that application bug unwillingly leaks FDs, but we could
consider it’s none of our business.

Thoughts?

Similarly, with commit a356ceebee000efe91a2a16dbcaa64d6c6a3a922, it’s
possible to pass ‘open-file’ a flag that corresponds to O_CLOEXEC, which
wasn’t possible before.  I’ve also been thinking that files opened with
‘call-with-*’ should be O_CLOEXEC.  That’d be an incompatible change
though, so maybe not something for 3.0.x.

Ludo’.

bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems

[tomas]

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

On Sun, Nov 20, 2022 at 06:24:57PM +0100, Ludovic Courtès wrote:
> Hi,
> 
> Andrew Whatson <whatson@gmail.com> skribis:
> 
> > Forcibly closing file descriptors like this shouldn't be necessary if
> > the application has properly opened descriptors with the FD_CLOEXEC
> > flag.  It would be good to get input from some more experienced Guile
> > hackers on the potential consequences of this change.
> 
> Libguile opens all its own file descriptors at O_CLOEXEC (one omission
> was recently fixed in 0aa1a9976fc3c6af4d1087e59d728cb8fe7d369a) so it
> may be possible to remove that FD-closing loop.  There’s still the
> possibility that application bug unwillingly leaks FDs, but we could
> consider it’s none of our business.
> 
> Thoughts?

Hm. Socket FDs don't "have" O_CLOEXEC. Arguably, they are at least as
"interesting" as file FDs (meaning: source of obscure bugs).

Moreover, misbehaving C libraries can be an additional source of bugs
we have no control of.

The reference I posted upthread makes a compelling case for at least
needing an option for this (admittedly ugly) close orgy (perhaps with
some additional platform-dependent mitigations, but that's an ugliness
in its own, sigh).

Cheers
-- 
t

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 195 bytes --]

bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems

[Andrew Whatson]

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

Ludovic Courtès <ludo@gnu.org> wrote:
>
> Andrew Whatson <whatson@gmail.com> skribis:
>
> > Forcibly closing file descriptors like this shouldn't be necessary if
> > the application has properly opened descriptors with the FD_CLOEXEC
> > flag.  It would be good to get input from some more experienced Guile
> > hackers on the potential consequences of this change.
>
> Libguile opens all its own file descriptors at O_CLOEXEC (one omission
> was recently fixed in 0aa1a9976fc3c6af4d1087e59d728cb8fe7d369a) so it
> may be possible to remove that FD-closing loop.  There’s still the
> possibility that application bug unwillingly leaks FDs, but we could
> consider it’s none of our business.
>
> Thoughts?

I agree with this approach in principle, but from what Tomas is saying
it seems like it's not currently possible for applications to do the
right thing in all cases.

> Similarly, with commit a356ceebee000efe91a2a16dbcaa64d6c6a3a922, it’s
> possible to pass ‘open-file’ a flag that corresponds to O_CLOEXEC,
> which wasn’t possible before.

Nice!

> I’ve also been thinking that files opened with ‘call-with-*’ should be
> O_CLOEXEC.  That’d be an incompatible change though, so maybe not
> something for 3.0.x.

This sounds reasonable to me.

We also need equivalent functionality around SOCK_CLOEXEC.  It seems
this is implemented for ‘accept’, but not ‘socket’ or ‘socketpair’.

Python's PEP 433 contains a good explanation of the issues which can
arise from leaked file descriptors:
https://peps.python.org/pep-0433/#inherited-file-descriptors-issues

Given the risks, I'm convinced that Guile's conservative approach is
actually quite sensible.  It seems like the best path forward would be
to implement platform-specific optimizations where possible.

I've attached a draft patch which implements a fast-path on systems
where "/proc/self/fd" is available.

[-- Attachment #2: close-inherited-with-proc-self-fd.patch --]
[-- Type: text/x-patch, Size: 2573 bytes --]

commit 08943cae90545dddea44ca55eab68047e5ae2f9d
Author: Andrew Whatson <whatson@gmail.com>
Date:   Mon Nov 21 13:40:33 2022 +1000

    Reduce redundant close() calls when forking on some systems.
    
    Some systems provide "/proc/self/fd" which is a directory containing an
    entry for each open file descriptor in the current process.  We use this
    to limit the number of close() calls needed to ensure file descriptors
    aren't leaked to the child process when forking.
    
    * libguile/posix.c (close_inherited_fds_slow):
    (close_inherited_fds): New static helper functions.
    (start_child): Attempt to close inherited file descriptors efficiently
    using 'close_inherited_fds', falling back to the brute-force approach in
    'close_inherited_fds_slow'.

diff --git a/libguile/posix.c b/libguile/posix.c
index b5352c2c4..fc3512054 100644
--- a/libguile/posix.c
+++ b/libguile/posix.c
@@ -24,6 +24,7 @@
 #  include <config.h>
 #endif
 
+#include <dirent.h>
 #include <errno.h>
 #include <fcntl.h>
 #include <stdio.h>
@@ -1337,6 +1338,46 @@ renumber_file_descriptor (int fd, int err)
 }
 #endif /* HAVE_FORK */
 
+static void
+close_inherited_fds_slow(int max_fd, int in, int out, int err)
+{
+  while (max_fd--)
+    if (max_fd != in && max_fd != out && max_fd != err)
+      close (max_fd);
+}
+
+static void
+close_inherited_fds(int max_fd, int in, int out, int err)
+{
+  DIR *dirp;
+  struct dirent *d;
+  int fd;
+
+  /* Try to use the platform-specific list of open file descriptors, so
+     we don't need to use the brute force approach. */
+  dirp = opendir ("/proc/self/fd");
+
+  if (dirp == NULL)
+    return close_inherited_fds_slow (max_fd, in, out, err);
+
+  while ((d = readdir (dirp)) != NULL)
+    {
+      fd = atoi (d->d_name);
+
+      /* Skip "." and "..", and any garbage entries. */
+      if (fd <= 0)
+        continue;
+
+      /* Keep in/out/err open. */
+      if (fd == in || fd == out || fd == err)
+        continue;
+
+      close (fd);
+    }
+
+  closedir (dirp);
+}
+
 #ifdef HAVE_FORK
 #define HAVE_START_CHILD 1
 /* Since Guile uses threads, we have to be very careful to avoid calling
@@ -1373,9 +1414,7 @@ start_child (const char *exec_file, char **exec_argv,
 
   /* Close all file descriptors in ports inherited from the parent
      except for in, out, and err.  Heavy-handed, but robust.  */
-  while (max_fd--)
-    if (max_fd != in && max_fd != out && max_fd != err)
-      close (max_fd);
+  close_inherited_fds (max_fd, in, out, err);
 
   /* Ignore errors on these open() calls.  */
   if (in == -1)

bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems

[Ludovic Courtès]

Hi Andrew,

Andrew Whatson <whatson@gmail.com> skribis:

> Ludovic Courtès <ludo@gnu.org> wrote:

[...]

>> Libguile opens all its own file descriptors at O_CLOEXEC (one omission
>> was recently fixed in 0aa1a9976fc3c6af4d1087e59d728cb8fe7d369a) so it
>> may be possible to remove that FD-closing loop.  There’s still the
>> possibility that application bug unwillingly leaks FDs, but we could
>> consider it’s none of our business.
>>
>> Thoughts?
>
> I agree with this approach in principle, but from what Tomas is saying
> it seems like it's not currently possible for applications to do the
> right thing in all cases.

OK.

[...]

> We also need equivalent functionality around SOCK_CLOEXEC.  It seems
> this is implemented for ‘accept’, but not ‘socket’ or ‘socketpair’.

It’s possible to use SOCK_CLOEXEC with ‘socket’ and ‘socketpair’
already, as in:

  (socket AF_INET (logior SOCK_CLOEXEC SOCK_STREAM) 0)

With commit 1d313bf5f0d296d766bd3a0e6d030df37c71711b, ‘pipe’ is also
covered.

So I think we have pretty much everything we need, at least starting
with 3.0.9.

> Python's PEP 433 contains a good explanation of the issues which can
> arise from leaked file descriptors:
> https://peps.python.org/pep-0433/#inherited-file-descriptors-issues
>
> Given the risks, I'm convinced that Guile's conservative approach is
> actually quite sensible.  It seems like the best path forward would be
> to implement platform-specific optimizations where possible.
>
> I've attached a draft patch which implements a fast-path on systems
> where "/proc/self/fd" is available.

The patch LGTM; it’s certainly an improvement on systems configured with
a high per-process FD limit.

Now, I believe use of ‘posix_spawn’ as proposed in
<https://issues.guix.gnu.org/52835> makes that unnecessary.  Let’s take
a closer look at that other patch and so we can see…

Thanks,
Ludo’.

bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems

[Andrew Whatson]

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

Ludovic Courtès <ludo@gnu.org> wrote:
>
> Andrew Whatson <whatson@gmail.com> skribis:
>
> > We also need equivalent functionality around SOCK_CLOEXEC.  It seems
> > this is implemented for ‘accept’, but not ‘socket’ or ‘socketpair’.
>
> It’s possible to use SOCK_CLOEXEC with ‘socket’ and ‘socketpair’
> already, as in:
>
>   (socket AF_INET (logior SOCK_CLOEXEC SOCK_STREAM) 0)
>
> With commit 1d313bf5f0d296d766bd3a0e6d030df37c71711b, ‘pipe’ is also
> covered.
>
> So I think we have pretty much everything we need, at least starting
> with 3.0.9.

Ah, nice!  In that case it might be possible to deprecate this
auto-closing behaviour in a future version.

> > Python's PEP 433 contains a good explanation of the issues which can
> > arise from leaked file descriptors:
> > https://peps.python.org/pep-0433/#inherited-file-descriptors-issues
> >
> > Given the risks, I'm convinced that Guile's conservative approach is
> > actually quite sensible.  It seems like the best path forward would be
> > to implement platform-specific optimizations where possible.
> >
> > I've attached a draft patch which implements a fast-path on systems
> > where "/proc/self/fd" is available.
>
> The patch LGTM; it’s certainly an improvement on systems configured with
> a high per-process FD limit.
>
> Now, I believe use of ‘posix_spawn’ as proposed in
> <https://issues.guix.gnu.org/52835> makes that unnecessary.  Let’s take
> a closer look at that other patch and so we can see…

Playing with the wip-posix-spawn branch, it has the same slowdown
(actually a bit worse).  I've updated the "/proc/self/fd" fast-path
patch for posix_spawn, please find attached.

> Thanks,
> Ludo’.

Thank you!

[-- Attachment #2: close-inherited-with-proc-self-fd-psawn.patch --]
[-- Type: text/x-patch, Size: 2563 bytes --]

commit c012d7b0d5248a99a3a92780687a676c5d420f5f
Author: Andrew Whatson <whatson@gmail.com>
Date:   Thu Dec 8 21:43:28 2022 +1000

    Reduce redundant close() calls when forking on some systems.
    
    Some systems provide "/proc/self/fd" which is a directory containing an
    entry for each open file descriptor in the current process.  We use this
    to limit the number of close() calls needed to ensure file descriptors
    aren't leaked to the child process when forking.
    
    * libguile/posix.c (close_inherited_fds_slow):
    (close_inherited_fds): New static helper functions.
    (scm_spawn_process): Attempt to close inherited file descriptors
    efficiently using 'close_inherited_fds', falling back to the brute-force
    approach in 'close_inherited_fds_slow'.

diff --git a/libguile/posix.c b/libguile/posix.c
index 87b329da9..8c9022116 100644
--- a/libguile/posix.c
+++ b/libguile/posix.c
@@ -24,6 +24,7 @@
 #  include <config.h>
 #endif
 
+#include <dirent.h>
 #include <errno.h>
 #include <fcntl.h>
 #include <stdio.h>
@@ -1309,6 +1310,41 @@ SCM_DEFINE (scm_fork, "primitive-fork", 0, 0, 0,
 #undef FUNC_NAME
 #endif /* HAVE_FORK */
 
+static void
+close_inherited_fds_slow (posix_spawn_file_actions_t *actions, int max_fd)
+{
+  while (--max_fd > 2)
+    posix_spawn_file_actions_addclose (actions, max_fd);
+}
+
+static void
+close_inherited_fds (posix_spawn_file_actions_t *actions, int max_fd)
+{
+  DIR *dirp;
+  struct dirent *d;
+  int fd;
+
+  /* Try to use the platform-specific list of open file descriptors, so
+     we don't need to use the brute force approach. */
+  dirp = opendir ("/proc/self/fd");
+
+  if (dirp == NULL)
+    return close_inherited_fds_slow (actions, max_fd);
+
+  while ((d = readdir (dirp)) != NULL)
+    {
+      fd = atoi (d->d_name);
+
+      /* Skip "." and "..", garbage entries, stdin/stdout/stderr. */
+      if (fd <= 2)
+        continue;
+
+      posix_spawn_file_actions_addclose (actions, fd);
+    }
+
+  closedir (dirp);
+}
+
 static SCM
 scm_spawn_process (SCM prog, SCM args, SCM scm_in, SCM scm_out, SCM scm_err)
 #define FUNC_NAME "spawn*"
@@ -1363,8 +1399,7 @@ scm_spawn_process (SCM prog, SCM args, SCM scm_in, SCM scm_out, SCM scm_err)
   posix_spawn_file_actions_adddup2 (&actions, fd_slot[1], 1);
   posix_spawn_file_actions_adddup2 (&actions, fd_slot[2], 2);
 
-  while (--max_fd > 2)
-    posix_spawn_file_actions_addclose (&actions, max_fd);
+  close_inherited_fds (&actions, max_fd);
 
   if (posix_spawnp (&pid, exec_file, &actions, attrp, exec_argv, environ) != 0)
     {

bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems

[Ludovic Courtès]

Hi,

Andrew Whatson <whatson@gmail.com> skribis:

> Playing with the wip-posix-spawn branch, it has the same slowdown
> (actually a bit worse).  I've updated the "/proc/self/fd" fast-path
> patch for posix_spawn, please find attached.

Ooh that’s perfect, thank you.

I’ll apply it once we’ve sorted out remaining issues on the branch.

Ludo’.

bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems

[Ludovic Courtès]

Hello!

Andrew Whatson <whatson@gmail.com> skribis:

> commit c012d7b0d5248a99a3a92780687a676c5d420f5f
> Author: Andrew Whatson <whatson@gmail.com>
> Date:   Thu Dec 8 21:43:28 2022 +1000
>
>     Reduce redundant close() calls when forking on some systems.
>     
>     Some systems provide "/proc/self/fd" which is a directory containing an
>     entry for each open file descriptor in the current process.  We use this
>     to limit the number of close() calls needed to ensure file descriptors
>     aren't leaked to the child process when forking.
>     
>     * libguile/posix.c (close_inherited_fds_slow):
>     (close_inherited_fds): New static helper functions.
>     (scm_spawn_process): Attempt to close inherited file descriptors
>     efficiently using 'close_inherited_fds', falling back to the brute-force
>     approach in 'close_inherited_fds_slow'.

Finally applied on top of the ‘posix_spawn’ series as commit
9332b632407894c2e1951cce1bc678f19e1fa8e4.

Thanks!

Ludo’.