adjust log levels to work better with debug level output
[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 has is_running => (is => 'ro', clearer => 'stop');
10 #maximum duration that select() will block - undef means indefinite,
11 #0 means no blocking, otherwise maximum time in seconds
12 has block_duration => ( is => 'rw' );
13
14 has _read_watches => (is => 'ro', default => sub { {} });
15 has _read_select => (is => 'ro', default => sub { IO::Select->new });
16
17 has _write_watches => (is => 'ro', default => sub { {} });
18 has _write_select => (is => 'ro', default => sub { IO::Select->new });
19
20 has _timers => (is => 'ro', default => sub { [] });
21
22 sub pass_watches_to {
23   my ($self, $new_loop) = @_;
24   log_debug { "passing watches to new run loop" };
25   foreach my $fh ($self->_read_select->handles) {
26     $new_loop->watch_io(
27       handle => $fh,
28       on_read_ready => $self->_read_watches->{$fh}
29     );
30   }
31   foreach my $fh ($self->_write_select->handles) {
32     $new_loop->watch_io(
33       handle => $fh,
34       on_write_ready => $self->_write_watches->{$fh}
35     );
36   }
37 }
38
39 sub watch_io {
40   my ($self, %watch) = @_;
41   my $fh = $watch{handle};
42   Dlog_debug { "Adding IO watch for $_" } $fh;
43   
44   if (my $cb = $watch{on_read_ready}) {
45     log_trace { "IO watcher is registering with select for reading" };
46     $self->_read_select->add($fh);
47     $self->_read_watches->{$fh} = $cb;
48   }
49   if (my $cb = $watch{on_write_ready}) {
50     log_trace { "IO watcher is registering with select for writing" };
51     $self->_write_select->add($fh);
52     $self->_write_watches->{$fh} = $cb;
53   }
54   return;
55 }
56
57 sub unwatch_io {
58   my ($self, %watch) = @_;
59   my $fh = $watch{handle};
60   Dlog_debug { "Removing IO watch for $_" } $fh;
61   if ($watch{on_read_ready}) {
62     log_trace { "IO watcher is removing read from select()" };
63     $self->_read_select->remove($fh);
64     delete $self->_read_watches->{$fh};
65   }
66   if ($watch{on_write_ready}) {
67     log_trace { "IO watcher is removing write from select()" };
68     $self->_write_select->remove($fh);
69     delete $self->_write_watches->{$fh};
70   }
71   return;
72 }
73
74 sub _sort_timers {
75   my ($self, @new) = @_;
76   my $timers = $self->_timers; 
77   
78   log_trace { "Sorting timers" };
79   
80   @{$timers} = sort { $a->[0] <=> $b->[0] } @{$timers}, @new;
81   return;   
82 }
83
84 sub watch_time {
85   my ($self, %watch) = @_;
86   my $at; 
87   
88   Dlog_trace { "watch_time() invoked with $_" } \%watch;
89  
90   if (exists($watch{every})) {
91     $at = time() + $watch{every};
92   } elsif (exists($watch{after})) {
93     $at = time() + $watch{after}; 
94   } elsif (exists($watch{at})) {
95     $at = $watch{at}; 
96   } else {
97     die "watch_time requires every, after or at";
98   }
99   
100   die "watch_time requires code" unless my $code = $watch{code};
101   my $timers = $self->_timers;
102   my $new = [ $at => $code, $watch{every} ];
103   $self->_sort_timers($new); 
104   log_debug { "Created new timer with id '$new' that expires at '$at'" };
105   return "$new";
106 }
107
108 sub unwatch_time {
109   my ($self, $id) = @_;
110   log_trace { "Removing timer with id of '$id'" };
111   @$_ = grep !($_ eq $id), @$_ for $self->_timers;
112   return;
113 }
114
115 sub _next_timer_expires_delay {
116   my ($self) = @_;
117   my $timers = $self->_timers;
118   my $delay_max = $self->block_duration;
119     
120   return $delay_max unless @$timers;
121   my $duration = $timers->[0]->[0] - time;
122
123   log_trace { "next timer fires in '$duration' seconds " };
124   
125   if ($duration < 0) {
126     $duration = 0; 
127   } elsif (defined $delay_max && $duration > $delay_max) {
128     $duration = $delay_max;
129   }
130   
131   return $duration; 
132 }
133
134 sub loop_once {
135   my ($self) = @_;
136   my $read = $self->_read_watches;
137   my $write = $self->_write_watches;
138   our $Loop_Entered = 1; 
139   my $read_count = 0;
140   my $write_count = 0; 
141   my @c = caller;
142   my $wait_time = $self->_next_timer_expires_delay;
143   log_trace {  sprintf("Run loop: loop_once() has been invoked by $c[1]:$c[2] with read:%i write:%i select timeout:%s",
144       scalar(keys(%$read)), scalar(keys(%$write)), defined $wait_time ? $wait_time : 'indefinite' ) };
145   my ($readable, $writeable) = IO::Select->select(
146     $self->_read_select, $self->_write_select, undef, $wait_time
147   ); 
148   log_trace { 
149     my $readable_count = defined $readable ? scalar(@$readable) : 0;
150     my $writable_count = defined $writeable ? scalar(@$writeable) : 0;
151     "Run loop: select returned readable:$readable_count writeable:$writable_count";
152   };
153   # I would love to trap errors in the select call but IO::Select doesn't
154   # differentiate between an error and a timeout.
155   #   -- no, love, mst.
156
157   local $Loop_Entered;
158
159   log_trace { "Reading from all ready filehandles" };
160   foreach my $fh (@$readable) {
161     next unless $read->{$fh};
162     $read_count++;
163     $read->{$fh}();
164     last if $Loop_Entered;
165   }
166   log_trace { "Writing to all ready filehandles" };
167   foreach my $fh (@$writeable) {
168     next unless $write->{$fh};
169     $write_count++;
170     $write->{$fh}();
171     last if $Loop_Entered;
172   }
173   
174   log_trace { "Read from $read_count filehandles; wrote to $write_count filehandles" };
175   my $timers = $self->_timers;
176   my $now = time();
177   log_trace { "Checking timers" };
178   while (@$timers and $timers->[0][0] <= $now) {
179     my $active = $timers->[0]; 
180     Dlog_trace { "Found timer that needs to be executed: '$active'" };
181      
182     if (defined($active->[2])) {
183       #handle the case of an 'every' timer
184       $active->[0] = time() + $active->[2]; 
185       Dlog_trace { "scheduling timer for repeat execution at $_"} $active->[0];
186       $self->_sort_timers;
187     } else {
188       #it doesn't repeat again so get rid of it  
189       shift(@$timers);    
190     }
191
192     #execute the timer
193     $active->[1]->();
194      
195     last if $Loop_Entered;
196   }
197   
198   log_trace { "Run loop: single loop is completed" };
199   return;
200 }
201
202 sub want_run {
203   my ($self) = @_;
204   Dlog_debug { "Run loop: Incrimenting want_running, is now $_" }
205     ++$self->{want_running};
206 }
207
208 sub run_while_wanted {
209   my ($self) = @_;
210   log_debug { my $wr = $self->{want_running}; "Run loop: run_while_wanted() invoked; want_running: $wr" };
211   $self->loop_once while $self->{want_running};
212   log_debug { "Run loop: run_while_wanted() completed" };
213   return;
214 }
215
216 sub want_stop {
217   my ($self) = @_;
218   if (! $self->{want_running}) {
219     log_debug { "Run loop: want_stop() was called but want_running was not true" };
220     return; 
221   }
222   Dlog_debug { "Run loop: decrimenting want_running, is now $_" }
223     --$self->{want_running};
224 }
225
226 sub run {
227   my ($self) = @_;
228   log_trace { "Run loop: run() invoked" };
229   local $self->{is_running} = 1;
230   while ($self->is_running) {
231     $self->loop_once;
232   }
233   log_trace { "Run loop: run() completed" };
234   return;
235 }
236
237 1;