Tools to help diagnose and pinpoint Node.js performance issues

Introducing Bubbleprof - a novel approach to Node.js async profiling

Alan Slater, Kamil Mech, Mathias Buus, Matteo Collina

Since the beginning of Node, profiling asynchronous operations has been a big hurdle. After months of internal research we have finally found a solution which greatly simplifies the process of finding async bottlenecks in Node applications. Today, we are glad to announce the first public version of Clinic.js Bubbleprof. Bubbleprof allows developers to capture all async activity with minimum effort. It then uses a novel "bubble" approach to visualize this activity. Everything you need is in one HTML file.

You can find it included in the Clinic.js bundle:

npm install -g clinic

Try it out by cloning our basic Bubbleprof examples from Github:

git clone git://github.com/clinicjs/node-clinic-bubbleprof-examples

Start simple and run the basic-latency example, which visualizes how a latency of 1s affects your server:

clinic bubbleprof --on-port ‘autocannon localhost:$PORT’ -- node node-clinic-bubbleprof-examples/basic-latency

Notice the long lines of latency? That’s a quick way of finding something to improve in the app.

Traditional Async Profiling

Node works best in heavily-I/O-related contexts, and often acts as a mediator between many data streams and interfaces. Due to JavaScript’s evented nature, most I/O is performed asynchronously – especially when our Node process is a networked application. If we can measure asynchronous activity in a decoupled way, we can find out where an application is waiting. Finding out where an application is waiting means finding out where to optimise our asynchronous flow. The end result being that our application becomes faster, and our users happier.

Tracking and profiling asynchronous is a tricky issue. Consider the following simple example:

setTimeout(crash, 1000) // maybe crash after 1s
setTimeout(crash, 1000) // call it again

function crash () {
  if (Math.random() < 0.5) {
    throw new Error(‘an async error’)
  }
}

Running the above program will (probably) crash our Node.js process with a stack like this:

set-timeout-crash.js:5
  throw new Error('an async error')
  ^

Error: an async error
    at Timeout.crash [as _onTimeout] (set-timeout-crash.js:5:9)
    at ontimeout (timers.js:466:11)
    at tryOnTimeout (timers.js:304:5)
    at Timer.listOnTimeout (timers.js:267:5)

Figuring out which one of the setTimeouts triggered the crash is a surprisingly hard problem. The stack trace only contains the last synchronous part of our application. If we want to not just figure out what crashed the program but also profile how many times the async function is called and from where we would run into similar problems.

This is not a new problem in Node.js, but in fact one that’s been around since the very beginning. Lots of solutions have been attempted for making the situation better in regards to capturing longer stack traces and measure runtime of functions. Most older solutions did things like rewrite all your code that does something async to capture a stack trace before and then combine them back to produce a “full” trace. This requires plenty of “monkey patching” and is known for being brittle and have a substantial negative performance effect - it would often de-optimise your code because of too much reflection.

Enter node core instrumentation

Luckily the Node.js core collaborators have been trying hard to make the diagnostic situation better for everyone by adding more instrumentation to the Node.js core codebase. In fact, all async code (excluding native modules) is actually triggered from Node.js core which means that the situation has to improve there for userland to get any benefit. Some of the new instrumentation that has landed recently is the new async_hooks core module. async_hooks is an interface to a new set of instrumentation in core that instruments any async operation. This means that we now have a way to hook into when something async happens and also a way to find out what the parent async operation was. This is a massive improvement in the profiling landscape as it means we can now get a ton of valuable timing data out of Node.js core without having to resort to a bunch of hacks.

If we add some async_hooks magic to our previous example, then we can figure out which of the setTimeouts made our program crash:

const hooks = require('async_hooks')
const stacks = []

hooks
  .createHook({
    // save the stack when we do something async
    init: (id, type, trigger) => (stacks[id] = new Error('error').stack)
  })
  .enable()

setTimeout(crash, 1000) // maybe crash after 1s
setTimeout(crash, 1000) // call it again

function crash() {
  if (Math.random() < 0.5) {
    // lookup the previous stack
    console.log(stacks[hooks.executionAsyncId()])
    throw new Error('an async error')
  }
}

