Preferred bug tracker

Please visit the preferred bug tracker to report your issue.

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

Report information
The Basics
Id:
122819
Status:
resolved
Priority:
Low/Low
Queue:

People
Owner:
Nobody in particular
Requestors:
ppisar [...] redhat.com
Cc:
AdminCc:

BugTracker
Severity:
(no value)
Broken in:
1.9745
Fixed in:
1.9753

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



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).
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.
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
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.
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.

Message body not shown because it is not plain text.

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.


This service runs on Request Tracker, is sponsored by The Perl Foundation, and maintained by Best Practical Solutions.

Please report any issues with rt.cpan.org to rt-cpan-admin@bestpractical.com.