I tried it, it seems to be more sporadic but the problem is not gone. log: 2013-03-27 18:07:11,809 - web2py.scheduler.mapserver#30515 - DEBUG - freeing workers that have not sent heartbeat 2013-03-27 18:07:11,811 - web2py.scheduler.mapserver#30515 - INFO - TICKER: I'm a ticker 2013-03-27 18:07:11,843 - web2py.scheduler.mapserver#30515 - DEBUG - looping... 2013-03-27 18:07:11,853 - web2py.scheduler.mapserver#30515 - INFO - pop task True False 2013-03-27 18:07:11,970 - web2py.scheduler.mapserver#30515 - DEBUG - is_a_ticker := True, worker_status[0] := ACTIVE 2013-03-27 18:07:11,983 - web2py.scheduler.mapserver#30515 - INFO - nothing to do 2013-03-27 18:07:11,983 - web2py.scheduler.mapserver#30515 - DEBUG - sleeping... 2013-03-27 18:07:14,971 - web2py.scheduler.mapserver#30515 - DEBUG - ........recording heartbeat (ACTIVE) 2013-03-27 18:07:14,986 - web2py.scheduler.mapserver#30515 - DEBUG - looping... 2013-03-27 18:07:15,009 - web2py.scheduler.mapserver#30515 - INFO - pop task True False 2013-03-27 18:07:15,190 - web2py.scheduler.mapserver#30515 - INFO - nothing to do 2013-03-27 18:07:15,190 - web2py.scheduler.mapserver#30515 - DEBUG - sleeping... 2013-03-27 18:07:18,148 - web2py.scheduler.mapserver#30515 - DEBUG - ........recording heartbeat (ACTIVE) 2013-03-27 18:07:18,192 - web2py.scheduler.mapserver#30515 - DEBUG - looping... 2013-03-27 18:07:18,193 - web2py.scheduler.mapserver#30515 - INFO - pop task True False 2013-03-27 18:07:18,323 - web2py.scheduler.mapserver#30515 - INFO - nothing to do 2013-03-27 18:07:18,324 - web2py.scheduler.mapserver#30515 - DEBUG - sleeping... 2013-03-27 18:07:21,314 - web2py.scheduler.mapserver#30515 - DEBUG - ........recording heartbeat (ACTIVE) 2013-03-27 18:07:21,327 - web2py.scheduler.mapserver#30515 - DEBUG - looping... 2013-03-27 18:07:21,327 - web2py.scheduler.mapserver#30515 - INFO - pop task True False 2013-03-27 18:07:21,457 - web2py.scheduler.mapserver#30515 - INFO - nothing to do 2013-03-27 18:07:21,458 - web2py.scheduler.mapserver#30515 - DEBUG - sleeping... 2013-03-27 18:07:24,454 - web2py.scheduler.mapserver#30515 - DEBUG - ........recording heartbeat (ACTIVE) 2013-03-27 18:07:24,461 - web2py.scheduler.mapserver#30515 - DEBUG - looping... 2013-03-27 18:07:24,461 - web2py.scheduler.mapserver#30515 - INFO - pop task True False 2013-03-27 18:07:24,641 - web2py.scheduler.mapserver#30515 - INFO - nothing to do 2013-03-27 18:07:24,642 - web2py.scheduler.mapserver#30515 - DEBUG - sleeping... 2013-03-27 18:07:27,604 - web2py.scheduler.mapserver#30515 - DEBUG - ........recording heartbeat (ACTIVE) 2013-03-27 18:07:27,605 - web2py.scheduler.mapserver#30515 - DEBUG - freeing workers that have not sent heartbeat 2013-03-27 18:07:27,607 - web2py.scheduler.mapserver#30515 - INFO - TICKER: I'm a ticker
Paolo 2013/3/27 Niphlod <[email protected]> > the do_assign_task variable gets eventually shifted (read True to False, > False to True) every loop. > The issue is .... how can the execution be pushed far (in your case even > 60 seconds) with no errors whatsoever ? > > Usually when a TICKER has been chosen (or re-confirmed), do_assign_task is > set to True and the thread is put to sleep for 3 seconds. > There's quite no logic between the do_assign_task = True and the > self.sleep() line, so there's a "sure" timeframe of 3 seconds for the main > process to pick up the tasks. > Are you suggesting that sleeping the main loop and the heartbeat thread > "at the same pace" generates the problem you're seeing ? > If so, as a trial, can you please replace the self.sleep() call on at the > end of the loop() function to be, e.g. time.sleep(3.5) ? > > > On Wednesday, March 27, 2013 1:42:22 PM UTC+1, Paolo valleri wrote: > >> So, I added: logger.debug('is_a_**ticker := %s, worker_status[0] := %s', >> self.is_a_ticker, self.worker_status[0]) before the last if of relevant >> snippet you posted,logs: >> >> 2013-03-27 13:25:01,785 - web2py.scheduler.mapserver#**29806 - INFO - >> TICKER: I'm a ticker >> 2013-03-27 13:25:01,797 - web2py.scheduler.mapserver#**29806 - DEBUG - >> looping... >> 2013-03-27 13:25:01,798 - web2py.scheduler.mapserver#**29806 - INFO - >> pop task True False >> 2013-03-27 13:25:01,950 - web2py.scheduler.mapserver#**29806 - DEBUG - >> is_a_ticker := True, worker_status[0] := ACTIVE >> 2013-03-27 13:25:01,978 - web2py.scheduler.mapserver#**29806 - INFO - >> nothing to do >> >> I supposed to see "is_a_ticker := True, worker_status[0] := ACTIVE" after >> "INFO - TICKER: I'm a ticker" and then something like: 'DEBUG - Assigning >> tasks..' but I didn't see it because I have 'INFO - pop task True False', >> the last False, means that self.do_assign_tasks was False. Later, the >> worker_status[0] >> is ACTIVE so it would set do_assign_tasks to True but it is too late. >> Given that, in some cases pop_task comes before the do_assign_tasks = >> True statement. This could be the problem, Is It correct? >> >> >> >> >> Paolo >> >> >> 2013/3/27 Niphlod <[email protected]> >> >>> yeps. >>> this is expected, but every ~15 seconds that turns to "True" (meaning >>> more or less "I'm the Ticker, I'm free, I was free in the last 15 seconds, >>> let's see if there are any submitted (or repeating) tasks to assign"). >>> I don't have a python interpreter ATM but let's break up the logic, so >>> everyone can follow (and explaining most of the times lights up the >>> underlying problem, let's hope so) >>> >>> Who "tells" if that process is a Ticker is the "being_a_ticker()" >>> function. >>> being_a_ticker() is wrapped in a try_except clause, so you should see >>> the error logging in case something goes wrong --> Error coordinating TICKER >>> >>> one level up, do_assign_task is set every 5 cycles (or when "PICK" is >>> found), with the "prune dead workers" logic in the same statements...that >>> too is wrapped and should log --> Error cleaning up >>> >>> one level up, the whole thread checking is wrapped and should log --> >>> Error retrieving status >>> >>> Now, you get "I'm a TICKER", so the being_a_ticker() is getting >>> executed, and you don't have any errors reported...... this is the relevant >>> snippet >>> try: >>> self.is_a_ticker = self.being_a_ticker() >>> except: >>> logger.error('Error coordinating TICKER') >>> if self.worker_status[0] == ACTIVE: >>> self.do_assign_tasks = True >>> >>> So...... either the worker status is not ACTIVE at that moment, or >>> self.do_assign_task is set to True ..... >>> >>> >>> >>> >>> >>> -- >>> >>> --- >>> 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]. > 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.