Running it will show something similar to this:

    at AsyncHook.init
    …
(set-timeout-crash-hook.js:11:1)
    ...
Error: an async error
    at Timeout.crash [as _onTimeout] (set-timeout-crash-hook.js:17:11)
    at ontimeout (timers.js:466:11)
    at tryOnTimeout (timers.js:304:5)
    at Timer.listOnTimeout (timers.js:267:5)

Which tells us that this time it was the timeout at line 11 (first one) that triggered the crash.

In addition to letting us capture the async context async_hooks gives us valuable insights into latency stats, throughput, the type of resource, and more.

Reducing complexity

async_hooks and other new core instrumentation give us a new waterhose of profiling data in Node.js. This is essential for doing any kind of profiling but also poses an interesting challenge. How do we digest this data in a way that helps us diagnose bottlenecks and/or find errors in our application? This, of course, is a non-trivial problem and depends on the use-case we are trying to support.

This is why we’ve started building Bubbleprof, a new command in the Clinic.js toolchain. Bubbleprof uses a series of heuristics and a novel “bubble” based UI to help all kinds of users - from beginners to advanced - to determine where asynchronous time is spent in their application.

Through a series of design workshops we’ve come up with a couple of heuristics we think help group async data together in a way that makes it easy to get an overview over your application.

There are 3 interesting groupings of code in your Node.js application:

"User code", ie. code you are writing as part of your app.
"Module code", code running in modules you have installed from npm
"Node core code", code running in Node.js core.

When code crosses the boundary between one of these groupings, we consider it important information that can help us group asynchronous operations together. Bubbleprof tries to collect and aggregate all async operations (using async_hooks) and then group them into bubbles based on this heuristic.

Visualizing async flow

Now that we have a manageable number of groupings - instead of hundreds or thousands of distinct async operations - we can draw a diagram that acts like a map of an application's async flow, showing where time is spent. For example, in this profile based on ACMEair (a dummy flight data application designed for use in benchmarking), we immediately see a flow centered around the database module MongoDB:

Live example

Bubbles and links

These "bubbles" represent the time spent in synchronous and asynchronous operations within this grouping. The largest bubble in the view represents calls from the mongodb-core, which calls other functions elsewhere in the mongodb code. It dwarves every other bubble, which compared to it are tiny dots, and much of the application branches off from it. Clearly, optimising how this application uses mongodb has a lot of potential to reduce overhead and trigger other async operations earlier. The dominating green colouring in the inner ring tells us that most of this time is spent on network-related activities, while the small sliver of purple indicates some time spent in scheduling (ticks, timeouts and promises). Rolling the mouse over the labels for these colours gives us information on what they mean and highlights the appropriate parts of the diagram.

