Hi, Deven.
It appears that you expect event handlers to run concurrently, which they
don't. Event handlers are run sequentially, in order of dispatch due time. In
other words, each is allowed to finish before the next is dispatched.
post() and yield() events are dispatched "as soon as possible". To keep things
fair, they are given the dispatch time of Time::HiRes::time(), which enqueues
them ahead of future timers, or behind timers that are overdue.
For example, you may have a queue of events scheduled for absolute times 10,
20, and 30 seconds from some epoch boundary. We'll call the events e_10, e_20,
and e_30, respectively.
At dispatch time, all events due prior or equal to "Now" are dispatched. If
none are due, the event loop POE is using will be asked to wait until the next
one is due.
For example, POE's default event loop uses select(). If the current time is 5,
the select() call will time out in 10-5 seconds, give or take processing time.
If there is no I/O for 5 seconds, select() returns, and e_10 is dispatched on
schedule.
Event handlers take some measurable time to execute. The faster, the better,
but many use cases can handle substantial processing delays.
Let's assume the handler for e_10 takes 15 seconds to run. The next event
(e_20) won't be dispatched until about 25 seconds past the start of the epoch.
That's 5 seconds later than it was scheduled.
In your test case, the 1/4-second processing time for each event handler means
that only 3-5 of them can be dispatched every second. You will need to make
the time-consuming tasks asynchronous or distribute the work across more cores.
--
Rocco Caputo <rcap...@pobox.com>
On Jul 12, 2012, at 01:13, Deven Parekh wrote:
> Hello POE team,
>
> I am trying to understand if the POE kernel dispatching algorithm has any
> precedence when it comes to events from yield Vs events from delay. Please
> read through the email to see if you can help me figure out what is the
> mistake i am doing here.
>
> Following is the code snipett that demonstrates my issue.
>
> <code>
> #!/usr/bin/perl
> use strict;
> use warnings;
> use Algorithm::TokenBucket;
> use Time::HiRes;
> use POE;
> use POE::Component::Schedule ;
>
> my $so_many_task = 10;
> my $so_many_seconds = 1;
> my $burst_size = 1;
> my $stop = 0;
>
> my $bucket = new Algorithm::TokenBucket $so_many_task / $so_many_seconds,
> $burst_size;
>
> my $time = Time::HiRes::time;
> my $master_session = POE::Session->create(
> inline_states => {
> _start => \&master_start,
> put_one_on_queue => \&put_one_on_queue,
> generate_tick => \&generate_tick,
> next_task => \&next_task,
> stop_scheduling => \&stop_scheduling,
> _stop => sub { },
> dummy => sub { },
> }
> );
>
> POE::Kernel->run();
> exit(0);
>
> sub master_start {
> my $kernel = $_[KERNEL];
> $_[KERNEL]->alias_set("Enqueuer");
> $_[KERNEL]->yield("generate_tick");
> $_[KERNEL]->delay( "stop_scheduling" => 1 );
> }
>
>
> sub generate_tick {
> my $kernel = $_[KERNEL];
> if ( $stop == 0 ) {
> my $after_sec = $bucket->until($burst_size);
> print "Next one after $after_sec\n";
> $_[KERNEL]->delay_add( "put_one_on_queue" => $after_sec );
> }
> }
>
> sub stop_scheduling {
> print "Stopped \n";
> }
>
> sub put_one_on_queue {
> my $kernel = $_[KERNEL];
> if ( $bucket->conform($burst_size) ) {
> print Time::HiRes::time -$time, " - Processed $burst_size more \n";
> $bucket->count($burst_size);
> $_[KERNEL]->yield("generate_tick");
> $_[KERNEL]->yield("next_task");
> }
> }
>
> sub next_task {
>
> #--- some operation that is taking about 0.2 sec
> #--- using select to show it here.
>
> #print "Started next task\n";
> select( undef, undef, undef, 0.25 );
> #print "Done with next task\n";
> }
>
> </code>
>
> <p>
> With the above code and the select statement, which i amusing to simulate
> some operation taking about .25 seconds, the output is as follows
>
> [lss@ctsauto1 misc]$ ./atbkt_2.pl
> Next one after 0.0995830059051514
> 0.100232124328613 - Processed 1 more
> Next one after 0.0998860359191895
> 0.350847959518433 - Processed 1 more
> Next one after 0.0998910427093506
> 0.60145115852356 - Processed 1 more
> Next one after 0.0998910427093506
> 0.852055072784424 - Processed 1 more
> Next one after 0.0998538494110107
> 1.10269498825073 - Processed 1 more
> Stopped
>
> *Well i was expecting 10 items to be processed in 1 second not just 5.*
>
>
> Now if i comment the select statement in the next_task routine then I get
> following output.
>
> Next one after 0.0997329711914063
> 0.100254058837891 - Processed 1 more
> Next one after 0.0999299049377441
> 0.200562953948975 - Processed 1 more
> Next one after 0.0999120235443115
> 0.300816059112549 - Processed 1 more
> Next one after 0.0999170303344727
> 0.401067018508911 - Processed 1 more
> Next one after 0.0999160766601563
> 0.501316070556641 - Processed 1 more
> Next one after 0.0999160766601563
> 0.601574897766113 - Processed 1 more
> Next one after 0.0999120235443115
> 0.701813936233521 - Processed 1 more
> Next one after 0.0999158382415772
> 0.802061080932617 - Processed 1 more
> Next one after 0.0999151229858398
> 0.902349948883057 - Processed 1 more
> Next one after 0.0999170303344727
> Stopped
> 1.0025269985199 - Processed 1 more
>
> *10 items in 1 second as expected.*
>
>
> Any help will be greatly appreciated.
>
> Thanks.
> -- DP
