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

Previous Next

Full log

View this message in rfc822 format

From: help-debbugs <at> gnu.org (GNU bug Tracking System)
To: Ludovic Courtès <ludo <at> gnu.org>
Cc: tracker <at> debbugs.gnu.org
Subject: bug#59321: closed (ice-9's open-input-pipe is unexpectedly slow
 on some systems)
Date: Fri, 13 Jan 2023 15:38:02 +0000

[Message part 1 (text/plain, inline)]

Your message dated Fri, 13 Jan 2023 16:37:24 +0100
with message-id <87fscebg3v.fsf <at> gnu.org>
and subject line Re: bug#59321: ice-9's open-input-pipe is unexpectedly slow on some systems
has caused the debbugs.gnu.org bug report #59321,
regarding ice-9's open-input-pipe is unexpectedly slow on some systems
to be marked as done.

(If you believe you have received this mail in error, please contact
help-debbugs <at> gnu.org.)


-- 
59321: https://debbugs.gnu.org/cgi/bugreport.cgi?bug=59321
GNU Bug Tracking System
Contact help-debbugs <at> gnu.org with problems

[Message part 2 (message/rfc822, inline)]

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

[Message part 3 (message/rfc822, inline)]

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

Previous Next

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