Tracing, Debugging and Profiling Node.js with spy-js
This post is part of a series of posts covering features in WebStorm 9 EAP:
Spy-js, our “secret agent”, has done a great job at tracing, debugging and profiling front-end JavaScript code. With WebStorm 9 EAP, we’re expanding its job: there is no back-end Node.js code our 007 can’t infiltrate.
As a refresher, spy-js was introduced with WebStorm 8. It allows tracing our code without resorting to console.log, debugging it without breakpoints and profiling it without any specialized tools. When running our application with spy-js, it gathers intelligence which we can use to see exactly what was going on in our code, even if it’s no longer running.
Let’s pour a Vodka-Martini (shaken, not stirred) and see how we can use spy-js for tracing, debugging and profiling Node.js apps.
http://youtu.be/kzw8GmakYGY
Spy-js Run Configuration for Node.js
First things first: we will have to create a new Run Configuration of the Spy-js for Node.js type. The parameters we have to specify are very similar to a regular Node.js Run Configuration: the Node interpreter, the working directory, the path to the JavaScript file we want to execute and so on. Optionally, we can provide a spy-js configuration file and decide which TCP port it will use to do its work.
Once that’s done, we can launch our app using this newly created Run configuration. Pressing Shift+F10 (Ctrl+R on Mac OS X) will do the trick.
The Spy-js Tool Window
After launching our application, a new tool window will open in which we can see the various types of information spy-js collects. For my Express app here, we can see from the Events Pane that the app has started from a script, as well as the different events and executions that took place while running and using the application. Hovering any event will show some useful information, like the list of scripts that participated in the execution and the time it took to run.
Selecting an event populates the Event Stack pane, showing the stack tree along with a short file and function name. For npm packages, the name of the module is displayed as well. We can also see the execution time of the function. Some nodes may have their execution time rendered in blue, meaning the function is responsible for more than 50% of the execution time of the expanded stack level. A perfect candidate to look into for performance optimization! Nodes rendered in red have had an unhandled exception occur.
The right-most pane shows more details about the selected stack tree node, for example the arguments passed into it.
We can use the context menu pretty much all the time for various actions, such as navigating to the package.json file, the source code for the highlighted function, and more interesting: the trace for the selected function. Press enter or use the Jump to Trace context menu of the selected node. Spy-js will show us the code with executed statements highlighted, and we can hover over variables to see their values, or over functions to see their return values. Note that we can also enable Autoscroll to Trace from the toolbar to automatically open the trace file when selecting a node.
From the code above, we can see the code that was executed: the “else if” block was not touched since the first condition matched for this request.
Mute Files and Modules
When using spy-js for the first time, or with modules like Express, the information shown can be overwhelming. To give you an idea, here’s the stack trace for hitting the index route in my application:
The function timings and trace of everything that happens in Express may not be of interest. By using the Mute this node module context menu on any of the Express functions, the tree will contain everything except the muted module on subsequent requests.
Using the Capture Events toolbar button, we can specify the events we want to capture or filter out. The Edit Capture Exclusions option opens a dialog in which we can filter events by event names or file name.
Spy-js with Child Processes
Whenever we want to run parallel processes in Node.js, we can go beyond its single-threaded nature and make use of the child_process module. Consider the following (pretty much useless) code that spawns several child processes.
When running app.js with spy-js, the Events Pane will have a node for our main program, as well as for the child processes that have been launched. We can do exactly the same things with them as we did earlier: each process will have its events listed, and we can drill down into the stack traces, mute specific modules and so on.
Child processes support is really handy when working with Node.js cluster: spy-js intercepts child process forking deep enough to trace applications that are using Node.js cluster extensively.
Simultaneously spying on the browser and the server
With spy-js for Node.js, we can now trace, debug and profile our server-side code. It’s worth mentioning that two spy-js sessions can be launched at the same time: one for the browser and one for Node.js. This gives us a nice end-to-end view of what’s happening in our application. The spy-js tool window will show both sessions in a different tab.
Download the latest WebStorm 9 EAP and go on a secret mission with spy-js. We would love to hear your thoughts in the comments below!
Develop with pleasure!
JetBrains WebStorm Team
