Timing Performance with Performance Hooks in Node.js

Image from Unsplash.com

Knowing the usage of resources would go a long way in helping identify parts of your system that need to be optimized.

Since theevent loop is germane to the story, let’s decipher it first.

The Event Loop

Node’s architecture is mainly composed of two major components: V8, the engine that serves as the JavaScript interpreter and libuv, the library that provides event loop to Node.js. Also, of importance is the fact that in a Node application, everything goes through the event loop.

Node.js is an event-based platform, which means that everything happens as a reaction to an event. In any given event-driven application, there is generally a main loop that listens for events then triggers a callback function when one of those events is detected.

To really understand the event loop, let’s dive into the various phases of an event loop cycle and what goes on in each of them.

a. Timers

Everything that was scheduled by setTimeout() and setInterval() will be processed here.

b. Set Immediate

Runs all callbacks registered via setImmediate().

c. IO Callbacks

Here most of the callbacks are processed.

d. IO Polling

Polls for new events to be processed on the next run.

e. Close

All on('close') events are processed here.

That’s basically everything you need to know about the event loop. But, in case you’d like to get more knowledgeable on the same, check out the Node documentation and/or this blog.

Big fan of Node.js API

Wonderfully, Node.js has built-in modules that make this process easier and fun. The Node.js API provides us with Performance Timing API which helps in collection of high resolution performance metrics.

In this tutorial, we’ll learn how to use the performance hooks module to get the relevant statistics of writing to and reading data from a file system. Let’s dive in!

It’s worth noting that I won’t be using any external dependencies (or modules) in this little project, so you’re going to learn how to create a REST API in Node.js without, at any given moment, using npm install . Cool, right?

Prerequisites;

As of the time this blog was written, the long-term-support (LTS) version of Node is -v 8.11.3 . Make sure you have this version or a later version installed on your PC.

I will be using insomnia as my REST API client of choice.

Head over to Github and clone this repo.

Navigate to the project’s directory and start the server with : node index.js . Your terminal should logServer running on port: 4000 .

Fire up your Postman or Insomnia and send a GET request to: localhost:4000/index

In my case, I see the following on Insomnia when I run: localhost:4000/index.

GET Request on Insomnia

Try with other routes, just to confirm that everything is working correctly:

All available routes can be seen in the lib/routeHandler.js. On to the good part now :)

Implementing performance hooks

In your lib.routeHandler.js import the perf_hooks module:

const performance = require('perf_hooks').performance;
// or using the ES6 syntactic sugar
const { performance } = require('perf_hooks');

Let’s register performance marks . We will use these marks to gather all performance measures.

We’ll be testing the time it takes to run the handler._user.post method. However, be at liberty to add any test any other part of our API. Just below the function header: handler._user.post = (data, callback) = > { type the following:

performance.mark('Beginning sanity check');

Below the phone variable,

type the following:

performance.mark('Ending sanity check');

Let’s calculate in ms how long it is taking to validate the request data:

Just below, the performance.mark('Ending sanity check');, type the following:

performance.measure('Inputs validation', 'Beginning sanity check', 'Ending sanity check');

performance.measure() takes in three arguments: name, startMark & endMark . Judging by the names provided above, we’re timing the performance between the time Beginning sanity check and the time we end it: Ending sanity check. Then we gave our performance check the name of Inputs validation.

One more change before we see the performance logs.

I’ll include the utilities module for debugging. Just below: const { performance } , type the following:

const util = require('util');
const debug = util.debuglog('performance');

Let’s log out all our measurements. A performance entry has a name, type, starting timestamp and duration. In this case, we’ll only log out the entry’s name and duration.

performance.measure('Inputs validation', 'Beginning sanity check', 'Ending sanity check');
// insert here
const measurements = performance.getEntriesByType('measure');
measurements.forEach(measurement => {
  // I'm going to make the logs colour-coded, in this case I'm using Green
  debug('\x1b[32m%s\x1b[0m', measurement.name + ' ' + measurement.duration);
})

To get the debug messages, we’ll run our server with:

NODE_DEBUG=performance node index.js

performance is the section name we defined earlier: const debug = util.debuglog('performance');

You should see some logs in your terminal now:

From the logs, input validation is taking 4612… ms!

Let’s see how long it’d take to run the entire post request:

To get the latest updates in the codebase, check out this tag: add_perf_hooks.

Debug logs

Your assignment now is to implement a performance mark on user reading & user creating. Leave out a comment if you need help with this. You can also find me on Twitter.

Thanks for reading! See you next time.