New Relic RPM with Resque

New Relic RPM announced that they’ve started to support Sinatra and Rack a few days ago (article). It’s also come up with a better background job monitoring. Good news. So I tried monitoring jobs being handled on Resque which we’ve started using recently for managing background jobs.

Unfortunately RPM 2.10.5 couldn’t monitor jobs of Resque. Resque forks to process a job. RPM agent instance can’t chase the things happend in forked processes which terminates in a short time.

However I succeeded to monitor Resque jobs with RPM with a little hack. I want to share it here, though, it is just a hack. The information might be obsolete soon. So I explain my process I took to find it too. In that way, I hope that it gives you a help when this hack is no longer applicable.

Step 1. Follow the instruction of RPM

Firstly I followed RPM’s instruction (API document) and implemented a sample job like this.

class HelloWorldJob
  include NewRelic::Agent::Instrumentation::ControllerInstrumentation

  @queue = :low
  def self.perform
    HelloWorldJob.new.hello_world
  end

  def hello_world
    RAILS_DEFAULT_LOGGER.info "#{Time.now}: Hello World!"
    RAILS_DEFAULT_LOGGER.flush
    sleep(3)
  end

  add_transaction_tracer :hello_world, :name=>'hello_world'
end

But even if the job is processed on Resque, it is not shown as a transaction in management screen of RPM.

Step 2. Google it

Secondly I googled it. I felt that researching myself is a waste of time if someone has found the way already(This idea is always wrong though). But Google didn’t give me the answer this time. I thank Google for that because it gives me an oppotunity to understand how both Resque and Newrelic RPM work deeply.

Step 3. Set up environment to debug

For Resque: start resque worker with very vobose mode.
e.g.

VVERBOSE=true QUEUE=* rake environment resque:work

For Newrelic: set log level with debug in newrelic.yml

  log_level: debug

Then I tested the job with script/console. You can run the job like this:

% script/console
> Resque.enqueue HelloWorldJob
=> Enqueues a job and it will be executed on Resque worker
> HelloWorldJob.process
=> Executes a job directly without queueing

You should be able to confirm that the job executed directly on console is monitored on RPM and shown in its management screen. But the one proccessed by Resque never comes to the screen.

Step 4. Try to know what happens in Resque

I proceeded the investigation with the following cycle.

1. Run job on Resque and script/console
2. Compare the log of Resque to the one of script/console
3. Make an assumption and put some debug codes in Resque or Newrelic RPM (Thanks god those are opensource!)
4. Restart Resque worker and script/console
5. Back to 1

Sorry but there is no magic and shortcut. But after I spent about 15 minutes or so with the cycle, I found(and remembered at the same time) that Resque uses forking for processing a job and I was convinced that it would cause the issue. So I changed the code on Reque not to fork the process as an experment.

in lib/resque/worker.rb

    def fork
+      return false

Then ran the job via Resque. Yay, the transaction information was shown in RPM.

Step 5. Then a little hack

Of course, you can’t turn off the forking of Resque. That is something that makes Resque awesome. So I reveted the change I made on worker.rb and focused on finding a way to monitor forked process with RPM.

What I tried at first is to call NewRelic::Agent.shutdown which sends the all queued data after the job is done. RPM sends the log every 60 seconds but the job finishes about in 3 seconds. So that the job has to make sure to send the data before ended.

class HelloWorldJob
  include NewRelic::Agent::Instrumentation::ControllerInstrumentation

  @queue = :low
  def self.perform
    HelloWorldJob.new.hello_world
    NewRelic::Agent.shutdown
  end

  def hello_world
    RAILS_DEFAULT_LOGGER.info "#{Time.now}: Hello World!"
    RAILS_DEFAULT_LOGGER.flush
    sleep(3)
  end

  add_transaction_tracer :hello_world, :name=>'hello_world'
end

On console/script, it worked in a way I expected, though, it didn’t on Resque. Dammn it. Next I looked into RPM’s codebase with the cycle I showed on Step 4.

Then I found that RPM resets the connection information if the current process id is different from the one which RPM got when it started. Then, on that situation, it tries to start worker thread which reports the information to RPM server every 60 seconds. But it takes seconds to launch and the job finishes before the thread finishes communicating server.

Anyway you don’t want to create a thread for RPM everytime Resque job is created. It just wastes your machines resource and makes a job process slow in terms of background job. Alternatively it would be nice if the forked process use the parent connection information simply. I monkey-patched onto RPM to behave in that way. This patch shouldn’t affect monitoring for other applications.

in lib/new_relic/agent/agent.rb

    def ensure_worker_thread_started
      return unless control.agent_enabled? && control.monitor_mode? && !@invalid_license

-     if !running?
+     if !running? && !control['resque']

Then changed the codebase of the job like this.

class HelloWorldJob
  include NewRelic::Agent::Instrumentation::ControllerInstrumentation

  @queue = :low
  def self.perform
    NewRelic::Control.instance['resque'] = true
    HelloWorldJob.new.hello_world
    NewRelic::Agent.shutdown
  end

  def hello_world
    RAILS_DEFAULT_LOGGER.info "#{Time.now}: Hello World!"
    RAILS_DEFAULT_LOGGER.flush
    sleep(3)
  end

  add_transaction_tracer :hello_world, :name=>'HelloWorldJob#hello_world'
end

Wheeee, now the job is shown and tracked as a transaction on RPM. You can track the exceptions occurred in Resque jobs as well as slow transactions with RPM.

Step 6. Refactor

To monitor all jobs in same way, I refactor HelloWorldJob with its super class. I hope that RPM is going to support forked background process like Resque officially in a nice way and the hack is no longer needed soon. So it doesn’t make sence to write this ugly hack on every single job. Instead of that, I put all newrelic related code onto a super class.

So here is a final codebase.

class BaseJob
  include NewRelic::Agent::Instrumentation::ControllerInstrumentation

  # This is called from Resque.
  # To be wrapped with the common operation, please describe job in the instance's perform method.
  def self.perform(*args)
    NewRelic::Control.instance['resque'] = true
    self.new.perform_wrapper(*args)
  ensure
    NewRelic::Agent.shutdown
  end

  # Sends a hint to our monitoring system, newrelic rpm
  def add_custom_parameters(key, value)
    NewRelic::Agent.add_custom_parameters(key => value.to_s)
  end

  # Calls :perform with monitoring on newrelic rpm
  def perform_wrapper(*args)
    # :task seems available only for charged plan. When you test this with a free plan, you have to get rid of it.
    # perform_action_with_newrelic_trace(:name=>'perform') do
    perform_action_with_newrelic_trace(:name=>'perform', :category => :task) do
      begin
        perform(*args)
      ensure
        logger.flush if logger && logger.respond_to?(:flush)
      end
    end
  end

  # Override this method instead of the class method.
  def perform(*args)

  end

  def logger
    RAILS_DEFAULT_LOGGER
  end
end

# Test purpose job. It output the information to log.
class HelloWorldJob < BaseJob
  @queue = :low

  def perform(who='World')
    # This sends the information to NewRelic RPM
    add_custom_parameters :whom, who

    logger "#{Time.now}: Hello #{who}!"
    sleep(3)
  end

end

Epilogue
I have to say lastly that reading Resque’s codebase was absolutely fun. It is simple and neat. You might feel that you can write the codebase yourself easily. But there are the good design decisions behind that: which are using only Redis for queue backend and forking for processing a job. Cool.

Advertisement

~ by ono on February 28, 2010.