NewRelic transaction traces in a Ruby Gem

Question

I am developing a Ruby gem that I would like to add NewRelic monitoring to. The gem is used in a script that is run as a daemon and monitored by bluepill. I followed "Monitoring Ruby background processes and daemons" to get started.

I confirmed the gem is establishing a connection with NewRelic as the application shows up in my portal there, however, there is no transaction traces or any metrics breakdown of the code being invoked.

Here's the "entry" point of my gem as I tried to manually start the agent around the invoking method:

require 'fms/parser/version'
require 'fms/parser/core'
require 'fms/parser/env'

require 'mongoid'

ENV['NRCONFIG'] ||= File.dirname(__FILE__) + '/../newrelic.yml'
require 'newrelic_rpm'

module Fms
  module Parser
    def self.prepare_parse(filename)
      ::NewRelic::Agent.manual_start
        Mongoid.load!("#{File.dirname(__FILE__)}/../mongoid.yml", :development)
        Core.prepare_parse(filename)    
      ::NewRelic::Agent.shutdown
    end
  end
end

I also tried adding this into the module:

   class << self
      include ::NewRelic::Agent::Instrumentation::ControllerInstrumentation
      add_transaction_tracer :prepare_parse, :category => :task
    end

I'm not entirely sure what else I can do. I confirmed the agent is able to communicate with the server and transaction traces are enabled. Nothing shows up in the background application tab either.

This is the most useful information I've gotten from the agent log so far:

[12/23/13 21:21:03 +0000 apivm (7819)] INFO : Environment: development
[12/23/13 21:21:03 +0000 apivm (7819)] INFO : No known dispatcher detected.
[12/23/13 21:21:03 +0000 apivm (7819)] INFO : Application: MY-APP
[12/23/13 21:21:03 +0000 apivm (7819)] INFO : Installing Net instrumentation
[12/23/13 21:21:03 +0000 apivm (7819)] INFO : Finished instrumentation
[12/23/13 21:21:04 +0000 apivm (7819)] INFO : Reporting to: https://rpm.newrelic.com/[MASKED_ACCOUNT_NUMBER]
[12/23/13 22:12:06 +0000 apivm (7819)] INFO : Starting the New Relic agent in "development" environment.
[12/23/13 22:12:06 +0000 apivm (7819)] INFO : To prevent agent startup add a NEWRELIC_ENABLE=false environment variable or modify the "development" section of your newrelic.yml.
[12/23/13 22:12:06 +0000 apivm (7819)] INFO : Reading configuration from /var/lib/gems/1.9.1/gems/fms-parser-0.0.6/lib/fms/../newrelic.yml
[12/23/13 22:12:06 +0000 apivm (7819)] INFO : Starting Agent shutdown

The only thing that's really concerning here is "No known dispatcher detected".

Is what I'm trying to do possible?

Answer 1

I work at New Relic and wanted to add some up-to-date details about the latest version of the newrelic_rpm gem. TrinitronX is on the right track, but unfortunately that code sample and blog post is based on a very old version of the gem, and the internals have changed significantly since then. The good news is that newer versions of the agent should make this simpler.

To start off, I should say I'm assuming that your process stays alive for a long time as a daemon, and makes repeated calls to prepare_parse.

Generally speaking, the explicit manual_start and shutdown calls you have inserted into your prepare_parse method should not be necessary - except for a few special cases (certain rake tasks and interactive sessions). The New Relic agent will automatically start as soon as it is required. You can see details about when the Ruby agent will automatically start and how to control this behavior here:

• https://docs.newrelic.com/docs/ruby/forcing-the-ruby-agent-to-start

For monitoring background tasks like this, there are conceptually two levels of instrumentation that you might want: transaction tracers and method tracers. You already have a transaction tracer, but you may also want to add method tracers around the major chunks of work that happen within your prepare_parse method. Doing so will give you better visibility into what's happening within each prepare_parse invocation. You can find details about adding method tracers here:

• https://docs.newrelic.com/docs/ruby/ruby-custom-metric-collection#method_tracers

With the way that you are calling add_transaction_tracer, your calls to prepare_parse should show up as transactions on the 'Background tasks' tab in the New Relic UI.

The one caveat here may be the fact that you're running this as a daemon. The Ruby agent uses a background thread to asynchronously communicate with New Relic servers. Since threads are not copied across calls to fork(), this means you will sometimes have to manually re-start the agent after a fork() (note that Ruby's Process.daemon uses fork underneath, so it's included as well). Whether or not this is necessary depends on the relative timing of the require of newrelic_rpm and the call to fork / daemon (if newrelic_rpm isn't required until after the call to fork / daemon, you should be good, otherwise see below).

There are two solutions to the fork issue:

1. Manually call NewRelic::Agent.after_fork from the forked child, right after the fork.

2. If you're using newrelic_rpm 3.7.1 or later, there's an experimental option to automatically re-start the background thread that you can enable in your newrelic.yml file by setting restart_thread_in_children: true. This is off by default at the moment, but may become the default behavior in future versions of the agent.

If you're still having trouble, the newrelic_agent.log file is your best bet to debugging things. You'll want to increase the verbosity by setting log_level: debug in your newrelic.yml file in order to get more detailed output.

Answer 2

For debugging this problem, try the following code:

require 'fms/parser/version'
require 'fms/parser/core'
require 'fms/parser/env'

require 'mongoid'

ENV['NRCONFIG'] ||= File.dirname(__FILE__) + '/../newrelic.yml'
# Make sure NewRelic has correct log file path
ENV['NEW_RELIC_LOG'] ||= File.dirname(__FILE__) + '/../log/newrelic_agent.log'

require 'newrelic_rpm'
::NewRelic::Agent.manual_start

# For debug purposes: output some dots until we're connected to NewRelic
until NewRelic::Agent.connected? do
  print '.'
  sleep 1
end

module Fms
  module Parser
    class << self
      include ::NewRelic::Agent::Instrumentation::ControllerInstrumentation
      add_transaction_tracer :prepare_parse, :category => :task
    end
    def self.prepare_parse(filename)
        Mongoid.load!("#{File.dirname(__FILE__)}/../mongoid.yml", :development)
        Core.prepare_parse(filename)

      # Force the agent to prepare data before we shutdown
      ::NewRelic::Agent.load_data
      # NOTE: Ideally you'd want to shut down the agent just before the process exits... not every time you call Fms::Parser#prepare_parse
      ::NewRelic::Agent.shutdown(:force_send => true)
    end
  end
end

I have a feeling that this probably has something to do with running your gem's code within the daemonized process that bluepill is starting. Ideally, we'd want to start the NewRelic agent within the process as soon after the daemon process is forked as we can get. Putting it after your library's requires should do this when the file is required.

We also would most likely want to stop the NewRelic agent just before the background task process exits, not every time the Fms::Parser#prepare_parse method is called. However, for our purposes this should get you enough debugging info to continue, so you can ensure that the task is contacting New Relic the first time it's run. We can also try using :force_send => true to ensure we send the data.

References:

• Blog Post: Instrumenting your monitoring checks with New Relic