Re: Do events due to yield have higher precedence than those due to delay for kernel dispatch?

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.

--=20
Rocco Caputo <[email protected]>

On Jul 12, 2012, at 01:13, Deven Parekh wrote:

> Hello POE team,
>=20
> 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.
>=20
> Following is the code snipett that demonstrates my issue.
>=20
> <code>
> #!/usr/bin/perl
> use strict;
> use warnings;
> use Algorithm::TokenBucket;
> use Time::HiRes;
> use POE;
> use POE::Component::Schedule ;
>=20
> my $so_many_task =3D 10;
> my $so_many_seconds =3D 1;
> my $burst_size =3D 1;
> my $stop =3D 0;
>=20
> my $bucket =3D new Algorithm::TokenBucket $so_many_task / =
$so_many_seconds,
>  $burst_size;
>=20
> my $time           =3D Time::HiRes::time;
> my $master_session =3D POE::Session->create(
>    inline_states =3D> {
>        _start           =3D> \&master_start,
>        put_one_on_queue =3D> \&put_one_on_queue,
>        generate_tick    =3D> \&generate_tick,
>        next_task        =3D> \&next_task,
>        stop_scheduling  =3D> \&stop_scheduling,
>        _stop            =3D> sub { },
>        dummy            =3D> sub { },
>    }
> );
>=20
> POE::Kernel->run();
> exit(0);
>=20
> sub master_start {
>    my $kernel =3D $_[KERNEL];
>    $_[KERNEL]->alias_set("Enqueuer");
>    $_[KERNEL]->yield("generate_tick");
>    $_[KERNEL]->delay( "stop_scheduling" =3D> 1 );
> }
>=20
>=20
> sub generate_tick {
>    my $kernel =3D $_[KERNEL];
>    if ( $stop =3D=3D 0 ) {
>        my $after_sec =3D $bucket->until($burst_size);
>        print "Next one after $after_sec\n";
>        $_[KERNEL]->delay_add( "put_one_on_queue" =3D> $after_sec );
>    }
> }
>=20
> sub stop_scheduling {
>    print "Stopped \n";
> }
>=20
> sub put_one_on_queue {
>    my $kernel =3D $_[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");
>    }
> }
>=20
> sub next_task {
>=20
>    #--- some operation that is taking about 0.2 sec
>    #--- using select to show it here.
>=20
>    #print "Started next task\n";
>    select( undef, undef, undef, 0.25 );
>    #print "Done with next task\n";
> }
>=20
> </code>
>=20
> <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
>=20
> [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
>=20
> *Well i was expecting 10 items to be processed in 1 second not just =
5.*
>=20
>=20
> Now if i comment the select statement in the next_task routine then I =
get
> following output.
>=20
> 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
>=20
> *10 items in 1 second as expected.*
>=20
>=20
> Any help will be greatly appreciated.
>=20
> Thanks.
> -- DP