t/io/openpid.t makes test harness sluggish; reduce sleep time

[p5pRT]

Migrated from rt.perl.org#132867 (status was 'resolved')

Searchable as RT132867$

[p5pRT]

From @jkeenan

When you run 'make test_harness' often enough, you quickly become aware
that, despite setting $TEST_JOBS to an appropriate value, certain test
files are slow and block the forward movement of the harness. The first
such file I notice is t/io/openpid.t, which contains two commands which
each sleep for 30 seconds.

The amount of 'sleep' requested has been unchanged since commit c8fc8fb
in 2003. Do we still need to sleep so much? If not, please review
patch attached.

Thank you very much.
Jim Keenan

[p5pRT]

From @jkeenan

Summary of my perl5 (revision 5 version 27 subversion 9) configuration​:
  Commit id​: 9c5d14b
  Platform​:
  osname=linux
  osvers=4.4.0-112-generic
  archname=x86_64-linux
  uname='linux zareason 4.4.0-112-generic #135-ubuntu smp fri jan 19 11​:48​:36 utc 2018 x86_64 x86_64 x86_64 gnulinux '
  config_args='-des -Dusedevel'
  hint=recommended
  useposix=true
  d_sigaction=define
  useithreads=undef
  usemultiplicity=undef
  use64bitint=define
  use64bitall=define
  uselongdouble=undef
  usemymalloc=n
  default_inc_excludes_dot=define
  bincompat5005=undef
  Compiler​:
  cc='cc'
  ccflags ='-fwrapv -fno-strict-aliasing -pipe -fstack-protector-strong -I/usr/local/include -D_LARGEFILE_SOURCE -D_FILE_OFFSET_BITS=64'
  optimize='-O2'
  cppflags='-fwrapv -fno-strict-aliasing -pipe -fstack-protector-strong -I/usr/local/include'
  ccversion=''
  gccversion='5.4.1 20160904'
  gccosandvers=''
  intsize=4
  longsize=8
  ptrsize=8
  doublesize=8
  byteorder=12345678
  doublekind=3
  d_longlong=define
  longlongsize=8
  d_longdbl=define
  longdblsize=16
  longdblkind=3
  ivtype='long'
  ivsize=8
  nvtype='double'
  nvsize=8
  Off_t='off_t'
  lseeksize=8
  alignbytes=8
  prototype=define
  Linker and Libraries​:
  ld='cc'
  ldflags =' -fstack-protector-strong -L/usr/local/lib'
  libpth=/usr/local/lib /usr/lib/gcc/x86_64-linux-gnu/5/include-fixed /usr/include/x86_64-linux-gnu /usr/lib /lib/x86_64-linux-gnu /lib/../lib /usr/lib/x86_64-linux-gnu /usr/lib/../lib /lib /lib64 /usr/lib64
  libs=-lpthread -lnsl -ldb -ldl -lm -lcrypt -lutil -lc
  perllibs=-lpthread -lnsl -ldl -lm -lcrypt -lutil -lc
  libc=libc-2.23.so
  so=so
  useshrplib=false
  libperl=libperl.a
  gnulibc_version='2.23'
  Dynamic Linking​:
  dlsrc=dl_dlopen.xs
  dlext=so
  d_dlsymun=undef
  ccdlflags='-Wl,-E'
  cccdlflags='-fPIC'
  lddlflags='-shared -O2 -L/usr/local/lib -fstack-protector-strong'

Characteristics of this binary (from libperl)​:
  Compile-time options​:
  HAS_TIMES
  PERLIO_LAYERS
  PERL_COPY_ON_WRITE
  PERL_DONT_CREATE_GVSV
  PERL_MALLOC_WRAP
  PERL_OP_PARENT
  PERL_PRESERVE_IVUV
  PERL_USE_DEVEL
  USE_64_BIT_ALL
  USE_64_BIT_INT
  USE_LARGE_FILES
  USE_LOCALE
  USE_LOCALE_COLLATE
  USE_LOCALE_CTYPE
  USE_LOCALE_NUMERIC
  USE_LOCALE_TIME
  USE_PERLIO
  USE_PERL_ATOF
  Built under linux
  Compiled at Feb 11 2018 11​:52​:54
  %ENV​:
  PERL2DIR="/home/jkeenan/gitwork/perl2"
  PERLBREW_BASHRC_VERSION="0.78"
  PERLBREW_HOME="/home/jkeenan/.perlbrew"
  PERLBREW_MANPATH="/home/jkeenan/perl5/perlbrew/perls/perl-5.26.0/man"
  PERLBREW_PATH="/home/jkeenan/perl5/perlbrew/bin​:/home/jkeenan/perl5/perlbrew/perls/perl-5.26.0/bin"
  PERLBREW_PERL="perl-5.26.0"
  PERLBREW_ROOT="/home/jkeenan/perl5/perlbrew"
  PERLBREW_VERSION="0.78"
  PERL_WORKDIR="/home/jkeenan/gitwork/perl"
  @​INC​:
  lib
  /usr/local/lib/perl5/site_perl/5.27.9/x86_64-linux
  /usr/local/lib/perl5/site_perl/5.27.9
  /usr/local/lib/perl5/5.27.9/x86_64-linux
  /usr/local/lib/perl5/5.27.9

