Bug #122819 for Time-HiRes: Unreliable t/usleep.t and t/utime.t tests

Wed Aug 16 10:00:45 2017 ppisar [...] redhat.com - Ticket created

Subject:

Unreliable t/usleep.t and t/utime.t tests

t/usleep.t and t/utime.t fail randomly when built on loaded machine. Example from a perl-5.26.0 build: # Failed test at t/usleep.t line 35. ../dist/threads-shared/t/waithires.t ............................... ok ../dist/threads/t/basic.t .......................................... ok ../dist/Time-HiRes/t/usleep.t ...................................... Dubious, test returned 1 (wstat 256, 0x100) Failed 1/6 subtests (less 1 skipped subtest: 4 okay) # Looks like you failed 1 test of 6. # Failed test 'File 1 atime set correctly' # at t/utime.t line 113. # '18.0852150917053' # < # '0.1' # Failed test 'File 1 mtime set correctly' # at t/utime.t line 114. # '18.0852150917053' # < # '0.1' # Failed test 'File 2 atime set correctly' # at t/utime.t line 118. # '18.0852150917053' # < # '0.1' # Failed test 'File 2 mtime set correctly' # at t/utime.t line 119. # '18.0852150917053' # < # '0.1' # Looks like you failed 4 tests of 18. ../dist/Time-HiRes/t/utime.t ....................................... Dubious, test returned 4 (wstat 1024, 0x400) Failed 4/18 subtests The reason is the tests retrieve current time, then perform an operation (usleep or utime) depending on CPU time, then retrieve current (or file) time and test the times difference falls into some range. This is inherently unreliable because a the perl process can be suspended any time by a CPU scheduler for an unpredictable long period and then the delay influences the measured time. I recommend to check only for lower bound of the range. I.e. If I test usleep(500_000) than I would test that the difference is bigger or equaled to 0.5 second (or 0.4 as you have in the current code). But not that the value is smaller than some arbitrary constant (0.9 in the current code).

Wed Aug 16 10:53:02 2017 ppisar [...] redhat.com - Correspondence added

From:

ppisar [...] redhat.com

Dne St 16.srp.2017 10:00:45, ppisar napsal(a): Show quoted text

> # Failed test 'File 1 atime set correctly' > # at t/utime.t line 113. > # '18.0852150917053' > # < > # '0.1' >

This 18 second delay was caused by NFS server clock skew whose file system was mounted in the working directory. But still the test is in general wrong.

Wed Aug 16 10:54:12 2017 ppisar [...] redhat.com - Correspondence added

From:

ppisar [...] redhat.com

Dne St 16.srp.2017 10:00:45, ppisar napsal(a): Show quoted text

> t/usleep.t and t/utime.t fail randomly when built on loaded machine.

Attached patch fixes it. (I sent the patch already by e-mail, but it got lost/delayed.)

Subject:

Time-HiRes-1.9745-t-usleep.t-and-t-utime.t-more-reliable-on-loaded-hos.patch

