Bugs in your Node.js code can be tricky to find and fix. More often than not, you can find and fix bugs by simply studying your code. This is a fast route to improving the quality of your code. You can also use log statements to do a post mortem, where you run some code and study console output (or a log file) to see how it actually executed. But for some types of bugs–the nastiest of bugs–you will need to go to the source.

In this unit, I introduce you to source-level debugging, where you pause execution in a running program to find out exactly what’s happening with your code.

Once your code is bug free, you’ll want to optimize it for performance and scalability. As a professional Node developer, it’s important that you know how to use a profiler and optimize your code.

This unit gets you started with four tools for debugging and profiling Node applications:

Source-level debugging

As an exercise, we’ll debug the create() method in the Shopping List application’s rest-controller module. We’ll use the same debugging process with each tool:

  1. Start the debugger.
  2. Set a breakpoint, which tells the program where to freeze execution.
  3. Use internal commands to navigate the code.
  4. Inspect variable values in the frozen program.
  5. Create a watch expression to watch those variables on the breakpoint.
  6. Alter the values of selected variables to improve how the program runs.

Note that we’ll debug the Shopping List application from Unit 12 for this exercise.

Get the code

The code you need to follow along with the examples in this learning path are in my GitHub repo.

Debugger #1: Node debugging client

The Node debugging client is a text-based debugger that ships with Node.js, so there’s no additional install required. It’s also super easy to use.

Run Node debugging client

The command to run Node debugging client is: node inspect node_module.

To start debugging the Shopping List application, open a terminal window and navigate to the Unit-12 directory, Make sure mongod is running (run npm run start-mongod in a separate terminal window), then run node inspect ./www/bin.

