Subject: ice-9's open-input-pipe is unexpectedly slow on some systems
From: [email-masked]
To: [email-masked]
Date: Wed, 16 Nov 2022 18:06:06 +0000
List-Id: <debbugs-submit.debbugs.gnu.org>

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