Node.js Profiling in WebStorm. Part 1: CPU Profiling.
Profiling is a hard job. Keeping in mind execution time and code structure is a serious challenge with regard to the huge amount of collected information.
WebStorm assists you on this tough journey. It starts a Node.js application with profiling and automatically opens the profile after the run. It points at hot spots by opening and highlighting them in call trees and bringing you immediately to the related source code. The IDE can filter out “noise” by showing only the functions that took too much time.
To try this feature right now, start with selecting Record CPU profiling info in the V8 Profiling tab in your Node.js Run Configuration.
Update: Part 2: Memory profiling is now available.
Table of content
- Background information
- Diving into the feature details
- Running Node.js application under profiler
- Explore call trees
- Analyzing the Flame chart
Background information
CPU profiling is a way to look inside code execution and see how the system lives in dynamics. Due to the Node.js IO-bound one-thread architecture, it is especially dangerous to experience a CPU-consuming callback in an event thread.
Profiling method and results distortion. Node.js CPU profiling in WebStorm is built around the V8 built-in sampling CPU profiler, which provides information about the execution of your code and the behavior of the JavaScript engine itself including garbage collection cycles, compilation and re-compilation, and code optimization.
The way sampling profilers gather information has certain limitations that one should always keep in mind. Profilers do not permanently record stack traces of your application but do that at certain intervals that are called ticks. This does not guarantee high accuracy because snapshots are taken at random moments, independently from the application execution.
As a result, the recorded information does not provide us with the whole picture of what happened during execution, some of the called functions may be missing, as well as information about the number of calls of each function. Moreover, even the relative quantities of function calls may be distorted.
Despite all the above, statistically, this method still gives results that are good enough to make a solid base for judgements about hot spots.
Remote profiling. You can work with resulting log files for Node.js applications that run with profiling on remote machines. This can be useful for stress testing of your application.
To run your Node.js application with profiler remotely, start it with the following flags:
node --prof --log-timer-events
After the application execution if over, open the v8.logTools | V8 Profiling | Analyze V8 Profiling Log on the main menu).
Learn more about running the internal profiler from the command line in the Node.js docs or from the “For Developers” section on the Chromium official website.
It all may sound too complicated, but don’t panic! WebStorm tries to simplify the inner details for the developer: you just run the application and see the hot spots.
Here you are:
Diving into the feature details
In a nutshell, you can use CPU profiling with the following scenarios:
- Run a Node.js application from WebStorm with CPU profiling.
After the application execution is over, the CPU profile view is opened. - Open an existing Node.js profiling log. This may a be log recorded while running scenario 1 or even in another environment (see section about Remote Profiling).
- Open a log file recorded by Chrome or Chromium (run with profiling flags).
To open a log file, choose Tools | V8 Profiling | Analyze V8 Profiling Log on the main menu.
Running Node.js application under profiler
In your Node.js Run Configuration, enable recording V8 profiling information:
Specify the path to the folder where the recorded logs will be stored, log files are named isolate-sesstion_number.
Choose whether you want to create only one log file (and accordingly one profiling results view) for all V8 instances or you need a separate file for each instance.
Click the green run icon to start your application, and run the scenario that you want to investigate.
After the application execution is finished, WebStorm opens the CPU profile in the V8 Profiling tool window.
Explore call trees
We present the collected information in the following ways:
- Top Calls: hot spots list (a list of actions that took long)
- Bottom-up: first, we show hot spots together with their callers, and callers of their callers etc., i.e. a tree of callers.
- Top-down: from entry points we unroll the execution tree down, from caller functions to callees.
Time in a CPU profile is presented in tick units — time intervals at which the sampling profiler takes stack traces.
The number of ticks or its ratio to the total execution time is presented as Total or Self. The Total value shows how much time was spent inside a function and the functions it called (i.e. recursively). The Self value shows how much time was spent only inside a function itself without taking into account its child nodes.
Top Calls view
We use the following color indications:
- Grey for native (JavaScript engine) actions
- Blue for Node.js calls
- Default text color for the user code
Functions from the same file are shown in the same color.
You can navigate to code! We search for the files and symbols mentioned in the snapshot and try to find them in your project.
We also can go inside Node.js sources and core modules and inside V8 sources: go to Preferences/Settings | Languages & Frameworks | Node.js and npm and select the Coding assistance for Node.js checkbox.
Bottom-up view
This view shows the ratio of the execution time of a function to the execution time of its caller (that is, its parent). Use the Parent % Filter slider to filter the results, for example, you can choose to see only the functions that took more than 5% of the total execution time.
Top-down view
Here you literally get full control over the execution information.
This view shows all the calls as a tree, which sometimes may go really deep. To help you deal with it, we by default expand all nodes where execution took longer than 10% (for either the Self or the Total time).
And last but no the least — you can get all the trees — the Top Calls, the Bottom-up, and the Top-down — saved as a text file!
V8 optimizer
Note the signs ~ and * before function names:
* indicates that the function was optimized by V8.
~ indicates that the function was not optimized.
Though optimization is never applied to short-running code and in some cases it may be postponed by the engine, these signs may point at the places where the code can be rewritten for better performance. More information on the subject is available in this article.
Analyzing the Flame chart
Use the multicolor Flame Chart to find where the application paused and explore the calls that provoked these pauses.
The chart consists of four areas:
- The upper area shows a timeline with two sliders for settings the beginning and the end of a fragment to investigate.
- The bottom area shows a stack of calls in the form of a multicolor chart. When called for the first time, each function is assigned a random color, whereupon every call of this function within the current session is shown in this color.
- The middle area shows a summary of calls from the Garbage Collector, the engine, the external calls, and the execution itself. The colors reserved for these calls are listed on top of the area.
- The right-hand pane lists the calls within a selected fragment, for each call the list shows its duration, the name of the called function, and the file where the function is defined.
Select a Fragment in the Timeline
To explore the processes within a certain period of time, you need to select the fragment in question. To do that, use the sliders or click the window between two sliders and drag it to the required fragment. In either case, the multicolor chart below shows the stack of calls within the selected fragment.
To enlarge the chart, click the selected fragment and then click Zoom on the toolbar. WebStorm opens a new tab and shows the selected fragment enlarged to fit the tab width so you can examine the fragment with more details.
Synchronization in the Flame chart
The bottom and the right-hand areas are synchronized: as you drag the slider in the bottom area through the timeline the focus in the right-hand pane moves to the call that was performed at each moment.
Moreover, if you click a call in the bottom area, the slider moves to it automatically and the focus in the right-hand pane switches to the corresponding function, if necessary the list scrolls automatically. And vice versa, if you click an item in the list, WebStorm selects the corresponding call in the bottom area and drags the slider to it automatically.
Navigation
WebStorm supports navigation from the right-hand area to the source code of called functions, to the other panes of the tool window, and to the areas in the flame chart with specific metrics.
You can also navigate to the stack trace of a call to view and analyze the exceptions. To do that, select the call in question and click Show As Stack Trace. WebStorm opens the stack trace in a separate tab. To return to the Flame Chart pane, click the V8 CPU Profiling tool window button in the bottom tool window.
Subscribe to WebStorm Blog updates
