NewRelic transaction traces in a Ruby Gem

Asked 20/12, 2013 at 5:28 Answered 27/12, 2013 at 1:3

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?

Cogency answered 20/12, 2013 at 5:28 Comment(4)

anything in the newrelic.log? – Landtag 23/12, 2013 at 21:7

Have you tried forcing it to run by setting agent_enabled: true in your newrelic.yml? Also are you trying to do this while you are in development? Maybe try switching to developer_mode: true. – Epexegesis 26/12, 2013 at 18:46

If you're not sure that the logging is coming through correctly... try adding: ENV['NEW_RELIC_LOG'] ||= File.dirname(__FILE__) + '/../log/newrelic_agent.log' after you set the NRCONFIG environment variable. – Emmen 26/12, 2013 at 18:47

Also try moving the ::NewRelic::Agent.manual_start to right after you require 'newrelic_rpm' – Emmen 26/12, 2013 at 18:55

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:

Manually call NewRelic::Agent.after_fork from the forked child, right after the fork.
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.

Hultin answered 27/12, 2013 at 1:3 Comment(4)

This is the most detailed customer support answer I've ever seen on SO; wish I could upvote this a million! – Dogtooth 28/12, 2013 at 3:45

Wow, thanks @JulianaA! I knew starting the agent close after the fork would be optimal, but I didn't know how the New relic agent's background process actually started itself. It's nice to find out about NewRelic::Agent.after_fork – Emmen 30/12, 2013 at 23:46

Yes-- can you please add NewRelic::Agent.after_fork to the docs. I'm using dante for daemonizing and NewRelic silently stopped reporting data from that process. The solution is to call .after_fork in the daemon. – Inevasible 15/4, 2014 at 17:59

Just a note - the restart_thread_in_children configuration setting mentioned above was enabled by default as of version 3.8.0 of the Ruby agent, so you no longer need to specify it explicitly. – Nork 27/8, 2015 at 3:16

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

Emmen answered 26/12, 2013 at 19:5 Comment(1)

I work at New Relic. This blog post and information is pretty outdated - if @Cogency is using an agent version from say the past year, it won't work. A co-worker is about to post a more current answer. – Literatim 27/12, 2013 at 0:29

References:

Recommended topics

Hot tags