Profiling Node.js application using v8-profiler
As I mentioned in my previous article we are working on an application where 1ms extra CPU consumption per request is also a big deal. Adding profiler wrapper and getting the trace is ok up to one level but you want to understand the problem deeply you need to do proper profiling. There are multiple APM options are there like newrelic & etc. Some good open source APMs also available like APM with Elasticsearch & etc.
But sometimes it’s not possible to use the APMs because of budget constraints if you want to use paid too or server/application maintenance headache if you want to use open source ones. Don’t worry there are several ways to solve this problem. Let me share one way for you.
There is a beautiful npm package is there to solve our problems. Which is none other than v8-profiler.
I am building a small web application for our example purpose. This application has an API which returns words with the count(number of times repeated) in a sentence which is given as input. It won’t give count for common/stop words.
Exp: a, an, another, any, certain, each, every, her & etc.
Usually, our applications will have controller and business logic code in different places so just to make sure our example application like the normal application I divided code in 3 files. Without wasting any time further let’s dive into our application code.
This is our App.js where we wrote our API entry points. getWordsCountInDesc is the API which we are going to concentrate. Created another API too for doing CPU profiling.
This is our simple controller just take our input sentence and creates a call back which used to respond back to the user.
This is our main logic file. It has small flaw w.r.t performance. Now Its time for deploying our application and checking our API with different sentences.
Almost every time API is taking around 6 ms for a small sentence. Which is not acceptable right because we are not doing anything substantial here. Its time find out the culprit.
Now we need to do CPU profiling. Now our profiling API will help. Lets do CPU profiling for 30 Secs. For that, you need to hit below URL.
http://localhost:3000/doCPUProfiling/profileId/profile1/durationInSec/30Means we are creating CPU profile file with name profile1 for 30 secs duration. For better understanding lets go through this code once.
1. We are taking profileId & duration in secs as parameters.
2. Then staring the CPU profiling with profileId.
3. Then stopping profiling using setTimeout for the number of seconds provided by the user.
4. At that time writing cpuprofile file with profileId in current directory.
Its time to read what our CPU profiler saying. Now open Chrome Developer Tools. Then open the Profiler/JavaScript Profiler tab. If you didn’t find any click on three dots(Customize and control DevTools) then go to More Tools you will find Profiler/JavaScript Profiler there. Now Click on Load button, Select our cpuprofile file.
Now Click on Load button. Select our cpuprofile file. Now click on profile1. You can see something like below.
Now you can clearly see the culprit. InnerArrayIncludes. Most of the time went there only. If you expand it, you will get to know who called also our isItStopWord function with file name & line number.
Our Chrome Dev Tools have some more functionalities also. Click on Heavy (Bottum Up) you will see 3 options. Click on Chart option and select the area where you see the spike that’s the one belongs to our API serving.
Now you can see the stack trace also with time it took. Amazing right. This way we can nail our problems easily.
There is no point in maintaining an array. We should use Set so that the traversing issue won’t be there.
Now let’s see what CPU profiling data says.
Peace. Happy Coding.
See my original article here.