[p5pRT]

From @jkeenan

0001-Reduce-sleep-time-so-that-test-does-not-delay-make-t.patch

From 6246167de9698ceb531052746ab8c87e1f2a7d02 Mon Sep 17 00:00:00 2001
From: James E Keenan <jkeenan@cpan.org>
Date: Wed, 14 Feb 2018 10:35:03 -0500
Subject: [PATCH] Reduce 'sleep' time so that test does not delay 'make
 test_harness'.

---
 t/io/openpid.t | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/t/io/openpid.t b/t/io/openpid.t
index d3fcf78..2516ddd 100644
--- a/t/io/openpid.t
+++ b/t/io/openpid.t
@@ -35,8 +35,8 @@ $perl .= qq[ "-I../lib"];
 # the other reader reads one line, waits a few seconds and then
 # exits to test the waitpid function.
 #
-$cmd1 = qq/$perl -e "\$|=1; print qq[first process\\n]; sleep 30;"/;
-$cmd2 = qq/$perl -e "\$|=1; print qq[second process\\n]; sleep 30;"/;
+$cmd1 = qq/$perl -e "\$|=1; print qq[first process\\n]; sleep 5;"/;
+$cmd2 = qq/$perl -e "\$|=1; print qq[second process\\n]; sleep 5;"/;
 $cmd3 = qq/$perl -e "print <>;"/; # hangs waiting for end of STDIN
 $cmd4 = qq/$perl -e "print scalar <>;"/;
 
-- 
2.7.4

[p5pRT]

From @Tux

On Wed, 14 Feb 2018 07​:46​:04 -0800, James E Keenan (via RT)
<perlbug-followup@​perl.org> wrote​:

# <URL​: https://rt-archive.perl.org/perl5/Ticket/Display.html?id=132867 >

When you run 'make test_harness' often enough, you quickly become aware
that, despite setting $TEST_JOBS to an appropriate value, certain test
files are slow and block the forward movement of the harness. The first
such file I notice is t/io/openpid.t, which contains two commands which
each sleep for 30 seconds.

Hum, my oldest box still takes 4½ hours per configuration adding op to
over 1½ day for a full smoke. Would it start failing then?

Are their any tests that "measure" allowed delays and set them
dynamically instead of hard-coded?

The amount of 'sleep' requested has been unchanged since commit c8fc8fb
in 2003. Do we still need to sleep so much? If not, please review
patch attached.

Thank you very much.
Jim Keenan

--
H.Merijn Brand http​://tux.nl Perl Monger http​://amsterdam.pm.org/
using perl5.00307 .. 5.27 porting perl5 on HP-UX, AIX, and openSUSE
http​://mirrors.develooper.com/hpux/ http​://www.test-smoke.org/
http​://qa.perl.org http​://www.goldmark.org/jeff/stupid-disclaimers/

[p5pRT]

The RT System itself - Status changed from 'new' to 'open'

[p5pRT]

From @tonycoz

On Wed, 14 Feb 2018 07​:46​:03 -0800, jkeenan@​pobox.com wrote​:

When you run 'make test_harness' often enough, you quickly become aware
that, despite setting $TEST_JOBS to an appropriate value, certain test
files are slow and block the forward movement of the harness. The first
such file I notice is t/io/openpid.t, which contains two commands which
each sleep for 30 seconds.

The amount of 'sleep' requested has been unchanged since commit c8fc8fb
in 2003. Do we still need to sleep so much? If not, please review
patch attached.

There's some sort of interaction between harness and this test causing the delay.

If you run the test directly​:

