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] <javascript:>> > >> 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. >> 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.
