| Subject: | Weird signal pipe behavior after daemonization ( 100% CPU ) |
Hello,
While debugging Getty's craptastic modules ( hah! ) I was able to
narrow down the spinlock problem to this testcase. It seems like the
internals doesn't like MooseX::Daemonize's method of daemonization and
things blow up.
How to reproduce:
1. Download POECrasher.pm and save it somewhere
2. POE_TRACE_DEFAULT=1 perl -I. -MPOECrasher -e'POECrasher->run' start
3. Wait a bit
4. Look at top ( and see the process is using 100% cpu )
5. Look at poe.log ( it should have output showing POE repeatedly
trying to read from the signal pipe and getting 0 bytes from it )
6. perl -I. -MPOECrasher -e'POECrasher->run' stop
Well, I sorta lied above - poe.log is cut off shortly after forking -
there seems to be a problem with TRACE_FILENAME's implementation. I
think the internals doesn't re-open the FH after forking...
What I did was hack POE::Kernel to re-open it in sub has_forked() BUT
that didn't work! I gave up and just set a $SIG{__WARN__} handler that
printed it to a file... This is a separate bug, ha!
Oh, this seems to not be 100% reproducible on my box ( probably some
timing issues ) but it happens reliably - just retry until you see 100%
cpu usage...
This is perl, v5.10.0 built for x86_64-linux-gnu-thread-multi
On a Linux Ubuntu 9.10 Karmic box
Here's a sample of what the trace shows: ( it's repeated bazillions of
times in the log ) - notice that it reads 0 bytes from the signal pipe
and keeps trying to read from it...
401: <ev> Kernel::run() iterating. now(31.3658) timeout(29.4168)
then(60.7826)
401: <fh> ,----- SELECT BITS IN -----
401: <fh> | READ : 00010000
401: <fh> | WRITE : 00000000
401: <fh> | EXPEDITE: 00000000
401: <fh> `--------------------------
401: <fh> select hits = 1
401: <fh> ,----- SELECT BITS OUT -----
401: <fh> | READ : 00010000
401: <fh> | WRITE : 00000000
401: <fh> | EXPEDITE: 00000000
401: <fh> `---------------------------
401: <fh> found pending rd selects: 3
401: <sg> Read 0 bytes from signal pipe at
/usr/local/share/perl/5.10.0/POE/Resource/Signals.pm line 862
401: <rc> trying sweep at
/usr/local/share/perl/5.10.0/POE/Resource/Sessions.pm line 339
401: <ev> time(1296851403.78262) id(4)
event(POE::Kernel=ARRAY(0x26d1cd0) POE::Kernel=ARRAY(0x26d1cd0)
_stat_tick 2048 ARRAY(0x30b0438)
/usr/local/share/perl/5.10.0/POE/Resource/Statistics.pm 40 (undef))
401: <ev> time(1296851403.78262) id(5)
event(POE::Session=ARRAY(0x30b6710) POE::Session=ARRAY(0x30b6710)
STARTALL 1 ARRAY(0x2736810) generated method (unknown origin) 28 _start)
401: <ev> time(1296851403.78262) id(6)
event(POE::Session=ARRAY(0x30b6710) POE::Session=ARRAY(0x30b6710)
_garbage_collect 32 ARRAY(0x30ae360)
/usr/local/share/perl/5.10.0/POE/Kernel.pm 1530 (undef))
401: <rc> trying sweep at
/usr/local/share/perl/5.10.0/POE/Resource/Sessions.pm line 339
401: <rc> ,----- Kernel Activity -----
401: <rc> | Events : 3 (vs. idle size = 1)
401: <rc> | Files : 0
401: <rc> | Extra : 0
401: <rc> | Procs :
401: <rc> `---------------------------
401: <rc> ... at /usr/local/share/perl/5.10.0/POE/Kernel.pm line 673
401: <ev> Kernel::run() iterating. now(31.3665) timeout(29.4162)
then(60.7826)
401: <fh> ,----- SELECT BITS IN -----
401: <fh> | READ : 00010000
401: <fh> | WRITE : 00000000
401: <fh> | EXPEDITE: 00000000
401: <fh> `--------------------------
401: <fh> select hits = 1
401: <fh> ,----- SELECT BITS OUT -----
401: <fh> | READ : 00010000
401: <fh> | WRITE : 00000000
401: <fh> | EXPEDITE: 00000000
401: <fh> `---------------------------
401: <fh> found pending rd selects: 3
401: <sg> Read 0 bytes from signal pipe at
/usr/local/share/perl/5.10.0/POE/Resource/Signals.pm line 862
401: <rc> trying sweep at
/usr/local/share/perl/5.10.0/POE/Resource/Sessions.pm line 339
401: <ev> time(1296851403.78262) id(4)
event(POE::Kernel=ARRAY(0x26d1cd0) POE::Kernel=ARRAY(0x26d1cd0)
_stat_tick 2048 ARRAY(0x30b0438)
/usr/local/share/perl/5.10.0/POE/Resource/Statistics.pm 40 (undef))
401: <ev> time(1296851403.78262) id(5)
event(POE::Session=ARRAY(0x30b6710) POE::Session=ARRAY(0x30b6710)
STARTALL 1 ARRAY(0x2736810) generated method (unknown origin) 28 _start)
401: <ev> time(1296851403.78262) id(6)
event(POE::Session=ARRAY(0x30b6710) POE::Session=ARRAY(0x30b6710)
_garbage_collect 32 ARRAY(0x30ae360)
/usr/local/share/perl/5.10.0/POE/Kernel.pm 1530 (undef))
401: <rc> trying sweep at
/usr/local/share/perl/5.10.0/POE/Resource/Sessions.pm line 339
401: <rc> ,----- Kernel Activity -----
401: <rc> | Events : 3 (vs. idle size = 1)
401: <rc> | Files : 0
401: <rc> | Extra : 0
401: <rc> | Procs :
401: <rc> `---------------------------
401: <rc> ... at /usr/local/share/perl/5.10.0/POE/Kernel.pm line 673
401: <ev> Kernel::run() iterating. now(31.3672) timeout(29.4155)
then(60.7826)
401: <fh> ,----- SELECT BITS IN -----
401: <fh> | READ : 00010000
401: <fh> | WRITE : 00000000
401: <fh> | EXPEDITE: 00000000
401: <fh> `--------------------------
401: <fh> select hits = 1
401: <fh> ,----- SELECT BITS OUT -----
401: <fh> | READ : 00010000
401: <fh> | WRITE : 00000000
401: <fh> | EXPEDITE: 00000000
401: <fh> `---------------------------
401: <fh> found pending rd selects: 3
401: <sg> Read 0 bytes from signal pipe at
/usr/local/share/perl/5.10.0/POE/Resource/Signals.pm line 862
401: <rc> trying sweep at
/usr/local/share/perl/5.10.0/POE/Resource/Sessions.pm line 339
401: <ev> time(1296851403.78262) id(4)
event(POE::Kernel=ARRAY(0x26d1cd0) POE::Kernel=ARRAY(0x26d1cd0)
_stat_tick 2048 ARRAY(0x30b0438)
/usr/local/share/perl/5.10.0/POE/Resource/Statistics.pm 40 (undef))
401: <ev> time(1296851403.78262) id(5)
event(POE::Session=ARRAY(0x30b6710) POE::Session=ARRAY(0x30b6710)
STARTALL 1 ARRAY(0x2736810) generated method (unknown origin) 28 _start)
401: <ev> time(1296851403.78262) id(6)
event(POE::Session=ARRAY(0x30b6710) POE::Session=ARRAY(0x30b6710)
_garbage_collect 32 ARRAY(0x30ae360)
/usr/local/share/perl/5.10.0/POE/Kernel.pm 1530 (undef))
401: <rc> trying sweep at
/usr/local/share/perl/5.10.0/POE/Resource/Sessions.pm line 339
401: <rc> ,----- Kernel Activity -----
401: <rc> | Events : 3 (vs. idle size = 1)
401: <rc> | Files : 0
401: <rc> | Extra : 0
401: <rc> | Procs :
401: <rc> `---------------------------
401: <rc> ... at /usr/local/share/perl/5.10.0/POE/Kernel.pm line 673
401: <ev> Kernel::run() iterating. now(31.3678) timeout(29.4148)
then(60.7826)
--
~Apocalypse
| Subject: | POECrasher.pm |
package POECrasher;
BEGIN {
my $logfile = '/home/apoc/poecrasher/poe.log';
# Make sure we are capturing traces from POE
$SIG{'__WARN__'} = sub {
my $l = $_[0];
$l =~ s/(?:\r|\n)+$//;
open my $fh, '>>', $logfile or die "Unable to open $logfile: $!";
print $fh "$l\n";
close $fh;
return;
};
}
use MooseX::POE;
with 'MooseX::Daemonize';
has '+pidbase' => (
default => sub { require Cwd; return Cwd::getcwd(); },
);
has _session => (
is => 'rw',
isa => 'POE::Session',
);
after start => sub {
my $self = shift;
return unless $self->is_daemon;
POE::Kernel->run;
};
sub run {
my ( $self ) = @_;
POE::Kernel->run;
if (!blessed $self) {
$self = $self->new_with_options;
}
my ( $command ) = @{$self->extra_argv};
if (!defined $command) {
if ($self->status) {
print "POECrasher already running...\n";
exit 0;
} else {
$command = 'start';
}
}
$self->start if $command eq 'start';
if ($command eq 'status') {
print "POECrasher is ".( $self->status ? '' : 'not ')."running...\n";
exit $self->status ? 0 : 1;
}
$self->restart if $command eq 'restart';
$self->stop if $command eq 'stop';
exit $self->exit_code;
}
sub START {
my ( $self, $session ) = @_[ OBJECT, SESSION ];
$self->_session($session);
$self->yield( 'looper' );
return;
}
event looper => sub {
my ($self) = @_;
$self->delay( 'looper' => 10 );
return;
};
__PACKAGE__->meta->make_immutable;
1;