Tracing de-optimizations in NodeJS

Last time, I showed you how to profile your application and find the place which slows it down — bottleneck. It helps a lot with finding the place in the code that executes slow, so you can fix that.

But, what if you don’t know how to fix that? How to find the reason of de-optimization in your JavaScript code when you have a lot of different variants of that de-optimization. How to trace specific de-optimizations in your code?

Trace de-optimizations

V8 has a special flag for these cases — trace-deopt. What can it do? It logs into the console information about every function that has been de-optimized. Also, there are handy flags like trace-opt and code-comments, that you can use in addition to trace-deopt.

Let me show you a simple example, which is obvious, but we are doing it in educational purposes. Try\catch block is always a de-optimization for V8 (at least for now), that’s why I’ve chosen it.

function deopt(a, b) {
  try {
    return a + b;
  } catch(e) {
    // in case of error do something
  }
}
for (var i = 0; i < 1000000; i++) {
  deopt(1, 2);
}

Looks like a normal function, right? But, run this example with the following flags:

node --trace-deopt --trace-opt test.js

You’ve got a few lines like [disabled optimization for *, reason: *]. Now, look at the bottom and you will find the output similar to this one:

[disabled optimization for 0x28b793a53101 <SharedFunctionInfo deopt>, reason: TryCatchStatement]

It tells us, that our function, named deopt, has been disabled for optimization because of TryCatchStatement. It means, that V8 will not optimize this function literally.

What if we remove try\catch statement?

function deopt(a, b) {
  return a + b;
}
for (var i = 0; i < 1000000; i++) {
  deopt(1, 2);
}

Run again node with tracing flags:

node --trace-deopt --trace-opt test.js

You will not see here that our deopt function has been de-optimized. In fact, you will find that it has been optimized:

[marking 0x14dd80c7ac9 <JS Function deopt> for recompilation]
[compiling method 0x14dd80c7ac9 <JS Function deopt>]
[optimizing 0x14dd80c7ac9 <JS Function deopt>]
[completed optimizing 0x14dd80c7ac9 <JS Function deopt>]

Now, we are sure that our function deopt has been optimized by Crankshaft.

The flags trace-deopt and trace-opt help us find de-optimizations or to be sure that our function has been optimized. Also, it tells us why de-optimization happened. In our case, it happened because of try\catch statement. When we removed it — functions became optimized.

That was a simple example, but it becomes difficult to find de-optimizations in big projects, when you have a lot of code and running node with these flags will spam your console with a lot of information, so that is difficult to find what you are looking for.

Luckily, thanks to Vyacheslav Egorov, we have IRHydra.

IRHydra

IRHydra is a tool that can display intermediate representations of your code used by V8 optimizing compilers. It’s worth to note that IRHydra works only in Google Chrome, because it uses V8 API.

We need to run node with more flags, because we need to trace intermediate representations too, not only de-optimizations:

node --trace-hydrogen --trace-phase=Z --trace-deopt --code-comments --hydrogen-track-positions --redirect-code-traces --redirect-code-traces-to=code.asm test.js

Running the following command creates two files in current folder: code.asm and hydrogen.cfg. You need to pass these files into IRHydra via Load Compilation Artifacts button in the left top corner.

Since our example with try\catch is too simple, there will be only one anonymous function. That is not so interesting.

IR of try\catch example

So, I’ve decided to run complex example from one of my projects — KittikJS — engine for creating ASCII presentations in your terminal. Here is a link to snippet that I’m running under those flags.

Providing IRHydra with artifacts I’ve collected, I’m getting the following picture:

IR of KittikJS example

As we can see, there are a lot of functions. How to find a de-optimizations here? Well, very simple. IRHydra marks de-optimized functions with different colors, based on type of de-optimization. If you look through functions list at the left, you can find marked function and click on it:

De-optimized function in KittikJS

If function is de-optimized, IRHydra notifies you about this with deopt button in the top. Hovering mouse over this button shows you a description of de-optimization and why it happened:

Why de-optimization happened in flush

So, we know about flush method. We know why de-optimization is happened. Knowing why de-optimization happened and where, helps you a lot in resolving this issue.

We can talk a lot about resolving de-optimizations, but it’s a really tough and long talk. The main goal of this article is to show you a way to find de-optimizations in your code.

You can try this right away with your current project and see what happens. The idea remains the same for any project, environment or whatever is: run node with the described flags -> collect the artifacts -> open them in IRHydra -> see where you have de-optimizations and try to fix them.

Also, do not optimize the whole project, do not ill with premature optimizations. Good luck!

Thanks for reading. I hope, this article shows you a new way to profile NodeJS applications and finding the slow places.

Eugene Obrezkov aka ghaiklor, Developer Advocate at Onix-Systems, Kirovohrad, Ukraine.