Performance profiling Node.js applications

Here we take a look at profiling a node.js app from 3 different angles. Client, Server and System performance. Using free tools available.

Tools:

1) Chrome Canary for client-side
Why: Any client-side javascript using a bundler like ‘Browserify’ will appear as anonymous during profiling (as Browserify builds modules into closures within a module map).
Canary will print the initial function name, hugely helping us track down the heavier functions.
2) Iron-node for server-side
why: Great tool with Electron at its core. Allows server-side code to run in a browser like environment for full access to memory/heap/stack.

Client Side:

2 different things we want to profile here, first is evaluation time, second is event time.

We will start with evaluation time (i.e. on page load).
While a bundle can be downloaded and cached, the browser will ALWAYS evaluate the javascript every-time, there is no getting around that.
The simple rule is the more javascript the longer the execution time will be.
To start load any page with JS enabled.
To profile click
‘Timeline’ -> enable ‘JS Profile’ -> refresh page
The important results here is under ‘Summary’ -> ‘Scripting’.
That prints the entire evaluation time.
JS Initial Evaluation
We can get a breakdown of why it is takes that time by observing the Yellow area in the flame graph.
Evaluation Heat graph
This shows that jquery is taking 24ms of the 26ms evaluation time, possibly a consideration on whether its really worth it.

The second type is event times (i.e. click hijacking/or scrolling)
This example does DOM replacement on clicking a link.
Once the page has loaded click
‘Profile’ -> ‘Collect JavaScript CPU Profile’ -> ‘Start’ -> Click page button -> ‘Stop’
I find it easiest to view the ‘Chart’ view. It prints a heat map (similar to above).
Here we can see the functions which are taking the longest and think about why.
My heat map shows jQuery DOM manipulation taking the longest followed by jQuery Ajax requests.
Event heat map
I could look at swapping jQuery’s `replaceWith` method for a native `replaceChild`. But unless we are replacing alot the difference becomes neglible and it comes down to programmer preference.

Server Side:

As mentioned above we can capture the full stack trace with iron-node.
A side-note, any app using Promises (e.g. Bluebird based) will find the large majority of calls from said library. For example Bluebird calls ‘_tickCallback’ to offload to Nodes event queue.

Again there are 2 ways to profile, (1) Node initialization time, and (2) request processing time. They follow the same client-side techniques.

On initializing iron-node use
‘Timeline’ -> ‘JS Profile’ -> refresh.
Here you can see the total evaluation time. A breakdown of node/dependencies and the app itself.
Iron-node evaluation

For request profiling click
‘Profile’ -> ‘Collect JavaScript CPU Profile’ -> ‘Start’ -> load page -> ‘Stop’
Here its possible to learn not just how much time/cpu/memory your own functions are taking but also those of your dependencies.
Request heat map
It is also possible to search for your own modules e.g. middleware. Get an understanding how your code compares to the complete request stack (see example in image).

System Calls:

On Mac it is possible to use a tool called ‘dtruss’ to print details of any process system calls.
Put the below in 1 tab
#sudo dtruss ­d ­n ‘node’ > /tmp/node.log 2>&1
Run node app in another.
Now we can view ALL system calls during a node process.
I found it interesting watching the System call ‘open()’ (which is obviously when system opens a file).
Node apparently opens ‘node_modules’ folder in the currently directory, then every single directory traversing up to the root directory, before finally issuing a ‘mdoule not found’ error.

Conclusion:

I hope you have found some or any of the details here useful. I find profiling an incredibly valuable insight into how an app/functions/code actually performs. Something hugely important these days.

Leave a Reply