Find bottlenecks in Node.js apps with Clinic Flame
Tags: javascript, node, tutorial, debug
Published: 2021-12-29 15:05:50

In 2018 I had the chance to attend a workshop hosted by some great devs from NearForm along a JS conference. 

They showed how to find bottlenecks on Node.js applications using [Flamegraphs](https://www.brendangregg.com/flamegraphs.html) using a very nice profiler they built called [Clinic JS](https://clinicjs.org/).

Too bad, I lost the notes about that workshop, but I remembered the tool name. So I've downloaded it and used it successfully to find an actual bottleneck while working on a side project of mine.

Here's briefly how it works through a super simple example.

## Example app: a slow REST API service (or similar)

Let's fire up a very basic HTTP service using the plain node `http` module, which basically is:

- simulating a slow query returning a random number (`dbQuery`)
- computing with the result it computes the Fibonacci series (`fib`)
- returning the Fibonacci value in plain text

```js
const http = require('http')
const { fib, dbQuery } = require('./util')

const hostname = '127.0.0.1'
const port = 3000
const baseUrl = `http://${hostname}:${port}`

const server = http.createServer((req, res) => {
  res.statusCode = 200
  res.setHeader('Content-Type', 'text/plain')

  dbQuery()
    .then(fib).then(result => {
      res.end(`${result}\n`)
    })
    .catch(err => res.send(err))
})

server.listen(port, hostname, () => {
  console.log(`Server running at ${baseUrl}`)
})
```

The `util.js` module looks like:

```js
const random = (min, max) => Math.floor(Math.random() * (max - min + 1)) + min

const sleep = s => new Promise(resolve => setTimeout(resolve, s * 1000))

const dbQuery = async () => {
  await sleep(random(1, 5)) // ugh!
  return random(10, 40)
}

function fib (n) {
  if (n <= 1) return 1
  return fib(n - 1) + fib(n - 2)
}

module.exports = { dbQuery, fib }
```

As you can see:

- `dbQuery` function is (intentionally) calling `sleep` before generating a random value to simulate slow I/O. 
- `fib` is a (potentially) CPU-heavy task which will block the main Node.js main event loop, especially with big `n` values.

## Basic performance testing using `curl` and `time`

If you simply fire up the service using:

```shell
$ node index.js
```

and then do something like:

```shell
$ time curl 'http://localhost:3000'
```

to test the response time, you'll find out that it's quite slow (average is around **3-5s**).

One can easily _guess_ that both `dbQuery` and `fib` functions may be the cause of the slowness, and then confirm wisely using logging. 

Anyway, let's try to see how Clinic flame could help us.

## Using Clinic Flame

[Clinic Flame](https://clinicjs.org/flame/) is one of the Clinic tools which is very handy in this case.

So let's run the web service through it:

```shell
$ clinic flame -- node index.js
```

Now we can do the same HTTP calls we did above using `curl`, one or two times:

```shell
$ curl 'http://localhost:3000'
```

When done, simply hit `ctrl+c` and Clinic Flame will automatically generate a report and show it to you on a browser page.

Let's look at the report:

![report](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/v3yp5w3yloecjufh2of1.png)

The first thing I did was to uncheck `Depedencies`, `WebAssembly`, `Node JS` and `V8` checkboxes from the bottom bar since I mainly want to see only how my module code is being called.

About the report, we have to look if there are **wide bars with a bright colour**. It basically means that the function is "hot": **lot of time** has being spent at the top of the stack while calling a specific function.

Here's one:

![dbQuery](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/yfx2x73enpv4sqef7ecd.png)
 
and it's related to the `dbQuery().then(fib).then( // ...` code block.

Note also that we have lots of calls to `fib` (which is ok for a recursive function) but with darker bar colours:

![fib](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/yo8s80w2qqq9gs00rnbr.png)
 
This means that `dbQuery` took more time at the top of the stack than `fib` function. Probably we `sleep` more than the time needed to compute `fib` with the random value.

What if it happens the opposite (i.e. less or no sleep time for `dbQuery` and a larger `n` for `fib`)?

![2nd report](https://dev-to-uploads.s3.amazonaws.com/uploads/articles/sl8y3awy6cazd7pptbtl.png)
 
This time basically all the bars are related to the `fib` function and they're super wide: it means that **all the recursive calls to `fib` took a lot of time**.

Note also that if you check `Node JS` or `V8` bars, they're super thin in comparison with `fib` ones. This means than internal Node.js routines took a very short time compared to `fib` calls.

## Why it could be useful?

If you have trouble to understanding bottlenecks in your Node.js-based web service, especially if the "blocking" issue comes from one of your `node_modules` deps, where putting random `console.log` calls to debug is both not easy and time consuming.

Moreover, if your blocking issue is appearing only on heavy load, you can easily test it using the very nice `--autocannon` CLI param (see it with `clinic flame --help`) where you can specificy [autocannon](https://github.com/mcollina/autocannon) options to generate some HTTP load on your web service.