Right, I updated the log too, now I have:
self.do_assign_tasks = False
logger.debug('send_heartbeat(), do_assign_tasks=%s', self.do_assign_tasks )
if counter % 5 == 0 or mybackedstatus == PICK:
and
if self.worker_status[0] == ACTIVE:
logger.debug('Inside If, do_assign_tasks=%s', self.do_assign_tasks )
self.do_assign_tasks = True
I can send a patch with the added logs if it helps, and the complete log
file as well.
The log are:
2013-04-03 08:49:47,990 - web2py.scheduler.mapserver#5108 - DEBUG -
........recording heartbeat (ACTIVE)
2013-04-03 08:49:47,990 - web2py.scheduler.mapserver#5108 - DEBUG -
send_heartbeat(), do_assign_tasks=False
2013-04-03 08:49:47,990 - web2py.scheduler.mapserver#5108 - DEBUG -
freeing workers that have not sent heartbeat
2013-04-03 08:49:47,992 - web2py.scheduler.mapserver#5108 - INFO - TICKER:
I'm a ticker
2013-04-03 08:49:48,029 - web2py.scheduler.mapserver#5108 - DEBUG -
looping...
2013-04-03 08:49:48,029 - web2py.scheduler.mapserver#5108 - INFO - pop task
True False
2013-04-03 08:49:48,143 - web2py.scheduler.mapserver#5108 - DEBUG -
is_a_ticker := True, worker_status[0] := ACTIVE
2013-04-03 08:49:48,143 - web2py.scheduler.mapserver#5108 - DEBUG - Inside
If, do_assign_tasks=False
2013-04-03 08:49:48,159 - web2py.scheduler.mapserver#5108 - INFO - nothing
to do
2013-04-03 08:49:48,159 - web2py.scheduler.mapserver#5108 - DEBUG -
sleeping...
2013-04-03 08:49:51,147 - web2py.scheduler.mapserver#5108 - DEBUG -
........recording heartbeat (ACTIVE)
2013-04-03 08:49:51,148 - web2py.scheduler.mapserver#5108 - DEBUG -
send_heartbeat(), do_assign_tasks=False
2013-04-03 08:49:51,162 - web2py.scheduler.mapserver#5108 - DEBUG -
looping...
2013-04-03 08:49:51,162 - web2py.scheduler.mapserver#5108 - INFO - pop task
True False
2013-04-03 08:49:51,292 - web2py.scheduler.mapserver#5108 - INFO - nothing
to do
2013-04-03 08:49:51,292 - web2py.scheduler.mapserver#5108 - DEBUG -
sleeping...
2013-04-03 08:49:54,288 - web2py.scheduler.mapserver#5108 - DEBUG -
........recording heartbeat (ACTIVE)
2013-04-03 08:49:54,289 - web2py.scheduler.mapserver#5108 - DEBUG -
send_heartbeat(), do_assign_tasks=False
2013-04-03 08:49:54,295 - web2py.scheduler.mapserver#5108 - DEBUG -
looping...
2013-04-03 08:49:54,295 - web2py.scheduler.mapserver#5108 - INFO - pop task
True False
2013-04-03 08:49:54,475 - web2py.scheduler.mapserver#5108 - INFO - nothing
to do
2013-04-03 08:49:54,475 - web2py.scheduler.mapserver#5108 - DEBUG -
sleeping...
2013-04-03 08:49:57,430 - web2py.scheduler.mapserver#5108 - DEBUG -
........recording heartbeat (ACTIVE)
2013-04-03 08:49:57,430 - web2py.scheduler.mapserver#5108 - DEBUG -
send_heartbeat(), do_assign_tasks=False
2013-04-03 08:49:57,479 - web2py.scheduler.mapserver#5108 - DEBUG -
looping...
2013-04-03 08:49:57,479 - web2py.scheduler.mapserver#5108 - INFO - pop task
True False
2013-04-03 08:49:57,583 - web2py.scheduler.mapserver#5108 - INFO - nothing
to do
2013-04-03 08:49:57,584 - web2py.scheduler.mapserver#5108 - DEBUG -
sleeping...
2013-04-03 08:50:00,579 - web2py.scheduler.mapserver#5108 - DEBUG -
........recording heartbeat (ACTIVE)
2013-04-03 08:50:00,579 - web2py.scheduler.mapserver#5108 - DEBUG -
send_heartbeat(), do_assign_tasks=False
2013-04-03 08:50:00,587 - web2py.scheduler.mapserver#5108 - DEBUG -
looping...
2013-04-03 08:50:00,587 - web2py.scheduler.mapserver#5108 - INFO - pop task
True False
2013-04-03 08:50:00,717 - web2py.scheduler.mapserver#5108 - INFO - nothing
to do
2013-04-03 08:50:00,717 - web2py.scheduler.mapserver#5108 - DEBUG -
sleeping...
2013-04-03 08:50:03,711 - web2py.scheduler.mapserver#5108 - DEBUG -
........recording heartbeat (ACTIVE)
2013-04-03 08:50:03,712 - web2py.scheduler.mapserver#5108 - DEBUG -
send_heartbeat(), do_assign_tasks=False
Regards,
Paolo
2013/4/2 Niphlod <niph...@gmail.com>
> I can't tell what logs line have been added (I see new lines but I don't
> know what is the line following "if counter ...." and what is the one
> following "if self.worker_status[0] ....")
>
>
> On Tuesday, April 2, 2013 11:05:11 AM UTC+2, Paolo valleri wrote:
>
>> Hi Niphlod, sorry for the late answer, I hadn't access to the involved
>> server.
>> I added the two logs lines you proposed, below the logs:
>> 2013-04-02 09:38:14,561 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> ........recording heartbeat (ACTIVE)
>> 2013-04-02 09:38:14,562 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> send_heartbeat(), do_assign_tasks=False
>> 2013-04-02 09:38:14,562 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> freeing workers that have not sent heartbeat
>> 2013-04-02 09:38:14,564 - web2py.scheduler.mapserver#**4162 - INFO -
>> TICKER: I'm a ticker
>> 2013-04-02 09:38:14,644 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> looping...
>> 2013-04-02 09:38:14,652 - web2py.scheduler.mapserver#**4162 - INFO - pop
>> task True False
>> 2013-04-02 09:38:14,723 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> is_a_ticker := True, worker_status[0] := ACTIVE
>> 2013-04-02 09:38:14,732 - web2py.scheduler.mapserver#**4162 - INFO -
>> nothing to do
>> 2013-04-02 09:38:14,732 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> sleeping...
>> 2013-04-02 09:38:17,727 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> ........recording heartbeat (ACTIVE)
>> 2013-04-02 09:38:17,728 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> send_heartbeat(), do_assign_tasks=True
>> 2013-04-02 09:38:17,735 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> looping...
>> 2013-04-02 09:38:17,736 - web2py.scheduler.mapserver#**4162 - INFO - pop
>> task True False
>> 2013-04-02 09:38:17,916 - web2py.scheduler.mapserver#**4162 - INFO -
>> nothing to do
>> 2013-04-02 09:38:17,916 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> sleeping...
>> 2013-04-02 09:38:20,871 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> ........recording heartbeat (ACTIVE)
>> 2013-04-02 09:38:20,872 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> send_heartbeat(), do_assign_tasks=False
>> 2013-04-02 09:38:20,919 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> looping...
>> 2013-04-02 09:38:20,920 - web2py.scheduler.mapserver#**4162 - INFO - pop
>> task True False
>> 2013-04-02 09:38:21,050 - web2py.scheduler.mapserver#**4162 - INFO -
>> nothing to do
>> 2013-04-02 09:38:21,050 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> sleeping...
>> 2013-04-02 09:38:24,045 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> ........recording heartbeat (ACTIVE)
>> 2013-04-02 09:38:24,046 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> send_heartbeat(), do_assign_tasks=False
>> 2013-04-02 09:38:24,054 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> looping...
>> 2013-04-02 09:38:24,054 - web2py.scheduler.mapserver#**4162 - INFO - pop
>> task True False
>> 2013-04-02 09:38:24,234 - web2py.scheduler.mapserver#**4162 - INFO -
>> nothing to do
>> 2013-04-02 09:38:24,234 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> sleeping...
>> 2013-04-02 09:38:27,193 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> ........recording heartbeat (ACTIVE)
>> 2013-04-02 09:38:27,193 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> send_heartbeat(), do_assign_tasks=False
>> 2013-04-02 09:38:27,238 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> looping...
>> 2013-04-02 09:38:27,238 - web2py.scheduler.mapserver#**4162 - INFO - pop
>> task True False
>> 2013-04-02 09:38:27,368 - web2py.scheduler.mapserver#**4162 - INFO -
>> nothing to do
>> 2013-04-02 09:38:27,368 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> sleeping...
>> 2013-04-02 09:38:30,360 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> ........recording heartbeat (ACTIVE)
>> 2013-04-02 09:38:30,361 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> send_heartbeat(), do_assign_tasks=False
>> 2013-04-02 09:38:30,361 - web2py.scheduler.mapserver#**4162 - DEBUG -
>> freeing workers that have not sent heartbeat
>> 2013-04-02 09:38:30,363 - web2py.scheduler.mapserver#**4162 - INFO -
>> TICKER: I'm a ticker
>>
>>
>>
>> Paolo
>>
>>
>> 2013/3/27 Niphlod <nip...@gmail.com>
>>
>>> it was just a trial.
>>> Explaining it further, let's see if someone spots the **supposed**
>>> implementation error....
>>>
>>> In order to separate transactions and avoid "task contention" among
>>> several workers, we need the **master** steps to both assign tasks and
>>> process tasks.
>>>
>>> The **thread** steps inserts a virtual "assign the task" job setting the
>>> do_assign_task flag to True when necessary.
>>> When that is found to be true, **worker** assigns tasks and sleeps for 3
>>> seconds, giving the change to the send_heartbeat() to reset the
>>> do_assign_task to False, so you don't have consecutive "assign_tasks" over
>>> and over.
>>>
>>> Skipping over the actual steps taken, a **master** does a loop and
>>> sleeps.
>>>
>>> In that loop, if do_assign_task is True, it assign tasks, returns "None"
>>> --> goes to sleep for 3 seconds
>>>
>>> A **thread** does some cleanup, sleeps for 3 seconds and sets the
>>> do_assign_task every 5 cycles.
>>>
>>> Ok, to be fair it's not guaranteed that a loop in either of those
>>> completes in 3 seconds, but the **steps** for both (when the **worker**
>>> doesn't anything) take a few ms (i.e. scheduler doesn't take into account
>>> how many ms passed between the start of either loop before setting the
>>> sleep of 3 seconds...)
>>>
>>> So, self.sleep() in normal condition gets called:
>>> - at every loop of the **thread** (at the end of the send_heartbeat())
>>> - at every loop of the **master** when it has no tasks or when it assign
>>> tasks (at the end of the loop() function)
>>>
>>> What you are experiencing is that, even if the **thread** sets correctly
>>> do_assign_tasks = True, when the **worker** tries to pop something for some
>>> reason do_assign_task is False.
>>> I can imagine that such a thing happens because do_assign_task is reset
>>> to False, but that reset happens only after (at least) 3 seconds, at the
>>> next send_heartbeat() call.
>>> What I can't reproduce is this behaviour exactly.... how is it possible
>>> that in your logs the "I'm a ticker" message comes 40 ms before pop_task,
>>> and do_assign_task is yet False ?
>>> Can you add a logging line just between these two lines
>>> self.do_assign_tasks = False
>>> if counter % 5 == 0 or mybackedstatus == PICK:
>>> and between
>>>
>>> if self.worker_status[0] == ACTIVE:
>>> self.do_assign_tasks = True
>>>
>>> so we can monitor exactly when the flag is switched ?
>>>
>>> --
>>>
>>> ---
>>> You received this message because you are subscribed to a topic in the
>>> Google Groups "web2py-users" group.
>>> To unsubscribe from this topic, visit https://groups.google.com/d/**
>>> topic/web2py/u_PgzKLuQmw/**unsubscribe?hl=en<https://groups.google.com/d/topic/web2py/u_PgzKLuQmw/unsubscribe?hl=en>
>>> .
>>> To unsubscribe from this group and all its topics, send an email to
>>> web2py+un...@**googlegroups.com.
>>>
>>> For more options, visit
>>> https://groups.google.com/**groups/opt_out<https://groups.google.com/groups/opt_out>
>>> .
>>>
>>>
>>>
>>
>> --
>
> ---
> You received this message because you are subscribed to a topic in the
> Google Groups "web2py-users" group.
> To unsubscribe from this topic, visit
> https://groups.google.com/d/topic/web2py/u_PgzKLuQmw/unsubscribe?hl=en.
> To unsubscribe from this group and all its topics, send an email to
> web2py+unsubscr...@googlegroups.com.
> For more options, visit https://groups.google.com/groups/opt_out.
>
>
>
--
---
You received this message because you are subscribed to the Google Groups
"web2py-users" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to web2py+unsubscr...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
