node.js Performance Profiling Per Functions

Introduction

There are many performance profilers out there for node.js. Most of them allow you to tap into the v8 logs and pull out performance data like CPU time, memory usage and so on, they are mostly about the environment that your code runs in, they don't give you data by files/functions. Other libraries would have you manually add markers to your code to time things as needed. And some other libraries provide "automatic" hooking, but they fail in one major area which is to duplicate the functions signatures of the overridden (wrapped) functions.

How is node.profiler (node dot profiler) different?

• It gives you clear useful data, per (filenames/function names).
• It doesn't require you to change your code or add markers to your code.
• It hooks to your code dynamically.
• The hooks it creates retains the behavior and signature of the original functions as closely as possible.
• It accounts for async functions. (callbacks).

Background

We needed some serious profiling insight into our code in the company I work for, so we needed to investigate many of the available tools out there. V8 logs was not what we were looking for, we needed to know which function is being called, how many times and how much time it took inside the function. There are libraries like nodetime and async-profiler. nodetime doesn't give you the proper details without marking your code manually. async-profiler still requires some code changes and the wrapper it uses (shimmer) doesn't replicate function signatures faithfully. In our code, we are using advanced dependency injection patterns that depended on the function parameters defined and also we were using some advanced meta-data for functions by pulling special comments from inside the functions code. In short, we needed the wrapper to be super faithful when it overrides the functions. Overriding functions is key to performance profiling tools.

node.profiler solved these challenges.

Using node.profiler

Head on to https://www.npmjs.org/package/node.profiler for the package or simply install it using:

$ npm install -g node.profiler

In your nodejs code folder, simply run node.profiler:

/path/to/your/project/ $ node.profiler

node.profiler will run your project in monitoring mode.

Use your project as needed and then exit your project and node.profiler will create the performance data for you (it also flushes the data every X amount of time when the code is idle).

Output

The core code for node.profiler will output "node.profiler.json" file. This file will contain a JSON object, each property being a filename/function name and inside the property, you will find data that shows the total number of times the function was called and the total time spent inside the function. The time is given in milliseconds and its resolution is in nanoseconds.

{
  "/path/to/your/project/lib/index.js:functionSync": {
    "async": {
      "count": 0,
      "total": 0
    },
    "sync": {
      "count": 1,
      "total": 0.41
    }
  },
  "/path/to/your/project/lib/index.js:functionAsync": {
    "async": {
      "count": 3,
      "total": 1.32
    },
    "sync": {
      "count": 0,
      "total": 0
    }
  }
}

node.profiler has a set of reporters as well (currently just one reporter) which will output a nice looking HTML file with a pie chart in it. The pie chart has different views that will give you full visibility over the data.

Under the Hood

Three major challenges were met while trying to put node.profiler together.

1. Hooking up the code: To hook up various code, an entry point was needed. The best place for this was the require function of node.js which is the entry point into loading any code. A require hook was designed to override the built in require and call an event handler every time a require was called. It needed a lot of meta-data for it to be powerful enough for node.profiler. Data like the calling file, native or not, absolute path (if file), required in tests only, third party or not, local to project or not.
2. A proxy generator (or a wrapper) that discovers the exported functions/objects that we get from require hooks and wrap them as needed properly.
3. Overriding functions with the same signature was tricky. The built it new Function in JavaScript that allows you to create a new function with a parameters list doesn't support closures. So you can not create a function with arguments (copied from function being wrapped). I ended up keeping a reference to the closure functions and creating functions with new Function that are closure safe. You can see my function generator here. The downside is that I have to keep references to all those functions, in the case of wrapping functions, this is normal and expected, we already keep references to functions. In the case of callbacks, we don't because callbacks are supposed to be GC eventually. So we don't use the function generator for the callbacks wrapping.

Advanced Use

You can use node.profiler as is and you can also use it as a library. If you use it as a library, you have some extra functions to do manual markings for custom timing of tasks. begin/end and attachMonitor are the functions you need. You can check those on the npm registry page. The command line tool has several command line arguments, I will go over the most important of them.

• verbose: You can set two levels of verbose to get more insight on what is being hooked and what is being called and so on.
• alternateProjectPaths: This is important because it allows you to specify other paths/substrings that you want to be considered as "local" so the code will hook those functions as well. By default, it will only hook functions local to your project.
• includeThirdParty: By default false, setting this to true will basically hook everything! Might fail on some code, but if the failure is restricted in few files, you can use the option skipAttach to control what to exclude from hooking.
• skipAttach/includeAttach: allows you to fine tune which "require"s are hooked or not.
• If you use grunt in your project, you can use runGrunt to profile a grunt task.
• safeAsyncDetection: true by default, this will miss some functions that operate in async mode but it will also make sure that the profiling code won't crash. You are advised to try to turn this off, if your project works as expected, better keep it off, to detect async functions correctly.

Overhead

The node.profile utility will impact the performance of the monitored app, but this is usually acceptable because you won't be using the profiler on live code. Care has been taken to ensure that the calculations made by node.profiler does not include the extra time it uses itself, but it can't be 100% accurate because of nested function calls.

I will discuss the overhead points in reference to the "Under the hood" section.

The require hook is fairly heavy because for each "require" call, it constructs the stack trace. It needs the stack trace to be able to know from which file the require has been called, this is an essential piece of information for the profiler to function correctly.

Also on each require, the proxy generator will have to traverse the results and override functions/constructors as needed. This takes time but this is done once per file, since functions that are already hooked are not hooked again.

The previous two points discussed affect the "loading" aspect of the target app's code and not the actual useful code. However, the last point I will discuss next, effects the overall performance of the target application.

Each function hooked by the function generator will have an another level of indirection in it with a couple of event hooks. The hooks are fairly fast, doing simple computations but this is done per function call, so you will, in general, feel your application is slower. It is hard to say how much slower but I did some tests on some projects I have, end to end testing, and the time difference was around 15-25%. This is the price we have to pay to gain detailed information about the target app.

References

• https://bitbucket.org/ralphv/node.profiler
• https://www.npmjs.org/package/node.profiler

History

• 4^th December, 2014: Initial version