libipc-run-perl: delay after child exit

[gregoa]

We have the following bug reported to the Debian package of IPC-Run,
c.f. https://bugs.debian.org/1021794

It doesn't seem to be a bug in the packaging, so you may want to take
a look. Thanks!

------8<-----------8<-----------8<-----------8<-----------8<-----

Package: libipc-run-perl
Version: 20220807.0-1

I've noticed that IPC::Run::run() sometimes takes significantly more 
time than the child process itself. For example:

    $ time -p perl -MIPC::Run=run -e "run('sleep 0.7')"
    real 1.18
    user 0.03
    sys 0.01

This is how it looks under strace:

    $ strace -T -e trace=pselect6 perl -MIPC::Run=run -e "run('sleep 0.7')"
    [ Process PID=8271 runs in 32 bit mode. ]
    pselect6(0, NULL, NULL, NULL, {tv_sec=0, tv_nsec=100000}, NULL) = 0 (Timeout) <0.000164>
    pselect6(0, NULL, NULL, NULL, {tv_sec=0, tv_nsec=100000}, NULL) = 0 (Timeout) <0.000161>
    pselect6(0, NULL, NULL, NULL, {tv_sec=0, tv_nsec=100000}, NULL) = 0 (Timeout) <0.000160>
    ...
    pselect6(0, NULL, NULL, NULL, {tv_sec=0, tv_nsec=100000}, NULL) = 0 (Timeout) <0.000248>
    pselect6(0, NULL, NULL, NULL, {tv_sec=0, tv_nsec=100000}, NULL) = 0 (Timeout) <0.000212>
    pselect6(0, NULL, NULL, NULL, {tv_sec=0, tv_nsec=500000000}, NULL) = ? ERESTARTNOHAND (To be restarted if no handler) <0.031700>
    --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=8272, si_uid=1000, si_status=0, si_utime=0, si_stime=0} ---
    pselect6(0, NULL, NULL, NULL, {tv_sec=0, tv_nsec=468403068}, NULL) = 0 (Timeout) <0.469205>
    +++ exited with 0 +++

So there's nearly half a second delay after the child exits.


-- System Information:
Architecture: i386

Versions of packages libipc-run-perl depends on:
ii  perl            5.34.0-5
ii  libio-pty-perl  1:1.15-2+b1

-- 
Jakub Wilk

------8<-----------8<-----------8<-----------8<-----------8<-----

Thanks for considering,
gregor herrmann,
Debian Perl Group

[nmisch]

I see the same. There's an exponential backoff that caps at 0.5s, so detecting command completion can take up to 0.5s extra:

$ IPCRUNDEBUG=gory time -p perl -MIPC::Run=run -e "run('sleep 2')" 2>&1 |grep timeout=
IPC::Run 0000 0123-------- [#1(2879835)]: timeout=0.01
IPC::Run 0000 0123-------- [#1(2879835)]: timeout=0.02
IPC::Run 0001 0123-------- [#1(2879835)]: timeout=0.04
IPC::Run 0001 0123-------- [#1(2879835)]: timeout=0.08
IPC::Run 0001 0123-------- [#1(2879835)]: timeout=0.16
IPC::Run 0001 0123-------- [#1(2879835)]: timeout=0.32
IPC::Run 0001 0123-------- [#1(2879835)]: timeout=0.5
IPC::Run 0002 0123-------- [#1(2879835)]: timeout=0.5
IPC::Run 0002 0123-------- [#1(2879835)]: timeout=0.5

[nmisch]

#172 solved this for most scenarios. Feel free to reopen this issue if you find
otherwise. On non-Windows, you can get most of the improvement, without waiting
for the next release, by adding $SIG{CHLD} = sub {}; in your application. For
background, see the comment added in commit fc9288c.