Setting Up Custom Instrumentation Using New Relic for Node.js

The New Relic for Node.js agent has automatic instrumentation for standard web requests, but sometimes that isn’t enough. If you are using web sockets or databases we don’t instrument yet, have background jobs, or have segments of your code that you’d like more insight into, custom instrumentation is for you. Luckily, we’ve added custom instrumentation to the Node agent as of v1.10.0.

I’ll be covering the three forms of custom instrumentation in this post. First, we’ll walk through a brief overview of Web Transactions, Background Transactions and Custom Tracers. After that, we’ll take a deeper dive into each of them with examples, including details on how to get Socket.IO instrumented.

Custom Transactions

There are two flavors of transactions in the New Relic ecosystem: Web and Background. Web transactions are the ones you are already familiar with if you’ve used our agent with your http servers. Background transactions are new along with custom instrumentation, and allow you to monitor work that isn’t performed as part of an HTTP request/response transaction.

Both types are used for wrapping up a batch of work, which can entail interactions with your users or tasks that you run behind the scenes to update caches or process payments. Any external http calls or calls to databases we instrument will be captured as part of the transaction.

Custom Tracers

Tracers are used to capture a unit of work in your application. This could be a call to a database that we don’t instrument, some code whose timing you’d like to measure, or anything else. Tracers are both the aggregate metrics for a transaction and the specific segments you see when you drill down into a transaction trace. They are built to be used as a callback wrappers, but there are also ways around that if you have functions that don’t take callbacks that you’d like to trace.

Examples

Web Transactions

Let’s look at an example of using Web Transactions to monitor Socket.IO. This was one of the use cases we had in mind as we built out custom instrumentation. With websockets, it is impossible to automatically determine the beginning and end of transactions because sockets live a long time and pass data back and forth arbitrarily. Custom instrumentation allows you to tell the agent when meaningful transactions begin and end.

App Server Breakdown

The following example shows two different incoming Socket.IO messages, one that is responded to synchronously and another responded to asynchronously.

var nr = require('newrelic')

var app = require('http').createServer()

var io = require('socket.io')(app)

io.on('connection', function (socket) {

  socket.on('ping', nr.createWebTransaction('/ws/ping', function (data) {

    socket.emit('pong')

    nr.endTransaction()

  }))

  socket.on('new-message',
            nr.createWebTransaction('/ws/new-message', function (data) {

    addMessageToChat(data, function () {

      socket.emit(‘message-recieved’)

      nr.endTransaction()

    })

  }))

})

This code creates a new transaction whenever the new-message or ping event comes in. In the ping case we just response with pong, so these transactions will be very short. In the new-message case, addMessageToChat is a function that inserts some records into redis and calls the callback when it is done. The transaction ends once the callback fires.

Notice how in each of the events we make sure to call nr.endTransaction(). Because the transaction is manually created, and asynchronous work can be performed within a transaction, we have to rely on you to end the transaction. If you don’t, then your transactions will appear very long or may not be reported.

Background Transactions

We’ll look at a couple examples of background transactions, as there are a few different instances where you might want to use them. The first is a periodic cache updater that uses setInterval, and the second is a background job kicked off at the end of a request.

setInterval Example

var nr = require('newrelic')

var redis = require('redis').createClient()

setInterval(nr.createBackgroundTransaction('update:cache', function () {

  var newValue = someDataGenerator()
 
  redis.set('some:cache:key', newValue, function () {

    nr.endTransaction() // End the transaction once redis is done

  })

}), 30000) // Every 30s

This very simple example updates a redis cache periodically. nr.createBackgroundTransaction takes a function, wraps it up, and returns it for setInterval to call every 30 seconds. Like we mentioned above in the Web Transactions section it makes sure to call nr.endTransaction once the cache has been updated.

Post Request Example

var nr = require('newrelic')

var app = require('express')() 

app.get('/message', function (req, res) {

  // Store the message for the current user.

  var message = processMessage(req)

  res.send('got your message')

  res.end()

  var bg = nr.createBackgroundTransaction('update:messages', function () {

    // Add the message to the queues of other people to read

    updateFriendQueues(message, function () {

      nr.endTransaction()

    })

  })

  bg()

})

This is an example of updating data using an eventual consistency approach. You get a message and process it for the current user, then send out updates to everyone who is paying attention to that user over time. One could also imagine monitoring a payment job, or any other background work you want to track, that doesn’t hold up the response back to the user.

Notice that we capture the return of nr.createBackgroundTransaction in a variable, then call it later. Like we talked about in the setInterval example, the value of bg is a wrapped version of the function we passed as an argument. Because it only wraps functions, we have to make sure it gets called.

Custom Tracers

Since custom tracers are typically used to instrument either databases or chunks of code that you want timing on, we’ll look into both of those cases. In the first, we will instrument a fictional SQL database driver, and in the second we will wrap up some data processing.

Database Example

Both examples all assume you are already in a transaction, whether that is from an automatically instrumented framework or a custom transaction.


// `db.clientFromPool` is an async function to get a client

db.clientFromPool(config.db_string,
                  nr.createTracer('db:connect',
                                  function (err, client, done) {

  if (util.handleError(err, res)) {

    return done()

  }

  // `client.query` is where our actual database access happens

  client.query('SELECT count(*) FROM test_count',
               nr.createTracer('db:query', function (err, result) {

    if (util.handleError(err, res)) {

      return done()

    }

    res.write(result.rows[0].count)

    res.write('\n')

    done()

  }))

}))

In the above example, we wrap the callbacks handed to both db.clientFromPool and client.query. db.clientFromPool is async; it either creates a new connection and puts it into the pool, or grabs a free connection from the pool. Because it is async, we need to wrap the callback in a tracer to get transaction state across the asynchronous boundary. Then we wrap up the callback for client.query in order to get timing data for the query.

Tracer Example

Timing for tracers starts when they are created and finish after the callback returns. This ensures any subsequent tracers created in callbacks are nested properly.

Wrapping functions without callbacks

From time to time you’ll want to measure how long parts of your code that don’t use callbacks take. In the following example, we are doing some crypto that has the potential to be a bottleneck so we wrap it up in a tracer so we can see how much of the request is spent doing crypto work.


app.get('/login', function (req, res) {

  var wrappedLogin = nr.createTracer('crypto:login', function (user, pass) {

    // Do some heavy stuff with bcrypt/hmac/etc

    if (authSuccessful) {

      res.send('happy times')

    } else {

      res.send('sad times')

    }

    res.end()

  })

  wrappedLogin()

})

In this example, we use createTracer to wrap up a function. Then we call the wrapped function that is returned, though we could just as easily pass it as a callback to another method. This lets us take a chunk of code and time it, which could also be interesting if you are doing things like converting images or any other processing that is very heavy.

Wrapping Up

Custom instrumentation will enable you to monitor everything in your Node.js app in ways that weren’t previously possible. Keep in mind that this is compatible with our auto instrumentation, so you only need to wrap up things that the agent doesn’t already handle for you. If you’d like to read more, see our documentation here. Any questions or comments? Let us know in our Community Forum.

Wraithan started programming in C++ to write his own video games, then later to cheat at them. He discovered Python and had a blast for a few years in the community. He picked up Node on a whim to build an IRC bot and fell in love. Wraithan enjoys listening to metal, biking, skateboarding, writing IRC bots, playing with hardware, and helping to run PDX Node. View posts by .

Interested in writing for New Relic Blog? Send us a pitch!