The output looks like this:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-12 sperry$ node inspect ./bin/www
< Debugger listening on ws://127.0.0.1:9229/90e7bfa4-c775-45ab-acd9-d60773f0c319
< For help, see: https://nodejs.org/en/docs/inspector
< Debugger attached.
Break on start in bin/www:1
> 1 (function (exports, require, module, __filename, __dirname) {
  2 /*
  3    Copyright 2018 Makoto Consulting Group, Inc.
debug>

In the above output, the debugging client stops on the first line of code in the program and issues a debug> prompt.

Type c (or cont for continue) to let the program finish initializing. The full output looks like this:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-12 sperry$ node inspect ./bin/www
< Debugger listening on ws://127.0.0.1:9229/90e7bfa4-c775-45ab-acd9-d60773f0c319
< For help, see: https://nodejs.org/en/docs/inspector
< Debugger attached.
Break on start in bin/www:1
> 1 (function (exports, require, module, __filename, __dirname) {
  2 /*
  3    Copyright 2018 Makoto Consulting Group, Inc.
debug> c
< [2018-08-11T10:38:06.077] [INFO] default - 1534001886077:INFO: lists-dao-mongogb.getDbConnection(): Initializing MongoDB connection...
< [2018-08-11T10:38:06.091] [INFO] default - 1534001886091:INFO: items-dao-mongogb.getDbConnection(): Initializing MongoDB connection...
< (node:20580) DeprecationWarning: current URL string parser is deprecated, and will be removed in a future version. To use the new parser, pass option { useNewUrlParser: true } to MongoClient.connect.
< [2018-08-11T10:38:06.110] [INFO] default - 1534001886110:INFO: lists-dao-mongogb.getDbConnection(): MongoDB connection initialized.
< [2018-08-11T10:38:06.111] [INFO] default - 1534001886111:INFO: items-dao-mongogb.getDbConnection(): MongoDB connection initialized.
debug>

Set a breakpoint for the Node debugging client

Next, we’ll set a breakpoint, so we can see what’s happening with the create() method in the rest-controller module.

There are two ways to set a breakpoint. The first, which I recommend, is to use the setBreakpoint function from the debug> prompt: setBreakpoint(module_file_name, line_number). Here’s how to set a breakpoint in the example application’s rest-controller module, on line 57:

debug> setBreakpoint('rest-controller.js', 57);
 52  * @param {Object} next - the next middleware function in the req/res cycle
 53  */
 54 function create(req, res, next) {
 55     let requestBody = req.body;
 56
>57     listsDao.create(requestBody.description).then((result) => {
 58         utils.writeServerJsonResponse(res, result.data, result.statusCode);
 59     }).catch((err) => {
 60         next(err);
 61     });
 62 }
debug>

Note that the debugging client shows five lines of code on either side of the breakpoint for reference.

When execution hits line 57 in rest-controller.js, the program will freeze.

The other way to set a breakpoint (which I don’t recommend) is to use a debugger; statement on the line just before you want the debugger to freeze:

function create(req, res, next) {
    let requestBody = req.body;
    debugger;
    listsDao.create(requestBody.description).then((result) => {
        utils.writeServerJsonResponse(res, result.data, result.statusCode);
    }).catch((err) => {
        next(err);
    });
}

If you use the debugger statement, you need to restart Node after setting the breakpoint, which is why I don’t recommend it. With the setBreakpoint function, you can set a breakpoint in a running program without needing to restart. I recommend using the setBreakpoint function (or sb) to set breakpoints.

Debugging startup code

Using the debug> prompt, you can set breakpoints at any point in the program, including when the Node debugging client first comes up and stops on the first line of code:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-12 sperry$ node inspect ./bin/www
< Debugger listening on ws://127.0.0.1:9229/90e7bfa4-c775-45ab-acd9-d60773f0c319
< For help, see: https://nodejs.org/en/docs/inspector
< Debugger attached.
Break on start in bin/www:1
> 1 (function (exports, require, module, __filename, __dirname) {
  2 /*
  3    Copyright 2018 Makoto Consulting Group, Inc.
debug> sb('rest-controller.js', 57)
Warning: script 'rest-controller.js' was not loaded yet.
debug>

Because the program has frozen on the first line of code, the rest-controller module has not yet loaded. That’s why you see the warning message: Warning: script 'rest-controller.js' was not loaded yet.

Don’t worry, though: the debugger is just telling you the breakpoint may never be used. (It doesn’t know for sure because the rest-controller module hasn’t been loaded.)

Setting the breakpoint here lets you debug startup code, which runs as the program is loading modules and doing other initializations. It’s good for something like debugging a problem with the database connection. Otherwise, let the program load, and set your breakpoints at the debug> prompt, after the program has reached its steady state.

Viewing and removing breakpoints

Anytime you need to see a list of the breakpoints you set, just type breakpoints at the debug> prompt:

debug> breakpoints
#0 controllers/rest-controller.js:57

To remove a breakpoint, use the clearBreakpoint() function (or cb for short):

debug> cb('rest-controller.js', 57)

You’ve already seen the c command that tells the debugger to continue (or resume) execution. Table 1 summarizes additional commands for moving through your application code in the debugger.

Command Shorthand Description
cont c Continue: Resume program execution.
next n Next (sometimes called step over): Execute the current line of code and stop on the next line.
step s Step: Step into the current line of code. If it’s a function call, the debugger stops on the first line in the function. If not, it behaves like next.
out o Out: Step out of the current function to the previous line of code in the call stack. The remaining code in the current function is executed as usual.
pause none Pause: Pauses program execution at the first opportunity.

If you’ve used source-level debuggers before, these commands should be familiar:

  • Use step to step into a function call.
  • Use out to step out of a function call.
  • Use next to execute the current line of code (stepping over it if it’s a function call) and stop on the next in the current function.

The pause command causes Node to pause as soon as it’s able to process your command:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-12 sperry$ node inspect ./bin/www
< Debugger listening on ws://127.0.0.1:9229/b74206cd-7d21-49ae-9e8b-f9b13eeec42d
< For help, see: https://nodejs.org/en/docs/inspector
< Debugger attached.
Break on start in bin/www:1
> 1 (function (exports, require, module, __filename, __dirname) {
  2 /*
  3    Copyright 2018 Makoto Consulting Group, Inc.
debug> setBreakpoint('rest-controller.js', 57)
Warning: script 'rest-controller.js' was not loaded yet.
debug> c
< [2018-08-11T10:55:16.055] [INFO] default - 1534002916055:INFO: lists-dao-mongogb.getDbConnection(): Initializing MongoDB connection...
< [2018-08-11T10:55:16.069] [INFO] default - 1534002916069:INFO: items-dao-mongogb.getDbConnection(): Initializing MongoDB connection...
< (node:20689) DeprecationWarning: current URL string parser is deprecated, and will be removed in a future version. To use the new parser, pass option { useNewUrlParser: true } to MongoClient.connect.
< [2018-08-11T10:55:16.087] [INFO] default - 1534002916087:INFO: lists-dao-mongogb.getDbConnection(): MongoDB connection initialized.
< [2018-08-11T10:55:16.088] [INFO] default - 1534002916088:INFO: items-dao-mongogb.getDbConnection(): MongoDB connection initialized.
**debug> pause**
break in timers.js:209
 207 }
 208
>209 function processTimers(now) {
 210   if (this.owner)
 211     return unrefdHandle(this.owner, now);
debug>

Get more context (lists(n))

By default, the debugging client gives you two lines of context surrounding the breakpoint (five lines total). If you need more context, use the lists(n) command to tell the debugging client to give you n lines of context (2n+1 total). For example, to tell the debugging client to give you five lines of context, at the debug> prompt type list(5):

debug> list(5)
 52  * @param {Object} next - the next middleware function in the req/res cycle
 53  */
 54 function create(req, res, next) {
 55     let requestBody = req.body;
 56
>57     listsDao.create(requestBody.description).then((result) => {
 58         utils.writeServerJsonResponse(res, result.data, result.statusCode);
 59     }).catch((err) => {
 60         next(err);
 61     });
 62 }

Inspect variable values in the Node debugging client

When the Node debugging client stops on a breakpoint, you can inspect variable values in that code. To do this, you need to enter the Read-Eval-Print-Loop (REPL) introduced in Unit 3, then ask REPL to evaluate the variable you want to see.

First, make sure the application has been started and you’ve set your breakpoint in rest-controller.js, on line 57. Now, open a browser and go to the Shopping List application UI http://localhost:3000. Click on the New Shopping List link and enter a description of Test Shopping List, then click the Create button.

Execution will break on line 57 in rest-controller.js, where you’ve set the breakpoint.

To see the value of the requestBody variable, enter the REPL and type requestBody, then press Enter:

break in controllers/rest-controller.js:57
 52  * @param {Object} next - the next middleware function in the req/res cycle
 53  */
 54 function create(req, res, next) {
 55     let requestBody = req.body;
 56
>57     listsDao.create(requestBody.description).then((result) => {
 58         utils.writeServerJsonResponse(res, result.data, result.statusCode);
 59     }).catch((err) => {
 60         next(err);
 61     });
 62 }
debug> repl
Press Ctrl + C to leave debug repl
> requestBody
{ description: 'Test Description' }
>

You can use the REPL to evaluate any variable that is in scope.

To exit the REPL, enter Ctrl+c.

Entering c instructs the running program to continue and create the new shopping list.

Create a watch expression for the Node debugging client

As you’ve seen, inspecting variable values involves a few steps:

  1. Enter the REPL.
  2. Evaluate the variable.
  3. Exit the REPL.
  4. Continue the program.
  5. Repeat each time the program breaks.

If you know you’ll be breaking on the same line of code again and again, there’s no point repeating those steps each time. Instead, you can set a watch expression.

As an example, let’s say you want to see the requestBody, req.body, req.params, and req.path HTTP request properties when the debugger breaks on line 57 of rest-controller.js. In this case, you would enter them one at a time at the debug> prompt.

Go ahead and exit the debugger, then restart with the node inspect ./bin/www command. When the debugger stops on the first line, enter:

debug> watch('requestBody')
debug> watch('req.body')
debug> watch('req.params')
debug> watch('req.path')

Now go to the application’s home screen and click the New Shopping List link. Create a shopping list called Sponge Bob (or something else, if you like), then click Create. The program will break in the create() function on the line that makes the call to the DAO. The output should look something like this:

break in controllers/rest-controller.js:57
Watchers:
  0: requestBody = { description: 'Sponge Bob' }
  1: req.body = { description: 'Sponge Bob' }
  2: req.params = {  }
  3: req.path = '/lists'

 52  * @param {Object} next - the next middleware function in the req/res cycle
 53  */
 54 function create(req, res, next) {
 55     let requestBody = req.body;
 56
>57     listsDao.create(requestBody.description).then((result) => {
 58         utils.writeServerJsonResponse(res, result.data, result.statusCode);
 59     }).catch((err) => {
 60         next(err);
 61     });
 62 }
debug>

Each time the program breaks, all of your watch expressions (called watchers) are displayed just before the code. (Any other watch expressions that are out of scope will cause a ReferenceError.)

debug> watch('no_such_variable')
break in controllers/rest-controller.js:57
Watchers:
  0: requestBody = { description: 'Foo' }
  1: req.body = { description: 'Foo' }
  2: req.params = {  }
  3: req.path = '/lists'
  4: no_such_variable =
    ReferenceError: no_such_variable is not defined
        at eval (eval at create (/Users/sperry/home/development/projects/IBM-Developer/Node.js/Course/Unit-12/controllers/rest-controller.js:57:5), <anonymous>:1:1)
        at create (/Users/sperry/home/development/projects/IBM-Developer/Node.js/Course/Unit-12/controllers/rest-controller.js:57:5)
        at Layer.handle [as handle_request] (/Users/sperry/home/development/projects/IBM-Developer/Node.js/Course/Unit-12/node_modules/express/lib/router/layer.js:95:5)
        at next (/Users/sperry/home/development/projects/IBM-Developer/Node.js/Course/Unit-12/node_modules/express/lib/router/route.js:137:13)
        at Route.dispatch (/Users/sperry/home/development/projects/IBM-Developer/Node.js/Course/Unit-12/node_modules/express/lib/router/route.js:112:3)
        at Layer.handle [as handle_request] (/Users/sperry/home/development/projects/IBM-Developer/Node.js/Course/Unit-12/node_modules/express/lib/router/layer.js:95:5)
        at /Users/sperry/home/development/projects/IBM-Developer/Node.js/Course/Unit-12/node_modules/express/lib/router/index.js:281:22
        at Function.process_params (/Users/sperry/home/development/projects/IBM-Developer/Node.js/Course/Unit-12/node_modules/express/lib/router/index.js:335:12)
        at next (/Users/sperry/home/development/projects/IBM-Developer/Node.js/Course/Unit-12/node_modules/express/lib/router/index.js:275:10)
        at Function.handle (/Users/sperry/home/development/projects/IBM-Developer/Node.js/Course/Unit-12/node_modules/express/lib/router/index.js:174:3)

 52  * @param {Object} next - the next middleware function in the req/res cycle
 53  */
 54 function create(req, res, next) {
 55     let requestBody = req.body;
 56
>57     listsDao.create(requestBody.description).then((result) => {
 58         utils.writeServerJsonResponse(res, result.data, result.statusCode);
 59     }).catch((err) => {
 60         next(err);
 61     });
 62 }
debug>

Alter variable values in the Node debugger client

With the debugger stopped on line 57 of rest-controller.js, your next task is to change the value you entered in the UI from Sponge Bob to Patrick (or whatever name you prefer). To do this, you enter the REPL and make the assignment. The output will look something like this (it’s cropped but you get the idea):

debug> c
debug> watch('req.body')
debug> watch('req.params')
debug> watch('req.path')
break in controllers/rest-controller.js:57
Watchers:
  0: req.body = { description: 'Sponge Bob' }
  1: req.params = {  }
  2: req.path = '/lists'

 52  * @param {Object} next - the next middleware function in the req/res cycle
 53  */
 54 function create(req, res, next) {
 55     let requestBody = req.body;
 56
>57     listsDao.create(requestBody.description).then((result) => {
 58         utils.writeServerJsonResponse(res, result.data, result.statusCode);
 59     }).catch((err) => {
 60         next(err);
 61     });
 62 }
debug> repl
Press Ctrl + C to leave debug repl
> requestBody.description = 'Patrick'
'Patrick'
debug> c

After you alter the description in the REPL, but before you make the call to the listsDao (which actually creates the shopping list), the name of the shopping list is reset, in this case to Patrick:

New Shopping List with altered name

Figure 1. The Shopping List application showing the description variable modified inside the debugger

That’s it for this quick introduction to Node debugging client. See the documentation to learn more about this tool.

Debugger #2: Chrome DevTools

Node.js uses the Chrome V8 engine to run JavaScript code, so it shouldn’t be a surprise that Chrome DevTools is also baked into Node.

We’ll follow the same process with Chrome DevTools that we did with the Node debugging client. Note that you must have a Chrome browser installed on your computer to use Chrome DevTools.

Run Chrome DevTools

To set up your Node application to use Chrome DevTools, just pass the --inspect flag to Node when you start your application: node --inspect node_module.

Now navigate to the Unit-12 directory, and make sure mongod is running (npm run start-mongod). In a separate terminal window, run node --inspect ./www/bin. The output will look like this:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-12 sperry$ node --inspect ./bin/www
Debugger listening on ws://127.0.0.1:9229/47508047-5864-4192-b05a-fbb3a914a352
For help, see: https://nodejs.org/en/docs/inspector
[2018-08-12T14:40:41.061] [INFO] default - 1534102841060:INFO: lists-dao-mongogb.getDbConnection(): Initializing MongoDB connection...
[2018-08-12T14:40:41.074] [INFO] default - 1534102841074:INFO: items-dao-mongogb.getDbConnection(): Initializing MongoDB connection...
(node:30100) DeprecationWarning: current URL string parser is deprecated, and will be removed in a future version. To use the new parser, pass option { useNewUrlParser: true } to MongoClient.connect.
[2018-08-12T14:40:41.092] [INFO] default - 1534102841092:INFO: lists-dao-mongogb.getDbConnection(): MongoDB connection initialized.
[2018-08-12T14:40:41.093] [INFO] default - 1534102841093:INFO: items-dao-mongogb.getDbConnection(): MongoDB connection initialized.

For security reasons, the debugger listens to IP address 127.0.0.1 and port 9229 by default.

To access the DevTools UI, open Chrome and type about:inspect in the address bar. You’ll see a screen that looks like Figure 2.

Accessing the Chrome DevTools UI

Figure 2. Accessing the Chrome DevTools UI

To open the DevTools UI, click on either Open dedicated DevTools for Node or the inspect links. You’ll see a screen that looks like Figure 3.

The Chrome DevTools UI

Figure 3. The Chrome DevTools UI

Set a breakpoint in Chrome DevTools

In the left corner of the DevTools console, click the Sources tab, followed by the Node tab. Under that, expand the file:// node of the tree to see your source code.

Continue to expand the source tree until you see the controllers directory. Open rest-controller.js, which will appear in the editor window in the middle of the UI.

To set the breakpoint, scroll down to line 57 and click on the line number gutter. The breakpoint appears as a small arrow in the editor window. It also shows in the Breakpoints panel on the lower righthand side of the UI, as shown in Figure 4.

Set breakpoint snippet

Figure 4. Setting a breakpoint in the DevTools UI

To unset the breakpoint, click again in the line number gutter, which acts as a toggle.

Chrome DevTools provides the same basic navigation as the Node debugger client, but as a set of buttons on the debugger. These are located in the upper right side of the UI, as shown in Figure 5.

DevTools debugger navigation buttons

Figure 5. DevTools debugger navigation buttons

From left to right, the buttons are:

  • Pause/Resume (F8): Pause or resume program execution.
  • Step over (F10). Execute the current line of code and stop on the next line in the same block.
  • Step into (F11): Step into the current line of code and stop on the next line of code within the line.
  • Step out (Shift + F11): Step out of the current function to the previous line of code in the call stack.
  • Stop (F9): Execute the current line of code and stop on the next line.

Inspect variable values in Chrome DevTools

When DevTools stops on a breakpoint, you can inspect variable values. To do this, you look in the debugger’s Scope panel.

Open a browser and go to the Shopping List application http://localhost:3000, and click the New Shopping List link. Enter the description Another Test List and click Create.

Execution breaks on line 57 of rest-controller.js. Now let’s say you want to see the value of the req.body object. To do this, expand the Scope tab followed by the req variable:

The `req.body` object

Figure 6. Inspecting the req.body.description variable in the DevTools UI

After you’ve examined the req variable, click the resume button (or F8), and let the program create the new shopping list.

Create a watch expression in Chrome DevTools

Locating variables in the Scope pane can be time consuming, especially because the variables you want are not always at the top of the list. If you know you’ll be stopping on the same breakpoint again and again, it makes sense to put a watch expression on the variables you want to check.

To add a watch expression, expand the Watch pane and click the plus (+) button in the top right corner.

For this example, type requestBody and press Enter. Go ahead and add req.params and req.path, as well.

While the program is running, the new watch expressions display as <not available> because the variables are not in scope. But when the program breaks on line 57 in rest-controller.js, the variables will be in scope, and their values will be displayed.

To test this out, create a new shopping list and name it Yet Another List, then click the Create button. When the program stops on the breakpoint you’ve set, you should see your watch expressions in the DevTools UI. (Note that you will need to expand the watch expressions to see them all.)

Watch expressions

Figure 7. Watch expressions in the DevTools UI

Alter variable values in Chrome DevTools

To modify the value of a variable, double-click on it in either the Scope panel or the Watch panel, give it a new value, and press Enter.

Modify the requestBody.description property, and give it a value of NOT Yet Another List, and press Enter. Then click the resume button or F8.

The list will not display Yet Another List (the value you initially set in the Shopping List UI), but rather the new value you’ve just assigned, as shown in Figure 8.

Modify the value of a watch expression

Figure 8. The Shopping List application showing the modified description variable

To learn more about Chrome DevTools, see its documentation.

Debugger #3: VSCode

I briefly introduced VSCode in Unit 6, so you should already be somewhat familiar with this debugging tool. We’ll follow the same source-level debugging process with VSCode that we’ve used with the other two tools. This time I’ll also show you how to set up multiple launch configurations.

Setting up a launcher with multiple configurations makes it easier to debug more than one program within the same project. This will be handy for the Shopping List application project, which consists of three programs:

  • Data loader (./utils/load-mongodb.js)
  • Functional test (./test/test-rest-services.js)
  • Shopping List application (./bin/www)

Set up a program launcher

To set up a launcher with multiple configurations, click the Debug tab on the left side of the VSCode IDE.

Launch configurations are stored in the (workspace-relative) .vscode/launch.json file. We’ll create one for each program in the Shopping List application project, starting with the functional test program.

Expand the dropdown list beside the run button, which is the triangle shown in Figure 9.

New Configuration

Figure 9. Add a new launch configuration

Choose the Add Configuration… option from the dropdown list. VSCode creates the launch.json file and opens it in the editor.

Replace the boilerplate code in launch.json with this:

{
    "version": "0.2.0",
    "configurations": [        {
            "type": "node",
            "request": "launch",
            "name": "Functional Tests",
            "program": "${workspaceFolder}/node_modules/mocha/bin/_mocha",
            "args": [
                "-u",
                "tdd",
                "--timeout",
                "999999",
                "--colors",
                "${workspaceFolder}/test/test-rest-services"
            ],
            "internalConsoleOptions": "openOnSessionStart"
        }
}

Save your changes. You should now see that the Run Mocha Tests option is selected. (The first entry in the list will always be the default choice.)

  • The configuration type for Node.js programs is always node.
  • The name should be something descriptive that you’ll recognize in the dropdown list.
  • The program is the workspace-relative path to the Node program you want to run.

In this case, the path doesn’t lead directly to your functional tests (./test/test-rest-services), but to the Mocha.js main module. On this module, you provide several arguments documented here, including the Mocha test(s) to run.

To run the Mocha tests, just select Functional Tests and click the triangle to run this program. Output from the tests appears in VSCode’s debug console, as shown in Figure 10.

VSCode after running functional test

Figure 10. Output from running the Functional Tests launcher in the VSCode debugger

Running Mocha tests

If you’ve tried to run Mocha tests using Node directly (rather than running the npm test script) you’ve probably seen an error like this one:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-12 sperry$ node ./test/test-rest-services.js
/Users/sperry/home/development/projects/IBM-Developer/Node.js/Course/Unit-12/test/test-rest-services.js:65
before(function(done) {
^

TypeError: before is not a function
.
.

You get this error because Mocha is meant to be run using the mocha module, and not directly from Node. VSCode knows this.

Complete the launcher

The Functional Tests launch configuration will be useful for debugging the Shopping List application’s functional tests. Next we’ll add configurations for the data loader program and the Shopping List application itself.

To start, click on the launch drop-down and choose Add Configuration, then select {} Node.js: Launch Program from the floating dropdown. Replace the entire code block with this:

        {
            "type": "node",
            "request": "launch",
            "name": "Data Loader",
            "program": "${workspaceFolder}/utils/load-mongodb.js"
        }

Follow the same process to add a launcher for the Shopping List application: choose Add Configuration, then {} Node.js: Launch Program. Replace the code with this:

      {
          "type": "node",
          "request": "launch",
          "name": "Run Shopping List",
          "program": "${workspaceFolder}/bin/www"
      }

The completed launch.json file should look like Listing 1.

Listing 1. The complete VSCode launch configuration (launch.json)

{
    "version": "0.2.0",
    "configurations": [
        {
            "type": "node",
            "request": "launch",
            "name": "Functional Tests",
            "program": "${workspaceFolder}/node_modules/mocha/bin/_mocha",
            "args": [
                "-u",
                "tdd",
                "--timeout",
                "999999",
                "--colors",
                "${workspaceFolder}/test/test-rest-services"
            ],
            "internalConsoleOptions": "openOnSessionStart"
        },
        {
            "type": "node",
            "request": "launch",
            "name": "Data Loader",
            "program": "${workspaceFolder}/utils/load-mongodb.js"
        },
        {
            "type": "node",
            "request": "launch",
            "name": "Run Shopping List",
            "program": "${workspaceFolder}/bin/www"
      },
  ]
}

We’ve set up a launcher with three program configurations. Next we’ll go through the usual source-level debugging process.

Set a breakpoint in VSCode

Open rest-controller.js, then click in the line number gutter just to the left of the source to set a breakpoint, which will appear as a small dot.

Set a breakpoint in VSCode

Figure 11. Set a breakpoint in VSCode

To remove the breakpoint, click in the line number gutter, which acts as a toggle.

VSCode provides the usual navigation options, which should be familiar by now:

Navigation buttons in VSCode

Figure 12. VSCode debugger navigation buttons

From left to right:

  • Pause/Resume (F5)
  • Step over (F10)
  • Step into (F11)
  • Step out (Shift+F11)
  • Restart (Shift+Cmd+F5)
  • Stop (Shift+F5)

Inspect variable values in VSCode

If you still have the Shopping List application running in the terminal window from the last section, shut it down now (Ctrl+c) to avoid a port conflict.

Next, choose the Run Shopping List launch configuration to start the debugger.

Create a new shopping list in the UI and call it Foo.

When the debugger stops on a breakpoint, you can see variable values in the VARIABLES pane, near the top left side of the IDE.

Inspect variables in the VARIABLES pane in VSCode

Figure 13. The VARIABLES and WATCH panes in the VSCode debugger tab

Create a watch expression in VSCode

To create a watch expression click the plus button (+) in the WATCH pane, enter the expressions you want to watch, and press Enter.

Now whenever the debugger stops on a breakpoint, values for all expressions that are in scope will display in the WATCH pane. (See Figure 13.)

Alter variable values in VSCode

In VSCode, you have to change the value of a live variable in the VARIABLES pane.

Locate the requestBody property, expand it, and double-click its description property. Change this property to bar and press Enter. Press F5 to tell the debugger to resume execution.

To learn more about debugging with VSCode, be sure to check out its documentation.

Performance profiling

Even if your code is bug free and functioning correctly, performance may still be an issue. As a professional Node developer, you need to know how to profile your code for “hotspots” so you can tune it to perform optimally.

In Unit 4 you learned how to run the V8 profiler. While V8 isn’t exactly user friendly, it’s one of Node’s out-of-the-box tools, so it’s important to be familiar with it. Fortunately, the Node ecosystem includes many other profilers to explore. When choosing a profiler, look for these qualities:

  • Easy setup: A few quick npm installs should do it. You should also be able to start the profiler with a simple command or a flag passed to the Node runtime.

  • Integration with the load testing tool of your choice: Load testing is the name of the game for application performance, so make sure your profiler integrates well with one or more of these tools. Personally, I like Apache Bench and loadtest.

  • Graphical output: You’ve seen the V8 profiler, and that output is not for the faint of heart. A good profiler should provide visual tools (like charts and graphs) to help you spot performance bottlenecks.

The Node ecosystem includes lots of profiling utilities, and I encourage you to explore your options. For this unit, I introduce you to clinic.

Setup

I recommend installing clinic globally. Open a terminal window and enter this command:

npm install -g clinic

To verify the installation, run clinic with the -v option and you should see output like this:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-12 sperry$ clinic -v
v1.0.3

Next we run clinic and use it to profile the Shopping List application.

Profile and load test your application (clinic doctor)

As a profiling utility, clinic “wraps” a Node process to collect information about how it runs. This utility has a number of profiling tools, and I’ll show you two of them:

  • clinic doctor diagnoses Node application performance issues and makes recommendations.
  • clinic bubbleprof analyzes asynchronous delays in your Node application and produces a visual bubble map of those delays.

To start, run clinic doctor -- node ./bin/www from the Unit-12 directory (just make sure mongod is running, or Node will crash):

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-12 sperry$ clinic doctor -- node ./bin/www
[2018-08-13T08:36:04.519] [INFO] default - 1534167364519:INFO: lists-dao-mongogb.getDbConnection(): Initializing MongoDB connection...
[2018-08-13T08:36:04.532] [INFO] default - 1534167364532:INFO: items-dao-mongogb.getDbConnection(): Initializing MongoDB connection...
[2018-08-13T08:36:04.550] [INFO] default - 1534167364550:INFO: lists-dao-mongogb.getDbConnection(): MongoDB connection initialized.
[2018-08-13T08:36:04.552] [INFO] default - 1534167364552:INFO: items-dao-mongogb.getDbConnection(): MongoDB connection initialized.

Next, use Apache Bench to stress test the application. For this example we stress test the Shopping List’s item-search REST service:

Ix:~ sperry$ ab -n 100 -c 10 -m GET 'http://localhost:3000/rest/items?description=free%20range'
This is ApacheBench, Version 2.3 <$Revision: 1826891 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, https://www.apache.org/

Benchmarking localhost (be patient).....done


Server Software:
Server Hostname:        localhost
Server Port:            3000

Document Path:          /rest/items?description=free%20range
Document Length:        2901 bytes

Concurrency Level:      10
Time taken for tests:   4.414 seconds
Complete requests:      100
Failed requests:        0
Total transferred:      311100 bytes
HTML transferred:       290100 bytes
Requests per second:    22.66 [#/sec] (mean)
Time per request:       441.401 [ms] (mean)
Time per request:       44.140 [ms] (mean, across all concurrent requests)
Transfer rate:          68.83 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:   155  405  72.1    415     519
Waiting:      155  405  72.1    415     519
Total:        156  406  72.0    415     519

Percentage of the requests served within a certain time (ms)
  50%    415
  66%    431
  75%    452
  80%    459
  90%    484
  95%    504
  98%    519
  99%    519
 100%    519 (longest request)

When you stop the process running clinic doctor, the utility analyzes the output and opens it in a browser.

clinic doctor HTML output

Figure 14. Clinic doctor HTML output

As you can see, clinic doctor has detected a potential CPU issue, which we’ll come back to shortly.

You might also notice there’s a delay before the CPU usage, and then the active handle count starts to go up. That’s because we started clinic doctor, then a few seconds later ran Apache Bench.

You can use the --on-port option to integrate the two tools. Just start clinic doctor and tell it to run Apache Bench (or another load test tool) as soon as the application starts listening on a port:

clinic doctor --on-port="ab -n 100 -c 10 -m GET 'http://localhost:3000/rest/items?description=free%20range'" -- node ./bin/www

As soon as the load test tool finishes, clinic doctor analyzes the data, leaving you with a purer performance sample. Here’s the console output:

Ix:~/src/projects/IBM-Developer/Node.js/Course/Unit-12 sperry$ clinic doctor --on-port="ab -n 100 -c 10 -m GET 'http://localhost:3000/rest/items?description=free%20range'" -- node ./bin/www
[2018-08-13T08:54:42.589] [INFO] default - 1534168482589:INFO: lists-dao-mongogb.getDbConnection(): Initializing MongoDB connection...
[2018-08-13T08:54:42.601] [INFO] default - 1534168482601:INFO: items-dao-mongogb.getDbConnection(): Initializing MongoDB connection...
[2018-08-13T08:54:42.629] [INFO] default - 1534168482629:INFO: items-dao-mongogb.getDbConnection(): MongoDB connection initialized.
[2018-08-13T08:54:42.630] [INFO] default - 1534168482630:INFO: lists-dao-mongogb.getDbConnection(): MongoDB connection initialized.
This is ApacheBench, Version 2.3 <$Revision: 1826891 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, https://www.apache.org/

Benchmarking localhost (be patient).....done


Server Software:
Server Hostname:        localhost
Server Port:            3000

Document Path:          /rest/items?description=free%20range
Document Length:        2901 bytes

Concurrency Level:      10
Time taken for tests:   4.347 seconds
Complete requests:      100
Failed requests:        0
Total transferred:      311100 bytes
HTML transferred:       290100 bytes
Requests per second:    23.00 [#/sec] (mean)
Time per request:       434.716 [ms] (mean)
Time per request:       43.472 [ms] (mean, across all concurrent requests)
Transfer rate:          69.89 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.1      0       1
Processing:   170  406  67.5    417     511
Waiting:      169  405  67.5    417     511
Total:        170  406  67.5    417     511

Percentage of the requests served within a certain time (ms)
  50%    417
  66%    442
  75%    447
  80%    456
  90%    486
  95%    499
  98%    509
  99%    511
 100%    511 (longest request)
Analysing data
Generated HTML file is 2107.clinic-doctor.html
You can use this command to upload it:
clinic upload 2107.clinic-doctor

The HTML generated by clinic doctor is automatically loaded into your default browser (for me, that’s Chrome):

clinic doctor HTML output

Figure 15. HTML output following integration with Apache bench

This time, the output contains only the data from the load test.

Analyze the output (clinic bubbleprof)

Data without analysis isn’t terribly useful. For instance, the CPU graph in Figure 15 looks about like we’d expect, yet clinic doctor says there’s a potential CPU usage issue. So what do we do now?

Fortunately, this is where we turn to bubbleprof. You can use this utility (or one like it) to visualize delays in asynchronous operations.

To use bubbleprof, change the doctor subcommand to bubbleprof and run the load test again, with this command:

clinic bubbleprof --on-port="ab -n 100 -c 10 -m GET 'http://localhost:3000/rest/items?description=free%20range'" -- node ./bin/www

The bubbleprof analyzer runs and produces a graph that looks like Figure 16 (note that this screenshot is from the bubbleprof profiling demo at ClinicJS.org.

clinic bubbleprof HTML output

Figure 16. Graphical output from bubbleprof

The visualizer shows three bubbles, which you can use to locate performance bottlenecks in your code:

  • The application under profile (Userland, in this case)
  • Third-party dependencies
  • Node core

That’s it for this quick demo, but I encourage you to work through the profiling exercise and video below to build on what you’ve learned.

Profiling exercise

As an exercise, run the clinic profiler against the Unit-11 code. Compare that profile to the code from Unit-12 and see if you can spot any differences.

  1. What’s the main difference between the versions of the Shopping List application in Unit 11 and Unit 12?
  2. Do you spot any potential performance issues from running the functional tests? (Hint: Run them and see what Mocha says about the GET /rest/items?description=Free Range test.)
  3. What might you do to make MongoDB perform better? (Hint: Check Unit-11/scripts/item.sql for a clue.)

Sorry, but as in life, there is no answer key for this section.

Conclusion to Unit 13

In this unit you’ve learned how to do source-level debugging, which is a technique for when simply studying your code and checking the logs isn’t enough. Source-level debugging can be tedious, but there’s simply no substitute for it.

You got to know three different tools for source-level debugging:

  • Node debugger client
  • Chrome DevTools
  • VSCode

Debugging is only half of the code quality equation, so I also showed you what to look for in a good performance profiler. Then you ran through a quick load testing and analysis demo using clinic and its tools, doctor and bubbleprof.

You should now have a good feeling for how to use a source-level debugger. You should also know what to look for in a profiling tool. Check out the video below for more step-by-step guidance to:

  • Setting up VSCode for source-level debugging.
  • Using clinic and its tools to find performance bottlenecks.

Video