From c8eb4fdc9bd0cba9c1f737af04e0d8a416f23a0a Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Petr=20P=C3=ADsa=C5=99?= <ppisar@redhat.com> Date: Wed, 16 Aug 2017 16:19:44 +0200 Subject: [PATCH] t/usleep.t and t/utime.t more reliable on loaded host MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The t/usleep.t and t/utime.t tests could fail on loaded machine because of unpredictable delayes affecting upper bound checks: not ok 13 - File 1 atime set correctly # Failed test 'File 1 atime set correctly' # at t/utime.t line 116. # '18.0842185020447' # < # '0.1' This patch changes the test to not check for the upper bound or to acutally adjusting the upper bound the clock after the tested operation. CPAN RT#122819 Signed-off-by: Petr PÃsaÅ <ppisar@redhat.com> --- t/usleep.t | 4 ++-- t/utime.t | 17 +++++++++++------ 2 files changed, 13 insertions(+), 8 deletions(-) diff --git a/t/usleep.t b/t/usleep.t index 9322458..1e568f2 100644 --- a/t/usleep.t +++ b/t/usleep.t @@ -32,7 +32,7 @@ SKIP: { Time::HiRes::usleep(500_000); my $f2 = Time::HiRes::time(); my $d = $f2 - $f; - ok $d > 0.4 && $d < 0.9 or print("# slept $d secs $f to $f2\n"); + ok $d > 0.4 or print("# slept $d secs $f to $f2\n"); } SKIP: { @@ -40,7 +40,7 @@ SKIP: { my $r = [ Time::HiRes::gettimeofday() ]; Time::HiRes::sleep( 0.5 ); my $f = Time::HiRes::tv_interval $r; - ok $f > 0.4 && $f < 0.9 or print("# slept $f instead of 0.5 secs.\n"); + ok $f > 0.4 or print("# slept $f instead of 0.5 secs.\n"); } SKIP: { diff --git a/t/utime.t b/t/utime.t index 8865e1d..1b5177a 100644 --- a/t/utime.t +++ b/t/utime.t @@ -50,7 +50,7 @@ BEGIN { } } -use Test::More tests => 18; +use Test::More tests => 22; BEGIN { push @INC, '.' } use t::Watchdog; use File::Temp qw( tempfile ); @@ -108,18 +108,23 @@ print "# utime undef sets time to now\n"; my ($fh1, $filename1) = tempfile( "Time-HiRes-utime-XXXXXXXXX", UNLINK => 1 ); my ($fh2, $filename2) = tempfile( "Time-HiRes-utime-XXXXXXXXX", UNLINK => 1 ); - my $now = Time::HiRes::time; + my $before = Time::HiRes::time; is Time::HiRes::utime(undef, undef, $filename1, $fh2), 2, "Two files changed"; + my $after = Time::HiRes::time; { my ($got_atime, $got_mtime) = ( Time::HiRes::stat($fh1) )[8, 9]; - cmp_ok abs( $got_atime - $now), '<', 0.1, "File 1 atime set correctly"; - cmp_ok abs( $got_mtime - $now), '<', 0.1, "File 1 mtime set correctly"; + cmp_ok $got_atime - $before, '>', -0.1, "File 1 atime not before the test"; + cmp_ok $after - $got_atime, '>', -0.1, "File 1 atime not after the test"; + cmp_ok $got_mtime - $before, '>', -0.1, "File 1 mtime not before the test"; + cmp_ok $after - $got_mtime, '>', -0.1, "File 1 mtime not after the test"; } { my ($got_atime, $got_mtime) = ( Time::HiRes::stat($filename2) )[8, 9]; - cmp_ok abs( $got_atime - $now), '<', 0.1, "File 2 atime set correctly"; - cmp_ok abs( $got_mtime - $now), '<', 0.1, "File 2 mtime set correctly"; + cmp_ok $got_atime - $before, '>', -0.1, "File 2 atime not before the test"; + cmp_ok $after - $got_atime, '>', -0.1, "File 2 atime not after the test"; + cmp_ok $got_mtime - $before, '>', -0.1, "File 2 mtime not before the test"; + cmp_ok $after - $got_mtime, '>', -0.1, "File 2 mtime not after the test"; } }; -- 2.9.5

Thu Jan 18 02:55:13 2018 JHI [...] cpan.org - Correspondence added

On Wed Aug 16 10:54:12 2017, ppisar wrote: Show quoted text

> Dne St 16.srp.2017 10:00:45, ppisar napsal(a):

> > t/usleep.t and t/utime.t fail randomly when built on loaded machine.

> > Attached patch fixes it. > > (I sent the patch already by e-mail, but it got lost/delayed.)

Please verify whether 1.9753 works for you, it should contain the suggested fixes.

Thu Jan 18 02:55:13 2018 The RT System itself - Status changed from 'new' to 'open'

Thu Jan 18 05:54:02 2018 ppisar [...] redhat.com - Correspondence added

Subject:	Re: [rt.cpan.org #122819] Unreliable t/usleep.t and t/utime.t tests
Date:	Thu, 18 Jan 2018 11:55:11 +0100
To:	Jarkko_Hietaniemi via RT <bug-Time-HiRes [...] rt.cpan.org>
From:	Petr Pisar <ppisar [...] redhat.com>

On Thu, Jan 18, 2018 at 02:55:13AM -0500, Jarkko_Hietaniemi via RT wrote: Show quoted text

> Please verify whether 1.9753 works for you, it should contain the suggested fixes. >

It looks fixed for me.

Download signature.asc
application/pgp-signature 228b

Message body not shown because it is not plain text.

Thu Jan 18 10:45:57 2018 JHI [...] cpan.org - Correspondence added

On Thu Jan 18 05:54:02 2018, ppisar wrote: Show quoted text

> On Thu, Jan 18, 2018 at 02:55:13AM -0500, Jarkko_Hietaniemi via RT > wrote:

> > Please verify whether 1.9753 works for you, it should contain the > > suggested fixes. > >

> It looks fixed for me.

Marking as resolved, thanks.

Thu Jan 18 10:45:58 2018 JHI [...] cpan.org - Status changed from 'open' to 'resolved'

Thu Jan 18 10:45:58 2018 JHI [...] cpan.org - Fixed in 1.9753 added