Skip Menu |

This queue is for tickets about the Time-HiRes CPAN distribution.

Report information
The Basics
Id: 17442
Status: resolved
Priority: 0/
Queue: Time-HiRes
People
Owner: Nobody in particular
Requestors: jdhedden [...] cpan.org
Cc:
AdminCc:
Bug Information
Severity: Important
Broken in: 1.86
Fixed in: (no value)

History Show all quoted text
  Thu Feb 02 10:28:10 2006 jdhedden [...] cpan.org - Ticket created
Subject: 'make test' frequently fails under Cygwin Perl v5.8.8
'make test' frequently fails with Perl v5.8.8 under cygwin. This problem is also causing 'make test' while building Perl v5.8.8 to _terminate_! ext/threads/t/stress_string...............ok ext/threads/t/thread......................ok ext/Time/HiRes/t/HiRes.................... ../ext/Time/HiRes/t/HiRes.t: overall time allowed for tests (60s) exceeded! Use of uninitialized value in subtraction (-) at ../ext/Time/HiRes/t/HiRes.t line 592. This is very bad, and needs to be changed so that a failure (not ok) occurs, and not a total termination of the test script. The problem is not caused by machine load. Here are a number of examples with the CPAN distribution: Show quoted text
cpan> force install Time::HiRes
CPAN: Storable loaded ok Going to read /admin/cpan/Metadata Database was generated on Thu, 02 Feb 2006 05:16:05 GMT Running install for module Time::HiRes Running make for J/JH/JHI/Time-HiRes-1.86.tar.gz CPAN: Digest::MD5 loaded ok Checksum for /admin/cpan/sources/authors/id/J/JH/JHI/Time-HiRes-1.86.tar.gz ok Time-HiRes-1.86/ Time-HiRes-1.86/Changes Time-HiRes-1.86/fallback/ Time-HiRes-1.86/fallback/const-c.inc Time-HiRes-1.86/fallback/const-xs.inc Time-HiRes-1.86/hints/ Time-HiRes-1.86/hints/dec_osf.pl Time-HiRes-1.86/hints/dynixptx.pl Time-HiRes-1.86/hints/irix.pl Time-HiRes-1.86/hints/sco.pl Time-HiRes-1.86/hints/solaris.pl Time-HiRes-1.86/hints/svr4.pl Time-HiRes-1.86/HiRes.pm Time-HiRes-1.86/HiRes.xs Time-HiRes-1.86/Makefile.PL Time-HiRes-1.86/MANIFEST Time-HiRes-1.86/META.yml Time-HiRes-1.86/ppport.h Time-HiRes-1.86/README Time-HiRes-1.86/t/ Time-HiRes-1.86/t/HiRes.t Time-HiRes-1.86/TODO Time-HiRes-1.86/typemap Removing previously used /admin/cpan/build/Time-HiRes-1.86 CPAN.pm: Going to build J/JH/JHI/Time-HiRes-1.86.tar.gz Configuring Time::HiRes... No syscall()... Looking for gettimeofday()... found. Looking for setitimer()... found. Looking for getitimer()... found. You have interval timers (both setitimer and getitimer). Looking for ualarm()... found. Looking for usleep()... found. Looking for nanosleep()... testing... found. You can mix subsecond sleeps with signals, if you want to. (It's still not portable, though.) Looking for clock_gettime()... found. Looking for clock_getres()... found. Looking for clock_nanosleep()... NOT found. Looking for clock()... found. Looking for <w32api/windows.h>... found. Checking if your kit is complete... Looks good Writing Makefile for Time::HiRes Now you may issue 'make'. Do not forget also 'make test'. cp HiRes.pm blib/lib/Time/HiRes.pm /usr/bin/perl.exe /usr/lib/perl5/5.8/ExtUtils/xsubpp -typemap /usr/lib/perl5/5.8/ExtUtils/typemap -typemap typemap HiRes.xs > HiRes.xsc && mv HiRes.xsc HiRes.c gcc -c -DPERL_USE_SAFE_PUTENV -fno-strict-aliasing -pipe -Wdeclaration-after-statement -DUSEIMPORTLIB -O3 -pipe -frename-registers -fomit-frame-pointer -march=pentium4 -mfpmath=sse -mmmx -msse -msse2 -DVERSION=\"1.86\" -DXS_VERSION=\"1.86\" "-I/usr/lib/perl5/5.8/cygwin/CORE" -DTIME_HIRES_NANOSLEEP -DTIME_HIRES_CLOCK_GETTIME -DTIME_HIRES_CLOCK_GETRES -DTIME_HIRES_CLOCK -DHAS_W32API_WINDOWS_H -DATLEASTFIVEOHOHFIVE HiRes.c In file included from HiRes.xs:18: ppport.h:2979:1: warning: "PERL_UNUSED_DECL" redefined In file included from HiRes.xs:16: /usr/lib/perl5/5.8/cygwin/CORE/perl.h:163:1: warning: this is the location of the previous definition Running Mkbootstrap for Time::HiRes () chmod 644 HiRes.bs rm -f blib/arch/auto/Time/HiRes/HiRes.dll /usr/bin/ld2 -s -L/usr/local/lib HiRes.o -o blib/arch/auto/Time/HiRes/HiRes.dll \ /usr/lib/perl5/5.8/cygwin/CORE/libperl.dll.a \ gcc -shared -o HiRes.dll -Wl,--out-implib=libHiRes.dll.a -Wl,--export-all-symbols -Wl,--enable-auto-import -Wl,--stack,8388608 -Wl,--enable-auto-image-base \ -s -L/usr/local/lib HiRes.o /usr/lib/perl5/5.8/cygwin/CORE/libperl.dll.a Creating library file: libHiRes.dll.a mv HiRes.dll libHiRes.dll.a blib/arch/auto/Time/HiRes/ chmod 755 blib/arch/auto/Time/HiRes/HiRes.dll cp HiRes.bs blib/arch/auto/Time/HiRes/HiRes.bs chmod 644 blib/arch/auto/Time/HiRes/HiRes.bs /usr/bin/make -- OK Running make test /usr/bin/perl.exe "-MExtUtils::Command::MM" "-e" "test_harness(0, 'blib/lib', 'blib/arch')" t/*.t t/HiRes....ok 8/33 t/HiRes.t: overall time allowed for tests (60s) exceeded! Use of uninitialized value in subtraction (-) at t/HiRes.t line 592. Got SIGTERM, leaving Show quoted text
cpan> make: *** [test_dynamic] Terminated
------------------------------------------------------------------------------- 98 Time-HiRes-1.86 > perl -Mblib t/HiRes.t 1..33 ok 1 # have_gettimeofday = 1 # have_usleep = 1 # have_nanosleep = 1 # have_ualarm = 1 # have_clock_gettime = 1 # have_clock_getres = 1 # have_clock_nanosleep = 0 # have_clock = 1 # I am the main process 3472, starting the timer process... # The timer process 3336 launched, continuing testing... ok 2 ok 3 # I am the timer process 3336, sleeping for 60 seconds... ok 4 ok 5 ok 6 ok 7 ok 8 ok 9 ok 10 ok 11 ok 12 # tick = 1, one = 1138893070, two = 1138893070, three = 1138893070 ok 13 # tick = 3, one = 1138893070, two = 1138893070, three = 1138893070 ok 14 # s = 17.3104686737061, n = 100, s/n = 0.173104686737061 # time...1138893071.17345 ok 15 Alarm clock 99 Time-HiRes-1.86 > t/HiRes.t: overall time allowed for tests (60s) exceeded! # Terminating the main process... # This is the timer process 3336, over and out. Use of uninitialized value in subtraction (-) at t/HiRes.t line 592. # I am the main process 3336, terminating the timer process 0 # before it terminates me in -1138893128 seconds (testing took 1138893188 seconds). ------------------------------------------------------------------------------- Show quoted text
> make test
/usr/bin/perl.exe "-MExtUtils::Command::MM" "-e" "test_harness(0, 'blib/lib', 'blib/arch')" t/*.t t/HiRes....ok 11/33 t/HiRes.t: overall time allowed for tests (60s) exceeded! # Terminating the main process... # This is the timer process 2844, over and out. Use of uninitialized value in subtraction (-) at t/HiRes.t line 592. # I am the main process 2844, terminating the timer process 0 # before it terminates me in -1138891622 seconds (testing took 1138891682 seconds). make: *** wait: No child processes. Stop. make: *** Waiting for unfinished jobs.... make: *** wait: No child processes. Stop. Show quoted text
> make test
/usr/bin/perl.exe "-MExtUtils::Command::MM" "-e" "test_harness(0, 'blib/lib', 'blib/arch')" t/*.t t/HiRes....ok 11/33 t/HiRes.t: overall time allowed for tests (60s) exceeded! Use of uninitialized value in subtraction (-) at t/HiRes.t line 592. make: *** [test_dynamic] Terminated Terminated Show quoted text
> make test
/usr/bin/perl.exe "-MExtUtils::Command::MM" "-e" "test_harness(0, 'blib/lib', 'blib/arch')" t/*.t t/HiRes....ok 11/33 t/HiRes.t: overall time allowed for tests (60s) exceeded! Use of uninitialized value in subtraction (-) at t/HiRes.t line 592. make: *** wait: No child processes. Stop. make: *** Waiting for unfinished jobs.... make: *** wait: No child processes. Stop. ------------------------------------------------------------------------------- My perl info: Summary of my perl5 (revision 5 version 8 subversion 8) configuration: Platform: osname=cygwin, osvers=1.5.19(0.15042), archname=cygwin-thread-multi-64int uname='cygwin_nt-5.0 pn100-02-2-054p 1.5.19(0.15042) 2006-01-20 13:28 i686 cygwin ' config_args='-de -Duse64bitint -Dusethreads -DPERL_DONT_CREATE_GVSV -Uusemymalloc -A define:optimize=-O3 -pipe -frename-registers -fomit-frame-pointer -march=pentium4 -mfpmath=sse -mmmx -msse -msse2 -A define:ld=/usr/bin/ld2' hint=recommended, useposix=true, d_sigaction=define usethreads=define use5005threads=undef useithreads=define usemultiplicity=define useperlio=define d_sfio=undef uselargefiles=define usesocks=undef use64bitint=define use64bitall=undef uselongdouble=undef usemymalloc=n, bincompat5005=undef Compiler: cc='gcc', ccflags ='-DPERL_USE_SAFE_PUTENV -fno-strict-aliasing -pipe -Wdeclaration-after-statement', optimize='-O3 -pipe -frename-registers -fomit-frame-pointer -march=pentium4 -mfpmath=sse -mmmx -msse -msse2', cppflags='-DPERL_USE_SAFE_PUTENV -fno-strict-aliasing -pipe -Wdeclaration-after-statement' ccversion='', gccversion='3.4.4 (cygming special) (gdc 0.12, using dmd 0.125)', gccosandvers='' intsize=4, longsize=4, ptrsize=4, doublesize=8, byteorder=12345678 d_longlong=define, longlongsize=8, d_longdbl=define, longdblsize=12 ivtype='long long', ivsize=8, nvtype='double', nvsize=8, Off_t='off_t', lseeksize=8 alignbytes=8, prototype=define Linker and Libraries: ld='/usr/bin/ld2', ldflags =' -s -L/usr/local/lib' libpth=/usr/local/lib /usr/lib /lib libs=-lgdbm -ldb -lcrypt -lgdbm_compat perllibs=-lcrypt -lgdbm_compat libc=/usr/lib/libc.a, so=dll, useshrplib=true, libperl=libperl.a gnulibc_version='' Dynamic Linking: dlsrc=dl_dlopen.xs, dlext=dll, d_dlsymun=undef, ccdlflags=' -s' cccdlflags=' ', lddlflags=' -s -L/usr/local/lib' Characteristics of this binary (from libperl): Compile-time options: MULTIPLICITY PERL_IMPLICIT_CONTEXT PERL_USE_SAFE_PUTENV USE_64_BIT_INT USE_ITHREADS USE_LARGE_FILES USE_PERLIO USE_REENTRANT_API Locally applied patches: MAINT27024 27041 Built under cygwin Compiled at Feb 2 2006 08:16:49 %ENV: PERLIO="perlio" CYGWIN="server ntsec forkchunk:32768" @INC: /usr/lib/perl5/5.8/cygwin /usr/lib/perl5/5.8 .
  Thu Feb 02 10:29:33 2006 jdhedden [...] cpan.org - Broken in 1.86 added
  Thu Feb 02 10:29:34 2006 jdhedden [...] cpan.org - Fixed in 1.86 deleted
  Sun Feb 12 11:04:47 2006 jhi [...] iki.fi - Correspondence added
CC: JDHEDDEN [...] cpan.org
Subject: Re: [rt.cpan.org #17442] 'make test' frequently fails under Cygwin Perl v5.8.8
Date: Sun, 12 Feb 2006 18:03:58 +0200
To: bug-Time-HiRes [...] rt.cpan.org
From: Jarkko Hietaniemi <jhietaniemi [...] gmail.com>
Jerry D. Hedden via RT wrote: Show quoted text
> Thu Feb 02 10:28:10 2006: Request 17442 was acted upon. > Transaction: Ticket created by JDHEDDEN > Queue: Time-HiRes > Subject: 'make test' frequently fails under Cygwin Perl v5.8.8 > Owner: Nobody > Requestors: JDHEDDEN@cpan.org > Status: new > Ticket <URL: http://rt.cpan.org/Ticket/Display.html?id=17442 > > > > 'make test' frequently fails with Perl v5.8.8 under cygwin.
Time::HiRes used to work just fine with Cygwin, so I am inclined to suspect rather the Cygwin side of things. Show quoted text
> This problem is also causing 'make test' while building Perl v5.8.8 to > _terminate_! > > ext/threads/t/stress_string...............ok > ext/threads/t/thread......................ok > ext/Time/HiRes/t/HiRes.................... > ../ext/Time/HiRes/t/HiRes.t: overall time allowed for tests (60s) exceeded! > Use of uninitialized value in subtraction (-) at > ../ext/Time/HiRes/t/HiRes.t line 592. > > This is very bad, and needs to be changed so that a failure (not ok) > occurs, and not a total termination of the test script.
If this really is taking place, it needs to be taken up with the perl5-porters@perl.org. Time::HiRes is using the standard test harness, it is not doing anything fancy to terminate everything. Show quoted text
> The problem is not caused by machine load. > > Here are a number of examples with the CPAN distribution:
Show quoted text
> Use of uninitialized value in subtraction (-) at t/HiRes.t line 592. > # I am the main process 3336, terminating the timer process 0
This is quite suspicious. The "timer process 0" looks like the pid timer process forked by the HiRes.t ended up being zero, which (a) obviously is wrong (b) sounds like it could spell trouble when killed. Show quoted text
> # before it terminates me in -1138893128 seconds (testing took > 1138893188 seconds).
This is even more suspicious, and non-sensical, so non-sensical that I really do suspect Cygwin being rather broken here. (The "testing took 1138893188 seconds" means that the first time() call in HiRes.t returned zero (!), but a later one returned a sensible value.)
  Sun Feb 12 11:04:48 2006 The RT System itself - Status changed from 'new' to 'open'
  Mon Feb 13 11:48:42 2006 jdhedden [...] cpan.org - Correspondence added
There are two problems here. One is a bug in Cygwin. I haven't been able to track it down, but the following reproduces it consistently: #!/usr/bin/perl use strict; use warnings; use Time::HiRes qw(sleep ualarm); { my $tick; local $SIG{ALRM} = sub { $tick++ }; $tick = 0; ualarm(10_000); while ($tick == 0) { } $tick = 0; ualarm(10_000); while ($tick == 0) { } $tick = 0; ualarm(10_000, 10_000); while ($tick < 3) { } ualarm(0); } { local $SIG{ALRM} = sub {print(STDERR "--- BOGUS ALARM ---\n")}; my $r = [Time::HiRes::gettimeofday()]; sleep (0.5); print('# sleep =', Time::HiRes::tv_interval($r), "\n"); } exit(0); This produces the following output: Show quoted text
--- BOGUS ALARM --- # sleep =0.080217 This shows that ualarm(0) isn't properly cancelling the alarm which then goes off during the sleep call. (Again, this is a Cygwin bug.) The other bug is in HiRes.t. There is nothing in the block for tests 15-17 to catch this bogus alarm. As a result, the main process dies during the sleep(0.5) call! This is the 'Alarm clock' message that appears in my previous message. 60 seconds after the start of the test, the child 'watchdog' process wakes up and attempts to kill the 'stuck' parent. Here's the bug: The child process uses kill('TERM', getppid()). The problem is that the parent is gone. getppid() return 1 and the child process executes a kill('TERM', 1)! This is what is terminating 'make test' when building Perl 5.8.8. The following patch corrects this problem. It runs getppid() right after the fork, and then uses that value later on in the kill statement. --- t/HiRes.t 2006-02-13 10:47:30.000000000 -0500 +++ t/HiRes.t.fixed 2006-02-13 11:05:48.000000000 -0500 @@ -74,11 +74,12 @@ $timer_pid = fork(); if (defined $timer_pid) { if ($timer_pid == 0) { # We are the kid, set up the timer. + my $ppid = getppid(); print "# I am the timer process $$, sleeping for $waitfor seconds...\n"; sleep($waitfor); warn "\n$0: overall time allowed for tests (${waitfor}s) exceeded!\n"; - print "# Terminating the main process...\n"; - kill('TERM', getppid()); + print "# Terminating main process $ppid...\n"; + kill('TERM', $ppid); print "# This is the timer process $$, over and out.\n"; exit(0); } else { This, at least, makes HiRes.t well behaved even with the Cygwin bug.
  Mon Feb 13 13:22:10 2006 jdhedden [...] cpan.org - Correspondence added
There's more to this saga. The END block, as defined, is executed not only by the main process, but also by the child 'watchdog' process if it times out. It's not enough to check for defined($timer_pid). The check should be 'if ($timer_pid)' so that the child doesn't execute this block. I was mistaken before about the cause of the termination of 'make test'. It turns out that the culpret is really the END block code. If the child times out, $timer_pid is defined, but is 0. This causes the child process to do kill('TERM', 0) which is really bad. My revised patch is attached. Thanks.
--- t/HiRes.t 2005-12-17 14:20:26.000000000 -0500 +++ t/HiRes.t.fixed 2006-02-13 13:12:14.000000000 -0500 @@ -74,11 +74,12 @@ $timer_pid = fork(); if (defined $timer_pid) { if ($timer_pid == 0) { # We are the kid, set up the timer. + my $ppid = getppid(); print "# I am the timer process $$, sleeping for $waitfor seconds...\n"; sleep($waitfor); warn "\n$0: overall time allowed for tests (${waitfor}s) exceeded!\n"; - print "# Terminating the main process...\n"; - kill('TERM', getppid()); + print "# Terminating main process $ppid...\n"; + kill('TERM', $ppid); print "# This is the timer process $$, over and out.\n"; exit(0); } else { @@ -588,7 +589,7 @@ } END { - if (defined $timer_pid) { + if ($timer_pid) { my $left = $TheEnd - time(); printf "# I am the main process $$, terminating the timer process $timer_pid\n# before it terminates me in %d seconds (testing took %d seconds).\n", $left, $waitfor - $left; kill('TERM', $timer_pid); # We are done, the timer can go.
  Mon Feb 13 13:23:56 2006 jhi [...] iki.fi - Correspondence added
Subject: Re: [rt.cpan.org #17442] 'make test' frequently fails under Cygwin Perl v5.8.8
Date: Mon, 13 Feb 2006 20:22:45 +0200
To: bug-Time-HiRes [...] rt.cpan.org
From: Jarkko Hietaniemi <jhietaniemi [...] gmail.com>
Show quoted text
> The other bug is in HiRes.t. There is nothing in the block for tests > 15-17 to catch this bogus alarm. As a result, the main process dies > during the sleep(0.5) call! This is the 'Alarm clock' message that > appears in my previous message. > > 60 seconds after the start of the test, the child 'watchdog' process > wakes up and attempts to kill the 'stuck' parent. Here's the bug: The > child process uses kill('TERM', getppid()). The problem is that the > parent is gone. getppid() return 1 and the child process executes a > kill('TERM', 1)! This is what is terminating 'make test' when building
Ahhh. Devious. Couldn't think of that failing. Thanks for the fix! New release coming up. Show quoted text
> Perl 5.8.8. The following patch corrects this problem. It runs > getppid() right after the fork, and then uses that value later on in the > kill statement. > > --- t/HiRes.t 2006-02-13 10:47:30.000000000 -0500 > +++ t/HiRes.t.fixed 2006-02-13 11:05:48.000000000 -0500 > @@ -74,11 +74,12 @@ > $timer_pid = fork(); > if (defined $timer_pid) { > if ($timer_pid == 0) { # We are the kid, set up the timer. > + my $ppid = getppid(); > print "# I am the timer process $$, sleeping for $waitfor > seconds...\n"; > sleep($waitfor); > warn "\n$0: overall time allowed for tests (${waitfor}s) > exceeded!\n"; > - print "# Terminating the main process...\n"; > - kill('TERM', getppid()); > + print "# Terminating main process $ppid...\n"; > + kill('TERM', $ppid); > print "# This is the timer process $$, over and out.\n"; > exit(0); > } else { > > This, at least, makes HiRes.t well behaved even with the Cygwin bug. >
  Mon Feb 13 13:42:50 2006 jhi [...] iki.fi - Correspondence added
Subject: Re: [rt.cpan.org #17442] 'make test' frequently fails under Cygwin Perl v5.8.8
Date: Mon, 13 Feb 2006 20:41:41 +0200
To: bug-Time-HiRes [...] rt.cpan.org
From: Jarkko Hietaniemi <jhietaniemi [...] gmail.com>
Jerry D. Hedden via RT wrote: Show quoted text
> <URL: http://rt.cpan.org/Ticket/Display.html?id=17442 > > > There's more to this saga. The END block, as defined, is executed not > only by the main process, but also by the child 'watchdog' process if it > times out. It's not enough to check for defined($timer_pid). The check > should be 'if ($timer_pid)' so that the child doesn't execute this block. > > I was mistaken before about the cause of the termination of 'make test'. > It turns out that the culpret is really the END block code. If the > child times out, $timer_pid is defined, but is 0. This causes the child > process to do kill('TERM', 0) which is really bad. > > My revised patch is attached. Thanks.
Thanks. Time-HiRes 1.87 uploaded to PAUSE.
  Mon Feb 13 14:47:17 2006 jdhedden [...] cpan.org - Correspondence added
FYI, I was able to generate a C program that reproduced the Cygwin bug, and have submitted a bug report to the Cygwin developers.
  Mon Feb 13 15:19:40 2006 jhi [...] iki.fi - Correspondence added
Subject: Re: [rt.cpan.org #17442] 'make test' frequently fails under Cygwin Perl v5.8.8
Date: Mon, 13 Feb 2006 22:18:24 +0200
To: bug-Time-HiRes [...] rt.cpan.org
From: Jarkko Hietaniemi <jhietaniemi [...] gmail.com>
Jerry D. Hedden via RT wrote: Show quoted text
> <URL: http://rt.cpan.org/Ticket/Display.html?id=17442 > > > FYI, I was able to generate a C program that reproduced the Cygwin bug, > and have submitted a bug report to the Cygwin developers. >
Excellent, thanks for letting me know.
  Sat Feb 18 08:14:43 2006 JHI [...] cpan.org - Correspondence added
Resolved in 1.87.
  Sat Feb 18 08:14:45 2006 JHI [...] cpan.org - Status changed from 'open' to 'resolved'