There is also a very long line to a tiny bubble labelled nextTick + http.server. A thin white stripe tells us that this is code from our own application. Connecting lines like this one represent asynchronous delays from operations that were called in one grouping (here, the mongodb module), but execute code in another (here, some of our application's own code which involves an http server and nextTick wrappers). This suggests another area for us to focus on: our own code, which might be a quick win.

Live example

Drilling down to code

We can click into these links and bubbles to see what is going on inside them. Clicking on the line shows something very simple: startServer is responsible for almost all of the delay in this grouping. Clicking again brings up the stack trace; and also - because context here is important - the complete async trace of the chain of events from our application's initiation to this point.

Live example

Because these traces can be very long, we group adjacent frames from the same section of code, automatically expanding those from the user's own application. In this example, startServer at line 192 of our app.js called the express module, which invoked a number of operations in node core, with createServerHandle being the last one. This was called from the mongodb client.

Looking at the area chart on the right, we see that this was pending for most of the runtime of our application. Is this a slow server we want to optimise, or a healthy service constantly awaiting requests? We can check our application code and find out.

We can click the upwards-pointing arrow labelled "Mongo..." to navigate up into that big, mongodb-core bubble. The view inside it also very simple - dominated by Connection.connect, called from within node_modules/mongodb-core.

Live example

Navigating async complexity

So what about the parts of our mongodb integration that are fast? If we click the small topmost grouping, it expands out into another more complex layout. These tiny, extremely short async operations would have been too small to be useful information in the previous view, so Bubbleprof has collapsed them together.

Live example

Exploring this view, we see activity mostly relating to database connection pools and sockets. Everything looks fine in terms of speed, and we can use these maps of how processes execute in series and parallel to better understand the module's flow, diagnose timing bugs, spot operations in series that could be more efficient in parrallel, and identify unnecessary steps that can be optimised away.

This is just a simple example. You can use Bubbleprof with benchmarking tools like Autocannon or Wrk to generate robust performance profiles, and see the changes in your application's throughput and flow as you try things out. We have a simple step-by-step walkthrough guide to help you get started.

Get Started

We'd love for you to install and try out Bubbleprof to see how it can help get to the bottom of your Node.js performance issues.

Head over to the walkthrough and you'll be up and running in minutes.

We'd also love to get your feedback on Bubbleprof/Doctor/Flame and the outputs they generate. In this early phase of release, we're eager to have it used on as many real-world problems as possible.

We welcome everyone who is interested in becoming part of our community. If you'd like to get involved in any aspect, not just code, first read our Code of Conduct and Contributor guide. Then feel free to reach out to us on GitHub or via the usual social channels.

Clinic.js Doctor just got more advanced with TensorFlow.js

Andreas Madsen

At the start of 2018 we introduced Clinic.js, an Open Source toolbox for developers to profile and improve their applications. As part of this toolbox, we launched Doctor, a very user-friendly tool, that uses data analysis to recommend the next steps the user should take to diagnose and fix performance problems in Node.js. And just last month we shipped a new tool, called Clinic.js Bubbleprof, which specializes in profiling I/O issues.

While we are developing new exciting tools, we are also making a significant effort in improving the existing tools we have. An issue we have noticed during our many workshops, where we teach people to use Clinic.js, is that the way Doctor analyzed the CPU usage wasn’t optimal. Until recently Doctor was using simple statistics to analyze the CPU usage, but now, with the experience we have gathered over the last half year, we have been able to develop much a more advanced Machine Learning model. This model is developed with TensorFlow.js. Because TensorFlow.js uses JavaScript, Doctor is just as easy to install as always but is now much more advanced.

The Details

An application with an I/O issue typically has a very low CPU usage, because it is spending most of its time being idle. However, what we have noticed is that even applications with I/O issues generate garbage, that the garbage collector will clean up. When the garbage collector runs, it makes the CPU usage spike. If the garbage collector runs often enough, the CPU usage spikes so much that our simple statistical model can no longer see that the CPU usage is too low.

CPU usage, with GC overlay: Shows the CPU usage with different types of garbage collection overlayed. Notice, that the alignment isn’t perfect and other events are interfering.

In a simple world, one could just have used information about when garbage collection is happening to filter out the CPU spikes. Unfortunately, the CPU usage data is sample based while the garbage collection data is event-based, which makes it difficult to align the two data sources. From our investigation, it is also clear that other things are going one. Some possible causes could be optimization or writing the logging information itself. All are things that happen in another thread, therefore they make the CPU usage spike to above 100%.

Since it isn’t possible to consistently detect when another thread from V8 within the application makes the CPU usage spike, the solution was to separate the spiky data with Machine Learning. For this, we use a Hidden Markov Model (HMM) with Gaussian Emissions. The central idea in HMM is that a measurable observation, the CPU usage, is influenced by a hidden unobservable state, is V8 is running an extra thread or not. The Baum–Welch algorithm, allows one to statistically determine what the most likely connection is between the hidden state and the measurable observations. The Viterbi algorithm can then infer the hidden state from the measurable observations.

A trainable and inferable implementation of HMM with Gaussian Emissions didn’t exist in the npm register, therefore we ended up implementing it ourselves using TensorFlow.js. The implementation is called hidden-markov-model-tf and is available on npm.

It's fully Open Source and the sourcecode is available here.

CPU usage filtered: Shows the CPU usage from the user’s application itself, being correctly separated from the CPU usage spikes caused by V8.

Using our implementation of the Hidden Markov Model, it is possible to separate the CPU usage caused by V8 from the CPU usage directly related to the user's application. With this separation in place, it is now possible to detect an I/O issue by checking if the CPU usage of the user’s application is too low.

Final Result: The Doctor detects an I/O issues by seeing there is a low CPU usage, even if there are spikes caused by V8.

Contact

If you would like us to do a workshop, where we teach how to profile and improve the performance of your application. Or if you need Machine Learning applied to some of your data. Then, feel free to contact us at https://www.nearform.com/contact/.

All the latest coverage and news on Clinic.js

Conor O'Neill

We have been very remiss in keeping the Clinic.js blog up to date. Rest assured that is going to change for 2020.

If you are curious about how Clinic.js might be able to help you pinpoint performance bottlenecks, here’s a glimpse at how it has helped others and what they have to say about what makes it unique.

NearForm Research new team members

The most important thing to tell you is that NearForm Research, a new group inside NearForm, is now responsible for Clinic.js. It's still the same Node.js experts but now we have even more team members. You can expect to see a lot of new functionality in Clinic.js over the next several months.

Our newly expanded NearForm Research team finally all together in one place! 🚀 #ideasflowing #opensource #nodejs @jasnell @addaleax @goto_bus_stop pic.twitter.com/Gub6LELzrF
— NearForm Research (@NF__Research) January 29, 2020

Getting involved

We love hearing from Clinic.js users and how it helped to solve performance issues for them. If you are interested in sharing your thoughts on the future of Clinic.js, please get in touch.

Some great mentions of Clinic.js

ADP Lifion

Clinic.js is one of those tools that has become invaluable for many Node.js developers. We were particularly pleased to see this post from Ali Yousuf in ADP Lifion Engineering on the Promise.allpocalypse - The performance implications of misunderstanding Node.js promises.

Opensource.com

This was quickly followed by Hiren Dhadhuk over on opensource.com including Clinic.js in their 9 favorite open source tools for Node.js developers

Sematext

And earlier in 2019, Adnan Rahić included Clinic.js in their Node.js Open Source Monitoring Tools list. And we loved the comment that "It’s surprisingly easy to use."

TensorFlow.js in Clinic.js Doctor

The TensorFlow.js team have very kindly highlighted its use in Clinic.js Doctor at multiple events including TensorFlow Dev and Node+JS Interactive.

Clinic.js Helping Users

Here's just a selection of the lovely things people have been saying on Twitter about how Clinic.js has helped them.

Michael Geers

Was able to cut the build time of our design system in half today 🚀. First time I used clinic.js by @NearForm. Awesome tool to visualise what's going on inside your node process. Thanks @DennisReimann #uiengine #designsystem #profiling #debugging https://t.co/88xCDuec06 pic.twitter.com/vNJDlkdK8M
— Michael Geers (@naltatis) August 8, 2019

Liran Tal

/3 Through these questions we understood the left and right borders and usage scenarios. One of the preliminary activities to developing this was doing performance testing with @NearForm's clinic to assess the JSON processing impact on the CPU
— Liran Tal ✨ Node.js CLI Magic ✨ (@liran_tal) February 10, 2020

Antoine Gomez

Thanks to @nodeclinic for helping me figure out a stupid pagination memory bug in my code

Before / After : pic.twitter.com/5kz7ebxad7
— Antoine Gomez (@antoineg) September 12, 2019

Dipro Chatterjee

I recently spoke about #clinicjs and is absolutely delighted to be a user.
— Dipro Chatterjee (@chatterjeedipro) December 17, 2019

Flavio Aandres

Estan usando Node.JS para aplicaciones realmente robustas, posiblemente con Leaks de memoria, Fallas en el EventLoop y procesos demasiado costosos?

Clinic.JS permite saber visualmente cuales son las funciones o metodos que bloquean el eventLoop! 🔥🙌https://t.co/7CDbA5mMwV
— Flavio Aandres (@FlavioAandres) November 19, 2019

Webinars

Want to find out more? We're planning a series of webinars to demonstrate how the Clinic.js suite of tools can help to solve Node.js performance issues. Register your interest here and we'll be in touch with some suggested dates.