--- Begin Message ---
|
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
--- End Message ---
--- Begin Message ---
|
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 |
|
User-agent: |
Gnus/5.13 (Gnus v5.13) Emacs/28.2 (gnu/linux) |
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’.
--- End Message ---