attach the complete log please.
>From the log lines you posted basically from 8:49:47 to 8:50:03 your assign
task is never set to True, however, I'm more interested to see where the
"switch" happens in your flow rather than seeing that is always False :P
On Wednesday, April 3, 2013 8:55:41 AM UTC+2, Paolo valleri wrote:
>
> 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 <[email protected] <javascript:>>
>
>> 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 <[email protected]>
>>>
>>>> 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
>> [email protected] <javascript:>.
>> 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 [email protected].
For more options, visit https://groups.google.com/groups/opt_out.
