unofficial mirror of bug-guile@gnu.org 
 help / color / mirror / Atom feed
* bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems
@ 2022-11-16 18:06 hylophile
  2022-11-18  4:49 ` Andrew Whatson
  0 siblings, 1 reply; 7+ messages in thread
From: hylophile @ 2022-11-16 18:06 UTC (permalink / raw)
  To: 59321

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






^ permalink raw reply	[flat|nested] 7+ messages in thread

* bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems
  2022-11-16 18:06 bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems hylophile
@ 2022-11-18  4:49 ` Andrew Whatson
  2022-11-18  5:52   ` tomas
  2022-11-20 17:24   ` Ludovic Courtès
  0 siblings, 2 replies; 7+ messages in thread
From: Andrew Whatson @ 2022-11-18  4:49 UTC (permalink / raw)
  To: hylophile; +Cc: 59321

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





^ permalink raw reply	[flat|nested] 7+ messages in thread

* bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems
  2022-11-18  4:49 ` Andrew Whatson
@ 2022-11-18  5:52   ` tomas
  2022-11-20 17:24   ` Ludovic Courtès
  1 sibling, 0 replies; 7+ messages in thread
From: tomas @ 2022-11-18  5:52 UTC (permalink / raw)
  To: Andrew Whatson; +Cc: hylophile, 59321

[-- 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 --]

^ permalink raw reply	[flat|nested] 7+ messages in thread

* bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems
  2022-11-18  4:49 ` Andrew Whatson
  2022-11-18  5:52   ` tomas
@ 2022-11-20 17:24   ` Ludovic Courtès
  2022-11-20 19:00     ` tomas
  2022-11-21  4:22     ` Andrew Whatson
  1 sibling, 2 replies; 7+ messages in thread
From: Ludovic Courtès @ 2022-11-20 17:24 UTC (permalink / raw)
  To: Andrew Whatson; +Cc: hylophile, 59321

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’.





^ permalink raw reply	[flat|nested] 7+ messages in thread

* bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems
  2022-11-20 17:24   ` Ludovic Courtès
@ 2022-11-20 19:00     ` tomas
  2022-11-21  4:22     ` Andrew Whatson
  1 sibling, 0 replies; 7+ messages in thread
From: tomas @ 2022-11-20 19:00 UTC (permalink / raw)
  To: 59321

[-- 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 --]

^ permalink raw reply	[flat|nested] 7+ messages in thread

* bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems
  2022-11-20 17:24   ` Ludovic Courtès
  2022-11-20 19:00     ` tomas
@ 2022-11-21  4:22     ` Andrew Whatson
  2022-11-26 14:39       ` Ludovic Courtès
  1 sibling, 1 reply; 7+ messages in thread
From: Andrew Whatson @ 2022-11-21  4:22 UTC (permalink / raw)
  To: Ludovic Courtès; +Cc: hylophile, 59321

[-- 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)

^ permalink raw reply related	[flat|nested] 7+ messages in thread

* bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems
  2022-11-21  4:22     ` Andrew Whatson
@ 2022-11-26 14:39       ` Ludovic Courtès
  0 siblings, 0 replies; 7+ messages in thread
From: Ludovic Courtès @ 2022-11-26 14:39 UTC (permalink / raw)
  To: Andrew Whatson; +Cc: hylophile, 59321

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’.





^ permalink raw reply	[flat|nested] 7+ messages in thread

end of thread, other threads:[~2022-11-26 14:39 UTC | newest]

Thread overview: 7+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2022-11-16 18:06 bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems hylophile
2022-11-18  4:49 ` Andrew Whatson
2022-11-18  5:52   ` tomas
2022-11-20 17:24   ` Ludovic Courtès
2022-11-20 19:00     ` tomas
2022-11-21  4:22     ` Andrew Whatson
2022-11-26 14:39       ` Ludovic Courtès

This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for read-only IMAP folder(s) and NNTP newsgroup(s).