Hi gang,
Thanks to other help I''ve gotten on this list, I''ve got
backgroundrb
up and running using postgres alongside my rails app. I''ve designed
the system to have several eternally-running workers that periodically
poll the database to see if there''s any work for them to do, and set
things up in the config file to make them restart quickly if any of
them should crash. One odd thing I''ve noticed is that one of my
workers, with the key "mr", seems to start twice (without the first
one having completed). I''ve got some logging that occurs when each
starts:
20070313-15:45:17 (5594) Starting WorkerLogger
20070313-15:45:17 (5595) In ResultsWorker
20070313-15:45:21 (5595) MbReceiver mr started.
20070313-15:45:21 (5595) Sender s started
20070313-15:45:22 (5595) MbSender ms1 started
20070313-15:45:22 (5595) MbSender ms2 started
20070313-15:45:22 (5595) Receiver r started
20070313-15:45:30 (5595) MbReceiver mr started.
The relevant chunk of backgroundrb_schedules.yml looks like this:
mb_receiver:
:class: :mb_receiver
:job_key: :mr
:worker_method: :do_work
:args:
:sleep_time: 5
:trigger_args: 0,10,20,30,40,50 * * * * * *
The other workers have identical trigger_args, but don''t exhibit this
behavior.
The do_work method just calls another method that loops forever, and I
wrapped that call in an exception handler to see if it was crapping
out or something, but it doesn''t seem to be. FWIW, here''s the
backgroundrb_server.log from the same period of time:
20070313-15:45:17 (5594) Starting BackgrounDRb Server
20070313-15:45:17 (5594) acl: denyallallowlocalhost 127.0.0.1orderdeny allow
20070313-15:45:17 (5594) temp_dir: /tmp
20070313-15:45:17 (5594) port: 2000
20070313-15:45:17 (5594) worker_dir: /Users/jnutting/work/m_project/lib/workers
20070313-15:45:17 (5594) protocol: drbunix
20070313-15:45:17 (5594) uri: drbunix:///tmp/backgroundrbunix_localhost_2000
20070313-15:45:17 (5594) config:
/Users/jnutting/work/m_project/config/backgroundrb.yml
20070313-15:45:17 (5594) rails_env: development
20070313-15:45:17 (5594) socket_dir: /tmp/backgroundrb.5594
20070313-15:45:17 (5594) pool_size: 5
20070313-15:45:17 (5594) host: localhost
20070313-15:45:17 (5594) Starting worker:
BackgrounDRb::Worker::WorkerLogger backgroundrb_logger
(backgroundrb_logger) ()
20070313-15:45:17 (5594) Starting worker:
BackgrounDRb::Worker::WorkerResults backgroundrb_results
(backgroundrb_results) ()
20070313-15:45:17 (5594) Loading Worker Class File:
/Users/jnutting/work/m_project/lib/workers/mb_receiver.rb
20070313-15:45:17 (5594) Loading Worker Class File:
/Users/jnutting/work/m_project/lib/workers/mb_sender.rb
20070313-15:45:17 (5594) Loading Worker Class File:
/Users/jnutting/work/m_project/lib/workers/receiver.rb
20070313-15:45:17 (5594) Loading Worker Class File:
/Users/jnutting/work/m_project/lib/workers/sender.rb
20070313-15:45:17 (5594) Loading Sechedule:
job_keymrclassmb_receiverargssleep_time5
worker_method_argssleep_time5job_keymrclassmb_receiverargssleep_time5trigger_typecron_triggertrigger_args0,10,20,30,40,50
* * * * * *worker_methoddo_work #<BackgrounDRb::CronTrigger:0x23bf3c4>
20070313-15:45:17 (5594) Loading Sechedule:
job_keysclasssenderargssleep_time5
worker_method_argssleep_time5job_keysclasssenderargssleep_time5trigger_typecron_triggertrigger_args0,10,20,30,40,50
* * * * * *worker_methoddo_work #<BackgrounDRb::CronTrigger:0x23be960>
20070313-15:45:17 (5594) Loading Sechedule:
job_keyms1classmb_senderargssleep_time5
worker_method_argssleep_time5job_keyms1classmb_senderargssleep_time5trigger_typecron_triggertrigger_args0,10,20,30,40,50
* * * * * *worker_methoddo_work #<BackgrounDRb::CronTrigger:0x23bdf38>
20070313-15:45:17 (5594) Loading Sechedule:
job_keyms2classmb_senderargssleep_time5
worker_method_argssleep_time5job_keyms2classmb_senderargssleep_time5trigger_typecron_triggertrigger_args0,10,20,30,40,50
* * * * * *worker_methoddo_work #<BackgrounDRb::CronTrigger:0x23bd3e4>
20070313-15:45:17 (5594) Loading Sechedule:
job_keyrclassreceiverargssleep_time5
worker_method_argssleep_time5job_keyrclassreceiverargssleep_time5trigger_typecron_triggertrigger_args0,10,20,30,40,50
* * * * * *worker_methoddo_work #<BackgrounDRb::CronTrigger:0x23bc8cc>
20070313-15:45:20 (5594) Schedule triggered: #<struct
#<Class:0x4069c4>
job=#<Proc:0x01031b40@/Users/jnutting/work/m_project/vendor/plugins/backgroundrb/server/lib/backgroundrb/middleman.rb:319>,
trigger=#<BackgrounDRb::CronTrigger:0x23bf3c4 @year=nil, @day=1..31,
@cron_expr="0,10,20,30,40,50 * * * * * *", @sec=[0, 10, 20, 30, 40,
50], @wday=0..6, @min=0..59, @month=1..12, @hour=0..23>, earliest=Tue
Mar 13 15:45:20 +0100 2007, last=Tue Mar 13 15:45:20 +0100 2007>
20070313-15:45:21 (5594) Starting worker: mb_receiver mr
(mb_receiver_mr) (sleep_time5)
20070313-15:45:21 (5594) Schedule triggered: #<struct
#<Class:0x4069c4>
job=#<Proc:0x01031b40@/Users/jnutting/work/m_project/vendor/plugins/backgroundrb/server/lib/backgroundrb/middleman.rb:319>,
trigger=#<BackgrounDRb::CronTrigger:0x23be960 @year=nil, @day=1..31,
@cron_expr="0,10,20,30,40,50 * * * * * *", @sec=[0, 10, 20, 30, 40,
50], @wday=0..6, @min=0..59, @month=1..12, @hour=0..23>, earliest=Tue
Mar 13 15:45:20 +0100 2007, last=Tue Mar 13 15:45:20 +0100 2007>
20070313-15:45:21 (5594) Starting worker: sender s (sender_s) (sleep_time5)
20070313-15:45:21 (5594) Schedule triggered: #<struct
#<Class:0x4069c4>
job=#<Proc:0x01031b40@/Users/jnutting/work/m_project/vendor/plugins/backgroundrb/server/lib/backgroundrb/middleman.rb:319>,
trigger=#<BackgrounDRb::CronTrigger:0x23bdf38 @year=nil, @day=1..31,
@cron_expr="0,10,20,30,40,50 * * * * * *", @sec=[0, 10, 20, 30, 40,
50], @wday=0..6, @min=0..59, @month=1..12, @hour=0..23>, earliest=Tue
Mar 13 15:45:20 +0100 2007, last=Tue Mar 13 15:45:20 +0100 2007>
20070313-15:45:22 (5594) Starting worker: mb_sender ms1
(mb_sender_ms1) (sleep_time5)
20070313-15:45:22 (5594) Schedule triggered: #<struct
#<Class:0x4069c4>
job=#<Proc:0x01031b40@/Users/jnutting/work/m_project/vendor/plugins/backgroundrb/server/lib/backgroundrb/middleman.rb:319>,
trigger=#<BackgrounDRb::CronTrigger:0x23bd3e4 @year=nil, @day=1..31,
@cron_expr="0,10,20,30,40,50 * * * * * *", @sec=[0, 10, 20, 30, 40,
50], @wday=0..6, @min=0..59, @month=1..12, @hour=0..23>, earliest=Tue
Mar 13 15:45:20 +0100 2007, last=Tue Mar 13 15:45:20 +0100 2007>
20070313-15:45:22 (5594) Starting worker: mb_sender ms2
(mb_sender_ms2) (sleep_time5)
20070313-15:45:22 (5594) Schedule triggered: #<struct
#<Class:0x4069c4>
job=#<Proc:0x01031b40@/Users/jnutting/work/m_project/vendor/plugins/backgroundrb/server/lib/backgroundrb/middleman.rb:319>,
trigger=#<BackgrounDRb::CronTrigger:0x23bc8cc @year=nil, @day=1..31,
@cron_expr="0,10,20,30,40,50 * * * * * *", @sec=[0, 10, 20, 30, 40,
50], @wday=0..6, @min=0..59, @month=1..12, @hour=0..23>, earliest=Tue
Mar 13 15:45:20 +0100 2007, last=Tue Mar 13 15:45:20 +0100 2007>
20070313-15:45:22 (5594) Starting worker: receiver r (receiver_r) (sleep_time5)
20070313-15:45:30 (5594) Schedule triggered: #<struct
#<Class:0x4069c4>
job=#<Proc:0x01031b40@/Users/jnutting/work/m_project/vendor/plugins/backgroundrb/server/lib/backgroundrb/middleman.rb:319>,
trigger=#<BackgrounDRb::CronTrigger:0x23bf3c4 @year=nil, @day=1..31,
@cron_expr="0,10,20,30,40,50 * * * * * *", @sec=[0, 10, 20, 30, 40,
50], @wday=0..6, @min=0..59, @month=1..12, @hour=0..23>, earliest=Tue
Mar 13 15:45:30 +0100 2007, last=Tue Mar 13 15:45:30 +0100 2007>
Any ideas?
--
// jack
// http://www.nuthole.com
Hi Jack, I''m experiencing the same problem and wrote about it here earlier. I wonder if it has something to do with thread_pool size or concurrent threads running in brb? Brian ------------- Date: Tue, 13 Mar 2007 16:06:58 +0100 From: "Jack Nutting" <jnutting at gmail.com> Subject: [Backgroundrb-devel] worker starting twice To: backgroundrb-devel at rubyforge.org Message-ID: <f84841020703130806v11497ea9webbd12fb30557cf9 at mail.gmail.com> Content-Type: text/plain; charset=ISO-8859-1; format=flowed Hi gang, Thanks to other help I''ve gotten on this list, I''ve got backgroundrb up and running using postgres alongside my rails app. I''ve designed the system to have several eternally-running workers that periodically poll the database to see if there''s any work for them to do, and set things up in the config file to make them restart quickly if any of them should crash. One odd thing I''ve noticed is that one of my workers, with the key "mr", seems to start twice (without the first one having completed). I''ve got some logging that occurs when each starts: 20070313-15:45:17 (5594) Starting WorkerLogger 20070313-15:45:17 (5595) In ResultsWorker 20070313-15:45:21 (5595) MbReceiver mr started. 20070313-15:45:21 (5595) Sender s started 20070313-15:45:22 (5595) MbSender ms1 started 20070313-15:45:22 (5595) MbSender ms2 started 20070313-15:45:22 (5595) Receiver r started 20070313-15:45:30 (5595) MbReceiver mr started.
On 3/13/07, Brian Lucas <blucasco at gmail.com> wrote:> Hi Jack, I''m experiencing the same problem and wrote about it here earlier. > I wonder if it has something to do with thread_pool size or concurrent > threads running in brb?I don''t know, but I know it''s really irritating. I think I have a few clues for whoever feels up to looking at this. First of all, the doubled worker is not actually running in two processes. ''ps'' shows me only the processes i''ve specified in the schedules file, not more. Instead, the trigger method is being called twice. Through logging output, I''ve observed that my loop is in fact running twice simultaneously, presumably from two different threads. Also, I''ve found a way to determine which of my processes will be doubled: whichever top-level job entry name (not the job_key, but the top-level identifier for a worker) comes alphabetically first, that''s the job that I start getting double-invocations on! e.g. if I have a job like this: zzzzz: :class: :my_class :job_key: :my_job1 ... that won''t won''t be doubled up (some other worker will instead). However, if I change the ''zzzzz'' to ''a'', this worker will be double-invoked. In the short term, this gives me a workaround since I can have a dummy worker called ''a'' that just sleeps, but this is still consuming excess RAM of course. -- // jack // http://www.nuthole.com
My understanding is that for scheduled workers, the do_work method is called automatically when the worker is created (which provides an opportunity for any initialization, if necessary), and subsequently the :worker_method specified in the backgroundrb_schedules.yml file is called on the specified schedule. If your worker_method is specified as :do_work, then your :do_work method will be called twice, once when the worker is created, and again when the schedule is invoked. Note that these separate calls can occur in separate threads. So if you do use the call to do_work at creation time to do some initialization, you will need to set a flag internally to let other (potentially simultaneous) calls to your :worker_method behave appropriately if called be initialization is complete. Here''s the relevant excerpt from the documentation:> Special case: :do_work > > The do_work method of a worker is automatically called when you first > create a worker and we are treating it differently than other methods when > you schedule. > > You can have do_work executed repeatedly in a schedule by specifying > :worker_method => :do_work in schedule_worker. What will happen, is that on > the initial schedule where a worker is created, it will call the built in > call to do_work, then on subsequent trigger events, use the :worker_method. >I believe the documentation should be corrected -- the "on subsequent trigger events" part is not exactly accurate, as the trigger event could be simultaneous, and hence not "subsequent". Mason On 3/14/07, Jack Nutting <jnutting at gmail.com> wrote:> > On 3/13/07, Brian Lucas <blucasco at gmail.com> wrote: > > Hi Jack, I''m experiencing the same problem and wrote about it here > earlier. > > I wonder if it has something to do with thread_pool size or concurrent > > threads running in brb? > > I don''t know, but I know it''s really irritating. > > I think I have a few clues for whoever feels up to looking at this. > > First of all, the doubled worker is not actually running in two > processes. ''ps'' shows me only the processes i''ve specified in the > schedules file, not more. Instead, the trigger method is being called > twice. Through logging output, I''ve observed that my loop is in fact > running twice simultaneously, presumably from two different threads. > > Also, I''ve found a way to determine which of my processes will be > doubled: whichever top-level job entry name (not the job_key, but the > top-level identifier for a worker) comes alphabetically first, that''s > the job that I start getting double-invocations on! e.g. if I have a > job like this: > > zzzzz: > :class: :my_class > :job_key: :my_job1 > ... > > that won''t won''t be doubled up (some other worker will instead). > However, if I change the ''zzzzz'' to ''a'', this worker will be > double-invoked. In the short term, this gives me a workaround since I > can have a dummy worker called ''a'' that just sleeps, but this is still > consuming excess RAM of course. > > -- > // jack > // http://www.nuthole.com > _______________________________________________ > Backgroundrb-devel mailing list > Backgroundrb-devel at rubyforge.org > http://rubyforge.org/mailman/listinfo/backgroundrb-devel >-------------- next part -------------- An HTML attachment was scrubbed... URL: http://rubyforge.org/pipermail/backgroundrb-devel/attachments/20070314/562bff13/attachment.html
On 3/14/07, Mason Hale <masonhale at gmail.com> wrote:> My understanding is that for scheduled workers, the do_work method is called > automatically when the worker is created (which provides an opportunity for > any initialization, if necessary), and subsequently the :worker_method > specified in the backgroundrb_schedules.yml file is called on the specified > schedule. > > If your worker_method is specified as :do_work, then your :do_work method > will be called twice, once when the worker is created, and again when the > schedule is invoked. Note that these separate calls can occur in separate > threads. So if you do use the call to do_work at creation time to do some > initialization, you will need to set a flag internally to let other > (potentially simultaneous) calls to your :worker_method behave appropriately > if called be initialization is complete.Ahhhh! Now it all makes sense. Thanks! -- // jack // http://www.nuthole.com
* Jack Nutting (jnutting at gmail.com) [070314 16:26]:> On 3/14/07, Mason Hale <masonhale at gmail.com> wrote: > > My understanding is that for scheduled workers, the do_work method is called > > automatically when the worker is created (which provides an opportunity for > > any initialization, if necessary), and subsequently the :worker_method > > specified in the backgroundrb_schedules.yml file is called on the specified > > schedule. > > > > If your worker_method is specified as :do_work, then your :do_work method > > will be called twice, once when the worker is created, and again when the > > schedule is invoked. Note that these separate calls can occur in separate > > threads. So if you do use the call to do_work at creation time to do some > > initialization, you will need to set a flag internally to let other > > (potentially simultaneous) calls to your :worker_method behave appropriately > > if called be initialization is complete.there is some safeguards in the code against this. If a worker is created, then it will keep track of the fact that it''s the initial do_work and _not_ call do_work a second time on the initial schedule. /skaar -- ---------------------------------------------------------------------- |\|\ where in the | s_u_b_s_t_r_u_c_t_i_o_n | | >=========== W.A.S.T.E. | genarratologies |/|/ (_) is the wisdom | skaar at waste.org ----------------------------------------------------------------------