Resque Batched Logger

ResqueBatchedLogger is an extension to the fantastic background work gem ‘resque’. This extension is intended for when you have large volumes of work you process in logical groups, or batches, and want timing, and logging information on the group as a whole. For example we have a daily import process which spawns a large amount of several types of jobs, running a couple of hours. This grouped logging lets us track when those jobs finish, and how long each took (by type)

Installation:

gem install resque-batched-logger

Usage:

# include the module in your job classes
class MyJob
  include Resque::Plugins::BatchedLogging
  def self.perform(*args)
    # your job implementation
  end
end

# enqueue your jobs by calling #enqueue from within a batched block on your job classes
# This will call any custom #self.enqueue or #self.create methods defined on your job class, defaulting to the standard Resque.enqueue after wrapping your job in it's logging code
# jobs will be batched grouped by the job class name, and must be unique so for running multiple batches at once see below on how to do so with subclassing.
MyJob.batched do
  enqueue(1,2,3,{:my => :options})
end

You’ll need to run at least one resque-worker on the queue named ‘batched_logger’, (recommended only one for consistency of log ordering) this worker can be reasonably low priority, depending on how quickly you need output to the logfile.

The logging of each batch of jobs will be written to a log file at ‘log/batched_jobs.log` by the BatchedLogger resque job.

Sample Output:

==== Batched jobs 'Daily MyJob run' : logged at Mon Mar 28 16:25:04 +1300 2011 ====
  batch started processing at: Mon Mar 28 16:23:00 +1300 2011
  batch finished processing at: Mon Mar 28 16:25:02 +1300 2011
  Total run time for batch: 122 seconds
  Jobs Enqueued: 220
  Jobs Processed: 220
  Average time per job: 0.527 seconds
  Total time spent processing jobs: 116 seconds
==== Batched jobs 'Daily MyJob run' completed at Mon Mar 28 16:25:02 +1300 2011 took 122 seconds ====

Advanced Usage

For batching jobs of the same type in multiple groups, or if your application might enqueue jobs of the same type while your batched jobs are running, it is recommended that you subclass your jobs for a batched class, to allow an exclusive batch scope

example:

class BackendLifting
  @queue = :standard
  def self.perform(user_id)
    # do something
  end
end
class BatchedBackendLifting < BackendLifting
  # This is simply to provide an exclusive scope
end

This allows you to batch your jobs via:

BatchedBackendLifting.batched do
  user_ids.each do |id|
    enqueue(id)
  end
end

Which will prevent any ‘BackendLifting` jobs your application enqueues simultaneously from being inadvertently logged as a batched job. This is only necessary if you want to guarantee there are no additional jobs added to the logging of your batch, or the ability to enqueue multiple batches at once.

How it works

Log information is stored in redis until all jobs have been processed, and once all the jobs present in the batch have been performed, the ‘BatchedJobsLogger` pulls this information out of redis, aggregates it and outputs it to the logfile ’log/batched_jobs.log’.