On Tue Dec 27 09:26:23 2011, CARNIL wrote:
Show quoted text> > # Failed test 'Other timers still fire after self-cancelling one'
> > # at /usr/share/perl5/IO/Async/LoopTests.pm line 458.
> > # got: undef
> > # expected: '1'
> > # Looks like you failed 1 test of 15.
> > t/02loop-timer.t ....
> > Dubious, test returned 1 (wstat 256, 0x100)
> > Failed 1/15 subtests
I see there are a dozen similar similar failures now on the CPAN tester
reports so it's not just us.
I looked into this, and the bug seems to be in timeouts rounding down
to the nearest full millisecond. See the commit messages of the attached
proposed patches. Hope they make the problem clear enough, let me know
if you need more information.
As the failures are easily reproducible for me, I can also easily
provide straces if you like. Just let me know (but note that I'm
currently not in the CC field of this ticket; feel free to add me though.)
Many thanks for your work,
--
Niko Tyni (Debian Perl Group)
ntyni@debian.org
From eab695afa987bde81db22f0dc7f689677cef6794 Mon Sep 17 00:00:00 2001
From: Niko Tyni <ntyni@debian.org>
Date: Sun, 1 Apr 2012 15:16:04 +0300
Subject: [PATCH 2/2] Fix loop_once() returning too soon
epoll_pwait() uses an integer millisecond value for its timeout parameter,
so round up any fractional values. This avoids early returns during the
very last millisecond before the next scheduled event.
As detailed in the previous commit message, this should fix the
intermittent t/02loop-timer.t failures seen in [rt.cpan.org #73498].
---
lib/IO/Async/Loop/Epoll.pm | 4 ++--
t/07loop-once.t | 2 --
2 files changed, 2 insertions(+), 4 deletions(-)
diff --git a/lib/IO/Async/Loop/Epoll.pm b/lib/IO/Async/Loop/Epoll.pm
index 9f577c3..abb818d 100644
--- a/lib/IO/Async/Loop/Epoll.pm
+++ b/lib/IO/Async/Loop/Epoll.pm
@@ -22,7 +22,7 @@ use IO::Epoll qw(
EPOLLIN EPOLLOUT EPOLLHUP EPOLLERR
);
-use POSIX qw( EINTR EPERM SIG_BLOCK SIG_UNBLOCK sigprocmask sigaction );
+use POSIX qw( EINTR EPERM SIG_BLOCK SIG_UNBLOCK sigprocmask sigaction ceil );
=head1 NAME
@@ -143,7 +143,7 @@ sub loop_once
$self->_adjust_timeout( \$timeout );
- my $msec = defined $timeout ? $timeout * 1000 : -1;
+ my $msec = defined $timeout ? ceil($timeout * 1000) : -1;
my $ret = epoll_pwait( $self->{epoll}, $self->{maxevents}, $msec, $self->{sigmask} );
diff --git a/t/07loop-once.t b/t/07loop-once.t
index 2cad2e3..5b46109 100644
--- a/t/07loop-once.t
+++ b/t/07loop-once.t
@@ -19,9 +19,7 @@ for my $delay (@delays) {
$i++ while
!$loop->loop_once( 1 ) # callback not triggered yet
&& (time() - $starttime < 1); # guard against infinite loops
- TODO: { local $::TODO = "[rt.cpan.org #73498]";
is ($i, 1, "Just one loop run is enough to wait $delay seconds");
- }
is ($done, 1, "Timer actually got triggered within one second");
}
--
1.7.9.1
From 9a6a6e60897777a4c220890ba709eb5ea3572418 Mon Sep 17 00:00:00 2001
From: Niko Tyni <ntyni@debian.org>
Date: Sun, 1 Apr 2012 14:10:00 +0300
Subject: [PATCH 1/2] TODO tests to detect loop_once() returning too soon
The intermittent t/02loop-timer.t failures seen in [rt.cpan.org #73498]
happen because epoll_pwait() uses an integer millisecond value for its
timeout parameter, so fractional values will get rounded down. The
loop_once() method of IO::Async::Loop::Epoll doesn't take this into
account, so the next scheduled callback may therefore well not get
triggered on just one loop_once() call.
If control comes back to the calling code before the remaining millisecond
is spent, the next loop_once() call will end up calling epoll_pwait()
with a timeout of zero, which makes it return immediately. This may result
in a busy loop of several loop_once() calls until the millisecond tick
actually happens.
Add (hopefully) more deterministic TODO tests to detect such
situations. As IO::Async::Loop will never sleep more than one second
($MAX_SIGWAIT_TIME), we test with a range of timeouts between one and
700 milliseconds that loop_once() will only return when a callback has
actually been called.
The busy loop seems to be longer on the small timeouts - perhaps
epoll_pwait(2) uses a finer resolution for shorter timeouts than the
longer ones?
---
MANIFEST | 1 +
t/07loop-once.t | 27 +++++++++++++++++++++++++++
2 files changed, 28 insertions(+), 0 deletions(-)
create mode 100644 t/07loop-once.t
diff --git a/MANIFEST b/MANIFEST
index 0010c9e..fc55176 100644
--- a/MANIFEST
+++ b/MANIFEST
@@ -14,4 +14,5 @@ t/03loop-signal.t
t/04loop-idle.t
t/05loop-child.t
t/06loop-control.t
+t/07loop-once.t
t/99pod.t
diff --git a/t/07loop-once.t b/t/07loop-once.t
new file mode 100644
index 0000000..2cad2e3
--- /dev/null
+++ b/t/07loop-once.t
@@ -0,0 +1,27 @@
+#!/usr/bin/perl -w
+my @delays;
+
+BEGIN { @delays = (.001, .005, .007, .01, .05, .07, .1, .5, .7) }
+
+use strict;
+use Test::More tests => 2 * @delays;
+use Time::HiRes q/time/;
+
+use IO::Async::Loop::Epoll;
+my $loop = IO::Async::Loop::Epoll->new;
+
+for my $delay (@delays) {
+ my $done;
+ my $i = 1;
+ my $starttime = time();
+
+ $loop->enqueue_timer( delay => $delay, code => sub { $done++ } );
+ $i++ while
+ !$loop->loop_once( 1 ) # callback not triggered yet
+ && (time() - $starttime < 1); # guard against infinite loops
+ TODO: { local $::TODO = "[rt.cpan.org #73498]";
+ is ($i, 1, "Just one loop run is enough to wait $delay seconds");
+ }
+ is ($done, 1, "Timer actually got triggered within one second");
+}
+
--
1.7.9.1
