more log lines - found deadlock where controller blocks on read seemingly outside...
[scpubgit/Object-Remote.git] / lib / Object / Remote / MiniLoop.pm
1 package Object::Remote::MiniLoop;
2
3 use IO::Select;
4 use Time::HiRes qw(time);
5 use Object::Remote::Logging qw( :log :dlog );
6 use Moo;
7
8 # this is ro because we only actually set it using local in sub run
9
10 has is_running => (is => 'ro', clearer => 'stop');
11
12 has _read_watches => (is => 'ro', default => sub { {} });
13 has _read_select => (is => 'ro', default => sub { IO::Select->new });
14
15 has _write_watches => (is => 'ro', default => sub { {} });
16 has _write_select => (is => 'ro', default => sub { IO::Select->new });
17
18 has _timers => (is => 'ro', default => sub { [] });
19
20 sub pass_watches_to {
21   my ($self, $new_loop) = @_;
22   log_debug { "passing watches to new run loop" };
23   foreach my $fh ($self->_read_select->handles) {
24     $new_loop->watch_io(
25       handle => $fh,
26       on_read_ready => $self->_read_watches->{$fh}
27     );
28   }
29   foreach my $fh ($self->_write_select->handles) {
30     $new_loop->watch_io(
31       handle => $fh,
32       on_write_ready => $self->_write_watches->{$fh}
33     );
34   }
35 }
36
37 sub watch_io {
38   my ($self, %watch) = @_;
39   my $fh = $watch{handle};
40   log_debug { my $type = ref($fh); "Adding watch for ref of type '$type'" };
41   if (my $cb = $watch{on_read_ready}) {
42     log_trace { "IO watcher on_read_ready has been invoked" };
43     $self->_read_select->add($fh);
44     $self->_read_watches->{$fh} = $cb;
45   }
46   if (my $cb = $watch{on_write_ready}) {
47     log_trace { "IO watcher on_write_ready has been invoked" };
48     $self->_write_select->add($fh);
49     $self->_write_watches->{$fh} = $cb;
50   }
51   return;
52 }
53
54 sub unwatch_io {
55   my ($self, %watch) = @_;
56   my $fh = $watch{handle};
57   log_debug { my $type = ref($fh); "Removing watch for ref of type '$type'" };
58   if ($watch{on_read_ready}) {
59     $self->_read_select->remove($fh);
60     delete $self->_read_watches->{$fh};
61   }
62   if ($watch{on_write_ready}) {
63     $self->_write_select->remove($fh);
64     delete $self->_write_watches->{$fh};
65   }
66   return;
67 }
68
69 sub watch_time {
70   my ($self, %watch) = @_;
71   my $at = $watch{at} || do {
72     die "watch_time requires at or after" unless my $after = $watch{after};
73     time() + $after;
74   };
75   die "watch_time requires code" unless my $code = $watch{code};
76   my $timers = $self->_timers;
77   my $new = [ $at => $code ];
78   @{$timers} = sort { $a->[0] <=> $b->[0] } @{$timers}, $new;
79   log_debug { "Created new timer that expires at '$at'" };
80   return "$new";
81 }
82
83 sub unwatch_time {
84   my ($self, $id) = @_;
85   log_debug { "Removing timer with id of '$id'" };
86   @$_ = grep !($_ eq $id), @$_ for $self->_timers;
87   return;
88 }
89
90 sub _next_timer_expires_delay {
91   my ($self) = @_;
92   my $timers = $self->_timers;
93   #undef means no timeout, only returns
94   #when data is ready - when the system
95   #deadlocks the chatter from the timeout in
96   #select clogs up the logs
97   my $delay_max = undef;
98     
99   return $delay_max unless @$timers;
100   my $duration = $timers->[0]->[0] - time;
101
102   log_trace { "next timer fires in '$duration' seconds " };
103   
104   if ($duration < 0) {
105     $duration = 0; 
106   } elsif (! defined($delay_max)) {
107     $duration = undef; 
108   } elsif ($duration > $delay_max) {
109     $duration = $delay_max; 
110   }
111     
112   return $duration; 
113 }
114
115 sub loop_once {
116   my ($self) = @_;
117   my $read = $self->_read_watches;
118   my $write = $self->_write_watches;
119   my $read_count = 0;
120   my $write_count = 0; 
121   my @c = caller;
122   my $wait_time = $self->_next_timer_expires_delay;
123   log_debug {  sprintf("Run loop: loop_once() has been invoked by $c[1]:$c[2] with read:%i write:%i select timeout:%s",
124       scalar(keys(%$read)), scalar(keys(%$write)), defined $wait_time ? $wait_time : 'indefinite' ) };
125   my ($readable, $writeable) = IO::Select->select(
126     $self->_read_select, $self->_write_select, undef, $wait_time
127   ); 
128   log_debug { 
129     my $readable_count = defined $readable ? scalar(@$readable) : 0;
130     my $writable_count = defined $writeable ? scalar(@$writeable) : 0;
131     "Run loop: select returned readable:$readable_count writeable:$writable_count";
132   };
133   # I would love to trap errors in the select call but IO::Select doesn't
134   # differentiate between an error and a timeout.
135   #   -- no, love, mst.
136   log_trace { "Reading from all ready filehandles" };
137   foreach my $fh (@$readable) {
138     next unless $read->{$fh};
139     $read_count++;
140     $read->{$fh}();
141 #    $read->{$fh}() if $read->{$fh};
142   }
143   log_trace { "Writing to all ready filehandles" };
144   foreach my $fh (@$writeable) {
145     next unless $write->{$fh};
146     $write_count++;
147     $write->{$fh}();
148 #    $write->{$fh}() if $write->{$fh};
149   }
150   log_trace { "Read from $read_count filehandles; wrote to $write_count filehandles" };
151   my $timers = $self->_timers;
152   my $now = time();
153   log_trace { "Checking timers" };
154   while (@$timers and $timers->[0][0] <= $now) {
155     Dlog_debug { "Found timer that needs to be executed: $_" } $timers->[0];
156     (shift @$timers)->[1]->();
157   }
158   log_debug { "Run loop: single loop is completed" };
159   return;
160 }
161
162 sub want_run {
163   my ($self) = @_;
164   Dlog_debug { "Run loop: Incrimenting want_running, is now $_" }
165     ++$self->{want_running};
166 }
167
168 sub run_while_wanted {
169   my ($self) = @_;
170   log_debug { "Run loop: run_while_wanted() invoked" };
171   $self->loop_once while $self->{want_running};
172   log_debug { "Run loop: run_while_wanted() completed" };
173   return;
174 }
175
176 sub want_stop {
177   my ($self) = @_;
178   if (! $self->{want_running}) {
179     log_debug { "Run loop: want_stop() was called but want_running was not true" };
180     return; 
181   }
182   Dlog_debug { "Run loop: decrimenting want_running, is now $_" }
183     --$self->{want_running};
184 }
185
186 sub run {
187   my ($self) = @_;
188   log_info { "Run loop: run() invoked" };
189   local $self->{is_running} = 1;
190   while ($self->is_running) {
191     $self->loop_once;
192   }
193   log_info { "Run loop: run() completed" };
194   return;
195 }
196
197 1;