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

Previous Next

Package: guile;

Reported by: hylophile <at> posteo.de

Date: Wed, 16 Nov 2022 20:57:02 UTC

Severity: normal

Done: Ludovic Courtès <ludo <at> gnu.org>

Bug is archived. No further changes may be made.

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 59321 in the body.
You can then email your comments to 59321 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

View this report as an mbox folder, status mbox, maintainer mbox


Report forwarded to bug-guile <at> gnu.org:
bug#59321; Package guile. (Wed, 16 Nov 2022 20:57:02 GMT) Full text and rfc822 format available.

Acknowledgement sent to hylophile <at> posteo.de:
New bug report received and forwarded. Copy sent to bug-guile <at> gnu.org. (Wed, 16 Nov 2022 20:57:02 GMT) Full text and rfc822 format available.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: hylophile <at> posteo.de
To: bug-guile <at> gnu.org
Subject: ice-9's open-input-pipe is unexpectedly slow on some systems
Date: Wed, 16 Nov 2022 18:06:06 +0000
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





Information forwarded to bug-guile <at> gnu.org:
bug#59321; Package guile. (Fri, 18 Nov 2022 04:50:02 GMT) Full text and rfc822 format available.

Message #8 received at 59321 <at> debbugs.gnu.org (full text, mbox):

From: Andrew Whatson <whatson <at> gmail.com>
To: hylophile <at> posteo.de
Cc: 59321 <at> debbugs.gnu.org
Subject: Re: ice-9's open-input-pipe is unexpectedly slow on some systems
Date: Fri, 18 Nov 2022 14:49:05 +1000
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




Information forwarded to bug-guile <at> gnu.org:
bug#59321; Package guile. (Fri, 18 Nov 2022 05:53:02 GMT) Full text and rfc822 format available.

Message #11 received at 59321 <at> debbugs.gnu.org (full text, mbox):

From: <tomas <at> tuxteam.de>
To: Andrew Whatson <whatson <at> gmail.com>
Cc: hylophile <at> posteo.de, 59321 <at> debbugs.gnu.org
Subject: Re: bug#59321: ice-9's open-input-pipe is unexpectedly slow on some
 systems
Date: Fri, 18 Nov 2022 06:52:27 +0100
[Message part 1 (text/plain, inline)]
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
[signature.asc (application/pgp-signature, inline)]

Information forwarded to bug-guile <at> gnu.org:
bug#59321; Package guile. (Sun, 20 Nov 2022 17:26:02 GMT) Full text and rfc822 format available.

Message #14 received at 59321 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: Andrew Whatson <whatson <at> gmail.com>
Cc: hylophile <at> posteo.de, 59321 <at> debbugs.gnu.org
Subject: Re: bug#59321: ice-9's open-input-pipe is unexpectedly slow on some
 systems
Date: Sun, 20 Nov 2022 18:24:57 +0100
Hi,

Andrew Whatson <whatson <at> 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’.




Information forwarded to bug-guile <at> gnu.org:
bug#59321; Package guile. (Sun, 20 Nov 2022 19:01:02 GMT) Full text and rfc822 format available.

Message #17 received at submit <at> debbugs.gnu.org (full text, mbox):

From: <tomas <at> tuxteam.de>
To: bug-guile <at> gnu.org
Subject: Re: bug#59321: ice-9's open-input-pipe is unexpectedly slow on some
 systems
Date: Sun, 20 Nov 2022 20:00:34 +0100
[Message part 1 (text/plain, inline)]
On Sun, Nov 20, 2022 at 06:24:57PM +0100, Ludovic Courtès wrote:
> Hi,
> 
> Andrew Whatson <whatson <at> 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
[signature.asc (application/pgp-signature, inline)]

Information forwarded to bug-guile <at> gnu.org:
bug#59321; Package guile. (Mon, 21 Nov 2022 04:24:01 GMT) Full text and rfc822 format available.

Message #20 received at 59321 <at> debbugs.gnu.org (full text, mbox):

