ice-9's open-input-pipe is unexpectedly slow on some systems

  • Done
  • quality assurance status badge
Details
4 participants
  • hylophile
  • Ludovic Courtès
  • tomas
  • Andrew Whatson
Owner
unassigned
Submitted by
hylophile
Severity
normal
H
H
hylophile wrote on 16 Nov 2022 19:06
(address . bug-guile@gnu.org)
8d55cf7d1e5382c874cfcaee1f4cddd3@posteo.de
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:

Output of config.guess:
x86_64-pc-linux-gnu
A
A
Andrew Whatson wrote on 18 Nov 2022 05:49
(address . hylophile@posteo.de)(address . 59321@debbugs.gnu.org)
CAPE069fJ0DRHv7b+mwwqOM22LJtWtUTMAJcDEAUCTbhSmO-abQ@mail.gmail.com
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
T
T
tomas wrote on 18 Nov 2022 06:52
Re: bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems
(name . Andrew Whatson)(address . whatson@gmail.com)
Y3cdm3LqqqsOpj8O@tuxteam.de
On Fri, Nov 18, 2022 at 02:49:05PM +1000, Andrew Whatson wrote:
Toggle quote (5 lines)
> 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


--
t
-----BEGIN PGP SIGNATURE-----

iF0EABECAB0WIQRp53liolZD6iXhAoIFyCz1etHaRgUCY3cdkgAKCRAFyCz1etHa
RsbVAJ97Yg5D78wAQwgvTWWklh9x7C7hEACeNOEVu093R3BYgmPtvPVtNjYdHHc=
=rpL5
-----END PGP SIGNATURE-----


L
L
Ludovic Courtès wrote on 20 Nov 2022 18:24
(name . Andrew Whatson)(address . whatson@gmail.com)
87r0xx5yja.fsf@gnu.org
Hi,

Andrew Whatson <whatson@gmail.com> skribis:

Toggle quote (5 lines)
> 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’.
T
T
tomas wrote on 20 Nov 2022 20:00
(address . bug-guile@gnu.org)
Y3p5Ugm5K07iP8c5@tuxteam.de
On Sun, Nov 20, 2022 at 06:24:57PM +0100, Ludovic Courtès wrote:
Toggle quote (17 lines)
> 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
-----BEGIN PGP SIGNATURE-----

iF0EABECAB0WIQRp53liolZD6iXhAoIFyCz1etHaRgUCY3p5TAAKCRAFyCz1etHa
RkdhAJ9OwLKxr//x1fHiEDF6JXcaNPJ7PwCePE7SZITdpX5l9tufDzMsnLFPboQ=
=8Oqy
-----END PGP SIGNATURE-----


A
A
Andrew Whatson wrote on 21 Nov 2022 05:22
(name . Ludovic Courtès)(address . ludo@gnu.org)
CAPE069cGWUWXMChrB86MBXKvNXFMUZUJnv=qkj-aDxSUTv3ygA@mail.gmail.com
Ludovic Courtès <ludo@gnu.org> wrote:
Toggle quote (16 lines)
>
> 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.

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

Nice!

Toggle quote (4 lines)
> 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:

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

Toggle diff (70 lines)
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)
L
L
Ludovic Courtès wrote on 26 Nov 2022 15:39
(name . Andrew Whatson)(address . whatson@gmail.com)
871qppaigl.fsf@gnu.org
Hi Andrew,

Andrew Whatson <whatson@gmail.com> skribis:

Toggle quote (2 lines)
> Ludovic Courtès <ludo@gnu.org> wrote:

[...]

Toggle quote (12 lines)
>> 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.

[...]

Toggle quote (3 lines)
> 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.

Toggle quote (11 lines)
> 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’.
A
A
Andrew Whatson wrote on 8 Dec 2022 13:02
(name . Ludovic Courtès)(address . ludo@gnu.org)
CAPE069diUWciWtkEdcKz68gJAHbjXQWozwwOA2_wd7vdM0cPug@mail.gmail.com
Ludovic Courtès <ludo@gnu.org> wrote:
Toggle quote (17 lines)
>
> 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.

Toggle quote (18 lines)
> > 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.

Toggle quote (3 lines)
> Thanks,
> Ludo’.

Thank you!
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'.

Toggle diff (64 lines)
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)
{
L
L
Ludovic Courtès wrote on 8 Dec 2022 15:34
(name . Andrew Whatson)(address . whatson@gmail.com)
87359qdkvo.fsf@gnu.org
Hi,

Andrew Whatson <whatson@gmail.com> skribis:

Toggle quote (4 lines)
> 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’.
L
L
Ludovic Courtès wrote on 13 Jan 2023 16:37
(name . Andrew Whatson)(address . whatson@gmail.com)
87fscebg3v.fsf@gnu.org
Hello!

Andrew Whatson <whatson@gmail.com> skribis:

Toggle quote (17 lines)
> 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’.
Closed
?
Your comment

This issue is archived.

To comment on this conversation send an email to 59321@debbugs.gnu.org

To respond to this issue using the mumi CLI, first switch to it
mumi current 59321
Then, you may apply the latest patchset in this issue (with sign off)
mumi am -- -s
Or, compose a reply to this issue
mumi compose
Or, send patches to this issue
mumi send-email *.patch