tony@​mars​:.../perl/t$ time ./perl io/openpid.t
1..10
ok 1 - first process started
ok 2 - second
ok 3 - third
ok 4 - fourth
# pids were 1662, 1663, 1666, 1667
ok 5 - message from first process
ok 6 - first process killed
ok 7 - message from second process
ok 8 - killing procs 2 & 3
# waiting for process 1667 to exit
ok 9 - text sent to fourth process
ok 10 - fourth process reaped

real 0m0.033s
user 0m0.008s
sys 0m0.016s

or under TEST​:

tony@​mars​:.../perl/t$ time ./perl TEST io/openpid.t
t/io/openpid ... ok
All tests successful.
Elapsed​: 0 sec
u=0.01 s=0.00 cu=0.02 cs=0.00 scripts=1 tests=10

real 0m0.041s
user 0m0.032s
sys 0m0.000s

the test completes immediately.

Only under harness does it take a long time​:

tony@​mars​:.../perl/t$ time ./perl harness io/openpid.t
io/openpid.t .. ok
All tests successful.
Files=1, Tests=10, 30 wallclock secs ( 0.01 usr 0.01 sys + 0.02 cusr 0.00 csys = 0.04 CPU)
Result​: PASS

real 0m30.123s
user 0m0.112s
sys 0m0.012s

Tony

[p5pRT]

From @tonycoz

On Wed, 14 Feb 2018 14​:38​:26 -0800, tonyc wrote​:

On Wed, 14 Feb 2018 07​:46​:03 -0800, jkeenan@​pobox.com wrote​:

When you run 'make test_harness' often enough, you quickly become
aware
that, despite setting $TEST_JOBS to an appropriate value, certain
test
files are slow and block the forward movement of the harness. The
first
such file I notice is t/io/openpid.t, which contains two commands
which
each sleep for 30 seconds.

The amount of 'sleep' requested has been unchanged since commit
c8fc8fb
in 2003. Do we still need to sleep so much? If not, please review
patch attached.

There's some sort of interaction between harness and this test causing
the delay.

I thought this was familiar, please try the attached patch.

List form pipe has been implemented since the discussion in #121028.

Tony

[p5pRT]

From @tonycoz

0001-perl-121028-avoid-creating-a-shell-process.patch