From: Andrew Whatson <whatson <at> gmail.com>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: hylophile <at> posteo.de, 59321 <at> debbugs.gnu.org
Subject: Re: bug#59321: ice-9's open-input-pipe is unexpectedly slow on some
 systems
Date: Mon, 21 Nov 2022 14:22:52 +1000
[Message part 1 (text/plain, inline)]
Ludovic Courtès <ludo <at> gnu.org> wrote:
>
> Andrew Whatson <whatson <at> 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.
[close-inherited-with-proc-self-fd.patch (text/x-patch, attachment)]

Information forwarded to bug-guile <at> gnu.org:
bug#59321; Package guile. (Sat, 26 Nov 2022 14:40:02 GMT) Full text and rfc822 format available.

Message #23 received at 59321 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: Andrew Whatson <whatson <at> gmail.com>
Cc: hylophile <at> posteo.de, 59321 <at> debbugs.gnu.org
Subject: Re: bug#59321: ice-9's open-input-pipe is unexpectedly slow on some
 systems
Date: Sat, 26 Nov 2022 15:39:06 +0100
Hi Andrew,

Andrew Whatson <whatson <at> gmail.com> skribis:

> Ludovic Courtès <ludo <at> 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’.




Information forwarded to bug-guile <at> gnu.org:
bug#59321; Package guile. (Thu, 08 Dec 2022 12:03:01 GMT) Full text and rfc822 format available.

Message #26 received at 59321 <at> debbugs.gnu.org (full text, mbox):

From: Andrew Whatson <whatson <at> gmail.com>
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: hylophile <at> posteo.de, 59321 <at> debbugs.gnu.org
Subject: Re: bug#59321: ice-9's open-input-pipe is unexpectedly slow on some
 systems
Date: Thu, 8 Dec 2022 22:02:04 +1000
[Message part 1 (text/plain, inline)]
Ludovic Courtès <ludo <at> gnu.org> wrote:
>
> Andrew Whatson <whatson <at> 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!
[close-inherited-with-proc-self-fd-psawn.patch (text/x-patch, attachment)]

Information forwarded to bug-guile <at> gnu.org:
bug#59321; Package guile. (Thu, 08 Dec 2022 14:36:01 GMT) Full text and rfc822 format available.

Message #29 received at 59321 <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: Andrew Whatson <whatson <at> gmail.com>
Cc: hylophile <at> posteo.de, 59321 <at> debbugs.gnu.org
Subject: Re: bug#59321: ice-9's open-input-pipe is unexpectedly slow on some
 systems
Date: Thu, 08 Dec 2022 15:34:51 +0100
Hi,

Andrew Whatson <whatson <at> 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’.




Reply sent to Ludovic Courtès <ludo <at> gnu.org>:
You have taken responsibility. (Fri, 13 Jan 2023 15:38:02 GMT) Full text and rfc822 format available.

Notification sent to hylophile <at> posteo.de:
bug acknowledged by developer. (Fri, 13 Jan 2023 15:38:02 GMT) Full text and rfc822 format available.

Message #34 received at 59321-done <at> debbugs.gnu.org (full text, mbox):

From: Ludovic Courtès <ludo <at> gnu.org>
To: Andrew Whatson <whatson <at> gmail.com>
Cc: hylophile <at> posteo.de, 59321-done <at> debbugs.gnu.org
Subject: Re: bug#59321: ice-9's open-input-pipe is unexpectedly slow on some
 systems
Date: Fri, 13 Jan 2023 16:37:24 +0100
Hello!

Andrew Whatson <whatson <at> gmail.com> skribis:

> commit c012d7b0d5248a99a3a92780687a676c5d420f5f
> Author: Andrew Whatson <whatson <at> 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’.




bug archived. Request was from Debbugs Internal Request <help-debbugs <at> gnu.org> to internal_control <at> debbugs.gnu.org. (Sat, 11 Feb 2023 12:24:07 GMT) Full text and rfc822 format available.

This bug report was last modified 1 year and 75 days ago.

Previous Next


GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.