NodeJS in Flames

May 2021

Hi, let’s do a quick POV.

You are a software engineer building amazing products, shipping them to production and telling bad jokes on Twitter. Once or twice a month when Mercury is in retrograde, you are confronted with a complex bug on production. A part of the code seems to be hogging CPU on the server and sometimes taking it down.

You have tried to reproduce in other environments, but you can’t. Figuring it out as it happens on prod seems to be the only option. How do you solve this?

This post attempts to help with an answer to that, by discussing CPU profiling with flame-graphs using NodeJS as the target runtime. Although it uses Node, it’s been intentionally written in a way that would get you started with profiling CPU for any known process or application once you have its Process ID.

Background on CPU Profiling and Flame-graphs

Profiling is a method used to get empirical information about the performance of code paths in software. It’s a really useful means of determining performance bottlenecks and finding performance wins in a system. A bottleneck might start out inconsequential, but as systems scale it will become more prominent.

Profiling tools have various ways of displaying the information, which are often specific to the language in question. For example, here’s how it looks if you run node with the profile option (—prof) enabled 1:

[Shared libraries]:
   ticks  total  nonlib   name
     59   17.2%          [vdso]
     30    8.7%          /lib/x86_64-linux-gnu/libc-2.24.so

 [JavaScript]:
   ticks  total  nonlib   name
      1    0.3%    0.4%  Script: ~<anonymous> internal/url.js:1:11
      1    0.3%    0.4%  LazyCompile: ~stringToFlags internal/fs.js:25:23
...

 [C++]:
   ticks  total  nonlib   name
     66   19.2%   26.0%  node::(anonymous namespace)::ContextifyScript::New(v8::FunctionCallbackInfo<v8::Value> const&)
     17    5.0%    6.7%  node::InternalModuleStat(v8::FunctionCallbackInfo<v8::Value> const&)
     15    4.4%    5.9%  node::Binding(v8::FunctionCallbackInfo<v8::Value> const&)
      7    2.0%    2.8%  node::Read(v8::FunctionCallbackInfo<v8::Value> const&)
      4    1.2%    1.6%  v8::internal::Heap::AllocateFixedArrayWithFiller(int, v8::internal::PretenureFlag, v8::internal::Object*)
...

It can quickly become cumbersome to go through all the lines to figure out where the bottlenecks are. This is a classic data visualization problem - how do we aggregate data and present it in a way humans can make sense of? e.g. pie charts, bar charts and in the case of profiling, flame-graphs.

Flame-graphs help visualize profiling data which could become hundreds of lines long. They are also a useful way to just figure out everything that your code is doing, including the syscalls 2. In the context of profiling a single process, each bar in the graph represents a function. The runtime of which may include executing another function. These “child” functions are stacked on top of their parents on the graph.

Here’s how to interpret a flame-graph: /media/Screen_Shot_2021-05-27_at_21.49.49.png Source: https://netflixtechblog.com/java-in-flames-e763b3d32166

A function that has no stacks on top of it is running On-CPU. This means the function is where the CPU spent its time in that period. Child functions increase the duration of their parents, and this propagates down the graph.

You can figure out what is consuming CPU resources by looking for what process spends the most time on-CPU after generating the flame-graph.

When you consider that the code you write is powered by underlying frameworks and sometimes modules which may be the source of an issue, being able to profile to get empirical evidence is important.

Profiling NodeJS CPU

Background on Profiling JIT-Compiled Languages

Before we talk about profiling Node, let’s gain some understanding of how languages like Node are profiled. This would help you understand the strategies for similar languages and even come up with your own strategy.

When tracing or profiling a language, the way it is implemented is a big factor. As a JIT-compiled language, Javascript is compiled into byte-code and then compiled into machine code at runtime. Profiling tools like perf use symbol tables to translate memory addresses into function and variable names, so that they can be read by us humans 3.

JIT-compiled languages don’t have symbol tables by default, which means If you profile these using perf, you’ll see symbols for the VM engine, but you won’t see the language-level context you might be expecting. e.g. NodeJS functions.

Perf 4 has solved for this by allowing the VM maintain a /tmp/perf-PID.map file for symbol translation. Java and Node have this implemented, adding that context to the resulting flame-graphs.

Practical - NodeJS Profiling Example

When trying to solve a performance problem like the one in our POV, there are various scenarios you can find yourself in. For the purpose of understanding basic profiling, we’ll limit it to two - profiling on the shell (external) and profiling the Node process itself (internal).

In both cases we’ll be use a basic framework:

To help create an actual scenario, I have added the code to a sample Github repository. In the NodeJS code there is a function that hogs CPU and increases the overrall time taken to process requests, making it problematic. I encourage you to clone the repo and follow along so you gain basic practical experience.

With each scenario there are two options - manual and with the sample repo. If you are trying to profile on your own application, you can try the manual option(s). If you’re just exploring and want to learn, use the sample repo.

Profiling the Node Process internally

This method demonstrates intrusive profiling by recording perf events directly when starting Node. It’s useful for direct profiling when trying to find a bottleneck.

Manually

With Sample Repo

Profiling on the shell (bash)

This method demonstrates how you can profile an already-running Node process when you are connected to the shell. Useful when there’s an ongoing issue and you need to generate a flame-graph. It can also be adapted to profile another process as long as it has symbol tables generated.

Manually

With Sample Repo

WARNING - the map file generated has been known to grow in size, which is why we are using the perf_basic_prof_only_functions option, which looks for less symbols than the -perf-basic-prof which can only be run for a couple of hours before the /tmp/perf-PID.map file becomes really big. Regardless, if you are running servers for long periods, you should watch the growth in size of the files and better still remove the option after you’re done profiling.

After running the steps above, open the generated flame-graph in your browser. If you used the sample repo, the results from internal and external profiling should look like this:

Internal

/media/flame-internal-8.16.1.svg

External

/media/flame-external-8.16.1.svg

By interpreting the graph using the On-CPU method introduced in the Background section, we can see that the node process is using up CPU, and the section of our code with the issue is get /usr/src/app/node_modules/fast-levenshtein/levenshtein.js:27!

Conclusion

Congrats on making it this far! We’ve covered quite a bit in this post. Here are the highlights:

There is more to the topic than I have covered in this post. Some questions should’ve come to mind when you think about the reality of our production environments. For example:

Using APM tools we could do some of this profiling and graph them over time, and even track performance between deployments. I haven’t done as much exploration of what the reality of that looks like yet. I intend to do so soon and will be covering in subsequent posts, so keep an eye out!

Thanks to Griffith, Ife and Chidi for reading drafts of this.

Further Reading

Notes

  1. More information about profiling this way can be found in this post - Easy profiling for Node.js Applications

  2. A syscall is a way for programs to tell the kernel to perform an action or a service. e.g. allocate memory or create a new process. 

  3. Symbol tables contain a mapping of functions to memory addresses. More information here

  4. Perf is a linux tool also called perf_events. It is powerful - it can instrument CPU performance and is capable of lightweight profiling. It is included in the Linux kernel. 

Hi! My name is Opeyemi. I like distributed systems, NodeJS, Golang and Puff Puff. You can learn more about me or message me on Twitter.

Share on