From 38350e53702d28f072f80311bc943afead03ef89 Mon Sep 17 00:00:00 2001
From: Tony Cook <tony@develop-help.com>
Date: Tue, 28 Jan 2014 15:52:22 +1100
Subject: [perl #121028] avoid creating a shell process

---
 t/io/openpid.t | 20 +++++++++++++++-----
 1 file changed, 15 insertions(+), 5 deletions(-)

diff --git a/t/io/openpid.t b/t/io/openpid.t
index d3fcf7869a..634330ded7 100644
--- a/t/io/openpid.t
+++ b/t/io/openpid.t
@@ -23,11 +23,15 @@ watchdog(15, $^O eq 'MSWin32' ? "alarm" : '');
 use Config;
 $| = 1;
 $SIG{PIPE} = 'IGNORE';
+# reset the handler in case the shell has set a broken default
+$SIG{HUP} = 'DEFAULT';
 $SIG{HUP} = 'IGNORE' if $^O eq 'interix';
 
 my $perl = which_perl();
 $perl .= qq[ "-I../lib"];
 
+my @perl = ( which_perl(), "-I../lib" );
+
 #
 # commands run 4 perl programs.  Two of these programs write a
 # short message to STDOUT and exit.  Two of these programs
@@ -35,16 +39,22 @@ $perl .= qq[ "-I../lib"];
 # the other reader reads one line, waits a few seconds and then
 # exits to test the waitpid function.
 #
-$cmd1 = qq/$perl -e "\$|=1; print qq[first process\\n]; sleep 30;"/;
-$cmd2 = qq/$perl -e "\$|=1; print qq[second process\\n]; sleep 30;"/;
+# Using 4+ arg open for the children that sleep so that that we're
+# killing the perl process instead of an intermediate shell, this
+# allows harness to see the file handles closed sooner.  I didn't
+# convert them all since I wanted 3-arg open to continue to be
+# exercised here.
+#
+@cmd1 = ( @perl, "-e", "\$|=1; print qq[first process\\n]; sleep 30;" );
+@cmd2 = ( @perl, "-e", "\$|=1; print qq[second process\\n]; sleep 30;" );
 $cmd3 = qq/$perl -e "print <>;"/; # hangs waiting for end of STDIN
 $cmd4 = qq/$perl -e "print scalar <>;"/;
 
-#warn "#$cmd1\n#$cmd2\n#$cmd3\n#$cmd4\n";
+#warn "#@cmd1\n#@cmd2\n#$cmd3\n#$cmd4\n";
 
 # start the processes
-ok( $pid1 = open(FH1, "$cmd1 |"), 'first process started');
-ok( $pid2 = open(FH2, "$cmd2 |"), '    second' );
+ok( $pid1 = open(FH1, "-|", @cmd1), 'first process started');
+ok( $pid2 = open(FH2, "-|", @cmd2), '    second' );
 {
     no warnings 'once';
     ok( $pid3 = open(FH3, "| $cmd3"), '    third'  );
-- 
2.11.0

[p5pRT]

From @Leont

On Thu, Feb 15, 2018 at 12​:31 AM, Tony Cook via RT
<perlbug-followup@​perl.org> wrote​:

I thought this was familiar, please try the attached patch.

List form pipe has been implemented since the discussion in #121028.

Tony

---
via perlbug​: queue​: perl5 status​: open
https://rt-archive.perl.org/perl5/Ticket/Display.html?id=132867

From 38350e5 Mon Sep 17 00​:00​:00 2001
From​: Tony Cook <tony@​develop-help.com>
Date​: Tue, 28 Jan 2014 15​:52​:22 +1100
Subject​: [perl #121028] avoid creating a shell process

---
t/io/openpid.t | 20 +++++++++++++++-----
1 file changed, 15 insertions(+), 5 deletions(-)

diff --git a/t/io/openpid.t b/t/io/openpid.t
index d3fcf7869a..634330ded7 100644
--- a/t/io/openpid.t
+++ b/t/io/openpid.t
@​@​ -23,11 +23,15 @​@​ watchdog(15, $^O eq 'MSWin32' ? "alarm" : '');
use Config;
$| = 1;
$SIG{PIPE} = 'IGNORE';
+# reset the handler in case the shell has set a broken default
+$SIG{HUP} = 'DEFAULT';
$SIG{HUP} = 'IGNORE' if $^O eq 'interix';

my $perl = which_perl();
$perl .= qq[ "-I../lib"];

+my @​perl = ( which_perl(), "-I../lib" );
+
#
# commands run 4 perl programs. Two of these programs write a
# short message to STDOUT and exit. Two of these programs
@​@​ -35,16 +39,22 @​@​ $perl .= qq[ "-I../lib"];
# the other reader reads one line, waits a few seconds and then
# exits to test the waitpid function.
#
-$cmd1 = qq/$perl -e "\$|=1; print qq[first process\\n]; sleep 30;"/;
-$cmd2 = qq/$perl -e "\$|=1; print qq[second process\\n]; sleep 30;"/;
+# Using 4+ arg open for the children that sleep so that that we're
+# killing the perl process instead of an intermediate shell, this
+# allows harness to see the file handles closed sooner. I didn't
+# convert them all since I wanted 3-arg open to continue to be
+# exercised here.
+#
+@​cmd1 = ( @​perl, "-e", "\$|=1; print qq[first process\\n]; sleep 30;" );
+@​cmd2 = ( @​perl, "-e", "\$|=1; print qq[second process\\n]; sleep 30;" );
$cmd3 = qq/$perl -e "print <>;"/; # hangs waiting for end of STDIN
$cmd4 = qq/$perl -e "print scalar <>;"/;

-#warn "#$cmd1\n#$cmd2\n#$cmd3\n#$cmd4\n";
+#warn "#@​cmd1\n#@​cmd2\n#$cmd3\n#$cmd4\n";

# start the processes
-ok( $pid1 = open(FH1, "$cmd1 |"), 'first process started');
-ok( $pid2 = open(FH2, "$cmd2 |"), ' second' );
+ok( $pid1 = open(FH1, "-|", @​cmd1), 'first process started');
+ok( $pid2 = open(FH2, "-|", @​cmd2), ' second' );
{
no warnings 'once';
ok( $pid3 = open(FH3, "| $cmd3"), ' third' );
--
2.11.0

Fix looks sensible to me, and I can indeed reproduce this issue once I
run the test under nohup.

Leon

[p5pRT]

From @jkeenan

On Wed, 14 Feb 2018 23​:31​:43 GMT, tonyc wrote​:

On Wed, 14 Feb 2018 14​:38​:26 -0800, tonyc wrote​:

On Wed, 14 Feb 2018 07​:46​:03 -0800, jkeenan@​pobox.com wrote​:

When you run 'make test_harness' often enough, you quickly become
aware
that, despite setting $TEST_JOBS to an appropriate value, certain
test
files are slow and block the forward movement of the harness. The
first
such file I notice is t/io/openpid.t, which contains two commands
which
each sleep for 30 seconds.

The amount of 'sleep' requested has been unchanged since commit
c8fc8fb
in 2003. Do we still need to sleep so much? If not, please review
patch attached.

There's some sort of interaction between harness and this test causing
the delay.

I thought this was familiar, please try the attached patch.

List form pipe has been implemented since the discussion in #121028.

Tony

Looks good to me. After applying your patch​:

#####
# Branch​: 132867-openpid
$ time ./perl -Ilib t/io/openpid.t
1..10
...
ok 10 - fourth process reaped

real 0m0.036s
user 0m0.020s
sys 0m0.004s

$ cd t;time ./perl harness -v io/openpid.t; cd -
ok 1 - first process started
...
ok 10 - fourth process reaped
ok
All tests successful.
Files=1, Tests=10, 0 wallclock secs ( 0.01 usr + 0.00 sys = 0.01 CPU)
Result​: PASS

real 0m0.067s
user 0m0.064s
sys 0m0.004s
#####

Please apply unless someone raises an objection. Thank you very much.

--
James E Keenan (jkeenan@​cpan.org)

[p5pRT]

From @tonycoz

On Wed, 14 Feb 2018 17​:26​:53 -0800, jkeenan wrote​:

Please apply unless someone raises an objection. Thank you very much.

Thanks for testing it.

Applied as b6811f8.

Tony

[p5pRT]

@tonycoz - Status changed from 'open' to 'pending release'

[p5pRT]

From @Tux

On Wed, 14 Feb 2018 15​:31​:43 -0800, "Tony Cook via RT"
<perlbug-followup@​perl.org> wrote​:

On Wed, 14 Feb 2018 14​:38​:26 -0800, tonyc wrote​:

On Wed, 14 Feb 2018 07​:46​:03 -0800, jkeenan@​pobox.com wrote​:

When you run 'make test_harness' often enough, you quickly become
aware
that, despite setting $TEST_JOBS to an appropriate value, certain
test
files are slow and block the forward movement of the harness. The
first
such file I notice is t/io/openpid.t, which contains two commands
which
each sleep for 30 seconds.

The amount of 'sleep' requested has been unchanged since commit
c8fc8fb
in 2003. Do we still need to sleep so much? If not, please review
patch attached.

There's some sort of interaction between harness and this test causing
the delay.

I thought this was familiar, please try the attached patch.

+1

List form pipe has been implemented since the discussion in #121028.

Tony

--
H.Merijn Brand http​://tux.nl Perl Monger http​://amsterdam.pm.org/
using perl5.00307 .. 5.27 porting perl5 on HP-UX, AIX, and openSUSE
http​://mirrors.develooper.com/hpux/ http​://www.test-smoke.org/
http​://qa.perl.org http​://www.goldmark.org/jeff/stupid-disclaimers/

[p5pRT]

From @craigberry

On Wed, Feb 14, 2018 at 9​:44 PM, Tony Cook via RT
<perlbug-followup@​perl.org> wrote​:

On Wed, 14 Feb 2018 17​:26​:53 -0800, jkeenan wrote​:

Please apply unless someone raises an objection. Thank you very much.

Thanks for testing it.

Applied as b6811f8.

The test now fails like so on VMS​:

$ perl io/openpid.t
1..10
List form of piped open not implemented at io/openpid.t line 56.
# Looks like you planned 10 tests but ran 0.

[p5pRT]

From @craigberry

On Thu, Feb 15, 2018 at 9​:35 PM, Craig A. Berry <craig.a.berry@​gmail.com> wrote​:

On Wed, Feb 14, 2018 at 9​:44 PM, Tony Cook via RT
<perlbug-followup@​perl.org> wrote​:

On Wed, 14 Feb 2018 17​:26​:53 -0800, jkeenan wrote​:

Please apply unless someone raises an objection. Thank you very much.

Thanks for testing it.

Applied as b6811f8.

The test now fails like so on VMS​:

$ perl io/openpid.t
1..10
List form of piped open not implemented at io/openpid.t line 56.
# Looks like you planned 10 tests but ran 0.

As of 0970cf2 I have hacked up the test to run the old way
on VMS only. As far as I can see, what Windows does for list open is
just paste the arguments together to form a command line, and there's
no reason in principle that couldn't be done on VMS as well -- just a
few dozen round tuits missing.