Debugging Node.js

class: title
# Debugging Node.js

![Great Indian Developer Summit](img/GIDSLogo.jpg)

## Sequoia McDowell

.small-list[
* 🌐  http://sequoia.makes.software
* 🦆  @_sequoia
* 📧  sequoia.mcdowell@gmail.com
]

???

## Welcoming to debugging Node.js!

* I'm Sequoia, find me online at x, y, z
* I've been writing Node.js since v0.3
* Come a long way since then
* Worked in Java for a bit
  * Code hinting
  * Step thru debugging
  * Robust logging
  * *Missed this when I returned to node*

→ Going to talk about how to do this stuff in node.js

---
class: biglist

# Agenda

* General Debugging Tips
--

* Logging
???
----
* enabling & disabling logs
* writing to other log systems
--

* Step-Through Debugging
???
----
* step through debugging
* Breakpoints
--

* Advanced Debugging
???
----
* CPU analysis
* Tracking timing from browser
* heap dump analysis

---

# Debugging Tips

1. Throw `Error` Objects
2. Name Functions
3. Use Assert

---

## ℹ️ Throw `Error` Objects

### ❌

```js
try{
  throw "something went wrong!";
}catch(e){
  console.error(e.stack); // undefined!! :(
}
```

???
* no stack

"A JavaScript **exception** is a **value that is thrown** as a result of an invalid operation or as the target of a throw statement. While it is not required that these values are instances of Error or classes which inherit from Error, **all exceptions thrown by Node.js or the JavaScript runtime will be instances of Error**."

### ✅

```js
try{
 throw new Error('something went wrong!');
}catch(e){
 console.error(e.stack); 
} 
// Error: something went wrong!
// at Object.<anonymous> (/Users/sequoia/tmp/test-app/app.js:16:11)
// at Module._compile (module.js:541:32)
// ...
```

???
* With stack trace!

---

## ℹ️ Name Functions

### ❌ Anonymous Functions
```js
db.connect(config, function(connection){ /*...*/})
connection.findAll(function(results){ /*...*/})
fs.read(filename, function(err, results){ /*...*/})
```

### ❌ Anonymous Functions
```no-highlight
Uncaught TypeError: Cannot read property 'name' of undefined
  getUser              @ foo.js:2
  (anonymous function) @ bar.js:71
  (anonymous function) @ bar.js:202
  (anonymous function) @ baz.js:11
  ...
```

---

## ℹ️ Name Functions

### ✅ Named Functions
```js
db.connect(config, function dbReady(connection){ /*...*/})
Users.findAll(function handleResults(results){ /*...*/})
fs.read(filename, function processFiles(err, results){ /*...*/})
```

### ✅ Named Functions
```no-highlight
Uncaught Error:
 getUser @ foo.js:2
 getItem @ bar.js:71
 buildDBQuery @ bar.js:202
 createDatabase @ baz.js:11
 ...
```

---

## ℹ️  Use `assert`

### ❌

```js
if(!cfg.host){
  throw new Error('host must be set');
}
if(typeof cfg.port !== 'number'){
  throw new Error('port must be a number');
}
```

--
### ✅

```js
const assert = require('assert');

assert(cfg.host, 'host must be set');
assert.equal(typeof cfg.port, 'number', 'port must be a number');
```

???

* Like asserts in java!
* Makes error with stack trace + optional message

---

# Console Logging

```js
console.log('looking up user {id: %s}', id);
db.Users.find({id: id}, function(e, user){
  console.log('found user %s: %s', user.id, user.name);
})
```
```js
app.get('/posts/:id', function showPost(req, res){
  console.log('post %s requested', req.params.id);
})
app.get('/users/:id', function showUser(req, res){
  console.log('user %s requested', req.params.id);
})
```
```js
db.on('query', function(query){
  console.log('querying database: %s', query.query);
})
```

???

While you're working you add console statements like this

---

# Console Logging

```js
//...
db.Users.find({id: id}, function(e, user){
  //...
})
```
```js
app.get('/posts/:id', function handleIndex(req, res){
  //...
})
app.get('/users/:id', function handleIndex(req, res){
  //...
})
```
```js
db.on('query', function(query){
  //...
})
```

???
Then you stop working on that stuff so you delete your console.log statements

---

# Console Logging

```js
//console.log('looking up user {id: %s}', id);
db.Users.find({id: id}, function(e, user){
  //console.log('found user %s: %s', user.id, user.name);
})
```
```js
app.get('/posts/:id', function handleIndex(req, res){
  //console.log('post %s requested', req.params.id);
})
app.get('/users/:id', function handleIndex(req, res){
  //console.log('user %s requested', req.params.id);
})
```
```js
db.on('query', function(query){
  //console.log('querying database: %s', query.query);
})
```

*"There's got to be a better way!"*

???
But later you need them, so you add them back

this time you just **comment them out**

→ There's got to be a better way!

---

# The `debug` module

```no-highlight
$ npm install --save debug
```

```js
const debug = require('debug');
const log = debug('my-app');
```

```js
log('test');

setTimeout(function(){
  log('user: %j', { id: 12, name: 'Qian' });
}, 500)
```

----

<pre class="ansi2html">
bash-3.2$ node script.js
</pre>

----

<pre class="ansi2html">
bash-3.2$ DEBUG=* node script.js
--

my-app test +0ms
 my-app user: {"id":12,"name":"Qian"} +503ms
</pre>

???

one of the first things I install on a new project

**Note the environmental variable**

---

## Using `debug`

```js
log('looking up user {id: %s}', id);
db.Users.find({id: id}, function(e, user){
  log('found user %s: %s', user.id, user.name);
})
```
```js
app.get('/posts/:id', function handleIndex(req, res){
  log('post %s requested', req.params.id);
})
//...
```
--

<pre class="ansi2html">
bash-3.2$ DEBUG=my-app node script.js
--

my-app looking up user {id: 123} +96ms
 my-app querying database: SELECT * FROM `Users` WHERE `User.id`=123 +6ms
 my-app found user 123: Naomi +108ms
 my-app post best-frameworks-2017 requested +43ms
 my-app querying database: SELECT * FROM `Posts` WHERE `Post.slug`="best-frameworks-2017";+22ms

 my-app user: {"id":12,"name":"Naomi"} +225ms
</pre>

???

* Note timings: time since **last call**
  * `108ms` is time between logging "querying db" and getting result
* Whole application verbose-mode
* We can do better!
* → **Per-section** debugging

---

```js
const dbLog = debug('my-app:database');
const routeLog = debug('my-app:routes');
const userLog = debug('my-app:users');
```
--
```js
db.Users.find({id: id}, function(e, user){
*  userLog('found user %s: %s', user.id, user.name);
})
app.get('/posts/:id', function handleIndex(req, res){
*  routeLog('post %s requested', req.params.id);
})
db.on('query', function(query){
*  dbLog('querying database: %s', query.query);
})
```

<pre class="ansi2html">
bash-3.2$ DEBUG=my-app:* node script.js 
--

my-app:routes user 123 requested +0ms
 my-app:users looking up user {id: 123} +97ms
 my-app:database querying database: SELECT * FROM `Users` WHERE `User.id`=123 +7ms
 my-app:users found user 123: Naomi +109ms
 my-app:routes post best-frameworks-2017 requested +43ms
 my-app:database querying database: SELECT * FROM `Posts` WHERE `Post.slug`="best-frameworks-2017"; +18ms
</pre>

???
What if you're only debugging the Database?

---

### Just Database Logger

<pre class="ansi2html">
bash-3.2$ DEBUG=my-app:database node script.js 
 my-app:database querying database: SELECT * FROM `Users` WHERE `User.id`=123 +7ms
 my-app:database querying database: SELECT * FROM `Posts` WHERE `Post.slug`="best-frameworks-2017"; +18ms
</pre>

### Users + Routes

<pre class="ansi2html">
bash-3.2$ DEBUG=my-app:users,my-app:routes node script.js 
 my-app:routes user 123 requested +0ms
 my-app:users looking up user {id: 123} +97ms
 my-app:users found user 123: Naomi +109ms
 my-app:routes post best-frameworks-2017 requested +43ms
</pre>

???

Comma separated

### Everything *but* database

<pre class="ansi2html">
bash-3.2$ DEBUG=my-app:*,-my-app:database node script.js 
 my-app:routes user 123 requested +0ms
 my-app:users looking up user {id: 123} +97ms
 my-app:users found user 123: Naomi +109ms
 my-app:routes post best-frameworks-2017 requested +43ms
</pre>

???

Minus to omit

---

## `debug` is widely used
<pre class="ansi2html">
bash-3.2$ DEBUG=* node script.js 
--

express:application set "x-powered-by" to true +0ms
 express:application set "etag" to 'weak' +3ms

express:router use / query +1ms
 express:router:layer new / +1ms
 express:router use / expressInit +0ms
 express:router:layer new / +1ms

express:router:route new / +0ms
 express:router:layer new / +1ms
 express:router:route get / +0ms
 express:router:layer new / +0ms

app:info listening on 3030 +7ms
 express:router dispatching GET /restaurants/1 +4s
 sqlLib:query Executing (default): SELECT `Restaurant`.`id`, `Restaurant`.`name`, `Restaurant`.`founded`, `Restaurant`.`createdAt`, `Restaurant`.`updatedAt`, `Dishes`.`id` AS `Dishes.id`, `Dishes`.`name` AS `Dishes.name`, `Dishes`.`spicy` AS `Dishes.spicy`, `Dishes`.`createdAt` AS `Dishes.createdAt`, `Dishes`.`updatedAt` AS `Dishes.updatedAt`, `Dishes`.`RestaurantId` AS `Dishes.RestaurantId` FROM `Restaurants` AS `Restaurant` LEFT OUTER JOIN `Dishes` AS `Dishes` ON `Restaurant`.`id` = `Dishes`.`RestaurantId` WHERE `Restaurant`.`id` = '1'; +4s
 app:info Restaurant Found: "Giotto's" +2ms
 express:view lookup "restaurant_detail.jade" +198ms
 express:view stat "/Users/sequoia/templates/restaurant_detail.jade" +0ms
 express:view render "/Users/sequoia/templates/restaurant_detail.jade" +0ms
</pre>

???

Turn on debugger and see what you get!

* Can also use of course app:\*,express:\* etc.

→ This is a node talk but as a side-note: `debug` also works in the browser!

---

## `debug` in The Browser

![debug module used in the browser](img/debug_browser.gif);

---

## More Robust Logging: `winston`

<http://github.com/winstonjs/winston>

--
.biglist[
* Log levels
* Multiple Transports
* Formatting plugins
]

???

* Sometimes you want more robust logging, log levels, external transports etc.
* Winston!

---

## Winston

```no-highlight
npm install winston
```

```js
var winston = require('winston');
```

```js
winston.log('info', 'Hello distributed log files!');
winston.log('debug','Here is some extra detailed info');

//shorthands:

winston.info('Hello again distributed logs');
winston.debug('Here is more info');
```

### Console Output

```no-highlight
info: Hello distributed log files!
info: Hello again distributed logs
```

???

No debug! Log levels

---

## Log Levels

.small-list[
* 0: error
* 1: warn
* 2: info
* 3: verbose
* 4: debug
* 5: silly
]

???
Reports current level **and below**

```js
winston.level = 'info';
winston.level = 'debug';
```

```js
winston.level = process.env.LOGLEVEL;
```

```no-highlight
$ LOGLEVEL=info node app.js
```

???
* Set log level
* set programatically

---

## Winston "Transports"

Extensions that send log messages somewhere.

```js
winston.add(winston.transports.File, { filename: 'somefile.log' });
winston.remove(winston.transports.Console);
```

???
Example: disabling Console & enabling File

## Built in Transports

* Console
* File
* HTTP

???

---

## Additional Winston Transports

.small-list[
* Syslog
* Loggly
* MongoDB
* Redis
* Riak
* Elasticsearch
* SimpleDB
* Mail
* Amazon Kinesis Firehose
* Graylog2
* and many more...
]

----
```no-highlight
$ npm search winston
winston-amon         Winston transport for Amon logging                            =zoramite
winston-amqp         An AMQP transport for winston                                 =kr1sp1n
winston-cassandra    A Cassandra transport for winston                             =jorgebay
winston-couchdb      a couchdb transport for winston                               =alz
winston-express      Express middleware to let you use winston from the browser.   =regality
winston-graylog2     A graylog2 transport for winston                              =smithclay
winston-hbase        A HBase transport for winston                                 =ddude
winston-loggly       A Loggly transport for winston                                =indexzero
winston-mail         A mail transport for winston                                  =wavded
winston-mail2        A mail transport for winston                                  =ivolo
winston-mongodb      A MongoDB transport for winston                               =indexzero
...
```

---

# Interactive Debugging

???

This is something common in Java, .Net, and other worlds, but unfamiliar to many JS devs. **this should change!!**

I will explain how to do this and explain what an I.D. does generally, so if you're familiar with it this will be some review

* inspect or alter application state
* see the code execution path ("call stack") that lead to the currently executing line of code, and
* inspect the application state at earlier points on that path

Debuggers are useful when writing your own, original code, but they really show their value when you're working with an unfamiliar codebase. Being able to step through the code execution line by line and function by function can save hours of poring over source code, trying to step through it in your head.

--
class:biglist
* Built-in Debugger
* Chrome Debugger
* IDE Debugger

---

## Node Built-in Debugger

<pre class="ansi2html">
bash-3.2$ node debug bin/www
</pre>
???
* start the debugger with `node debug` scriptname
--
<pre class="ansi2html">
< Debugger listening on [::]:5858
connecting to 127.0.0.1:5858 ... ok
break in bin/www:7
 5 */
 6 
> 7 var app = require('../app');
 8 var debug = require('debug')('test-app:server');
 9 var http = require('http');
</pre>
???
* breaks on first line
* `n` to go to next line
--
<pre class="ansi2html">
n
</pre>
--
<pre class="ansi2html">
break in bin/www:8
 6
 7 var app = require('../app');
> 8 var debug = require('debug')('test-app:server');
 9 var http = require('http');
 10
</pre>
???
let's try help
--
<pre class="ansi2html">
help
</pre>
--
<pre class="ansi2html">
Commands: run (r), cont (c), next (n), step (s), out (o), backtrace (bt), setBreakpoint (sb), clearBreakpoint (cb),
watch, unwatch, watchers, repl, exec, restart, kill, list, scripts, breakOnException, breakpoints, version
</pre>
???
let's continue
--
<pre class="ansi2html">
c
</pre>
--
<pre class="ansi2html">
< process 92507 listening on 3000
debug> .exit
</pre>
???
**That's enough of that**

→ VSCode

---

## Visual Studio Code

![vscode with debugger running](img/nodejs_debugsession.png)

---

class: biglist

## Visual Studio Code

* From Microsoft
* Written in JavaScript
* Based on Atom editor
* Free / Open Source

???

→ Let's look at setting up

---

## Setting Up The Project

```no-highlight
$ npm install express-generator -g
$ express test-app   # create an application
$ cd test-app        
$ npm install
```

--
```no-highlight
$ npm start
```
![Express homepage](img/express-start.png)

???

Start with a scaffolded express app

---

## Launching VSCode

```no-highlight
$ code .
```

???

From the app directory

--
![Newly opened VSCode](img/vscode-start.png)

---
class:biglist

## Ways to Debug from VS Code

1. Launch from shell and attach
2. Launch from VSCode

???

Either way works, the first is slightly less work

→ We'll start with method 1

---

## Creating Launch Configurations

![](img/vscode-no-launch-configs.png)

???

1. Click the debug icon
2. No configurations
3. →Click little gear icon

---

## Creating Launch Configurations
![](img/vscode-generate-launchconfig.png)
???
Presented with choices, select Node.js

---

## Creating Launch Configurations
![](img/vscode-default-launchconfig.png)
???
* Now there are two default launch configurations

---

## Default Launch Configurations

```no-highlight
test-app/.vscode/launch.json
```

```js
{
  "version": "0.2.0",
  "configurations": [
    {
      "type": "node",
      "request": "launch",
      "name": "Launch Program",
      "program": "${workspaceRoot}/bin/www"
    },
*   {
*     "type": "node",
*     "request": "attach",
*     "name": "Attach to Port",
*     "address": "localhost",
*     "port": 5858
*   }
  ]
}
```

???

* This will attach to a **running** application
* Node.js debugger has the ability to be steered by an external application

---

## Launch App & Attach

### 1. Launch with Debug *Server* Listening

<pre class="ansi2html">
$ node --debug bin/www
Debugger listening on [::]:5858
process 2377 listening on 3000
</pre>

???
Server portion is node.js, it's like the debugger from before but **listening for a controller to drive it** (set breakpoints etc.)

### 2. Attach Debugger *Client* (VSCode)

![](img/vscode-launch-attach.png)

???
Select "Attach to port" & click green arrow

---

## Launch App & Attach
![](img/vscode-debug-attach-started.png)

???
Now our debugger is running, note (what you'd expect in a debugger):

* Control bar on top
  * Pause execution
  * Step Over
  * Restart
  * Stop button (with a plug for "detach" because it doesn't actually stop the server)

---

## Set a Breakpoint
![Setting a breakpoint on index route](img/vscode-set-breakpoint.png)
???
When our homepage is requested, stop code execution

---

## Load Page in Browser
![Loading the page in the browser](img/load-localhost-3000-breakpoint.png)

???
Page won't actually load, just hangs

---

## Load Page in Browser
![Hit first Breakpoint, VS Code loaded](img/vscode-hit-first-breakpoint.png)

???

**Execution is now paused**

* Variables Pane:
  * Local variables
  * Request, Response, & Next objects (passed to function)
  * types: **Request is IncomingMessage**, response is ServerResponse. Useful!
  * **This is a big benefit of interactive debugging: discovering stuff you didn't know about your code**
* Watch Expressions
  * None yet
* Call Stack
* Breakpoints

→ Open the request object

---

## Inspecting Variables

![inspecting the request object](img/vscode-inspect-variables-request.png)

???

We opened the request object and if we scroll down

→ We can see...

---

## Inspecting Variables

![Request object: headers open](img/vscode-inspect-variables-request-2.png)

???

* **Incoming headers object** → Open this
* HTTP Method
* original URL
* etc.

Good way to discover what's available

→ Let's say our issue is in the rendering itself, now we can step into deps

---

## Stepping Through Code

![Click step into](img/vscode-step-into.png)

???

We want to debug the render function that's being called, so click **step into**

(*little arrow pointing down*)

(or F11)

**Step Into a function call**

---

## Stepping Through Code

![node_modules/express/lib/response.js](img/vscode-step-into-express-response.png)

???
* Stopped on line 938

**We want to see what gets assigned to `app`**, so

Let's let this line execute and stop on the next line

→ Step over

---

## Stepping Through Code

![step over button](img/vscode-step-over.png)

???

Click (little arc button)

(Or F10)

---

## Stepping Through Code

![step over button](img/vscode-stepped-over.png)

???
* Now stopped on line 939
* Step out works as you might expect: goes to return statement and breaks after exiting function

→ Let's look at editing variables in the value pane

---

## Editing Variables

???
If in the course of your work you find yourself testing by:

* change value
* restart script
* change value
* restart script...

You'll like this feature: edit variables in memory in a running application without restarting

→ We're stopped on line 929

![Mover hovered over VSCode variable "options.title"](img/vscode-edit-variable-express.png)

???

----

I've moused over the "options" object, options are the object passed to the template engine

Here you can see it has a `title` property: let's change that.

→ Double click it

---

## Editing Variables

![options.title open for editing](img/vscode-editing-variable-express.png)

???
Now edit (note quotes for string)

→ hit **Enter**

---

## Editing Variables

![Edited title](img/vscode-edited-variable-express.png)

???
Now string is replaced

→ Now I'm going to click →continue

---

## Editing Variables

![Click continue](img/vscode-continue.png)

???
→ Then click "continue"

(Or f5)

All this time our browser has been waiting!!

---

## Editing Variables

![BROWSER with Edited title](img/browser-with-edited-title.png)

???

...and our template rendered with the new value we set, from the debugger.

**Bahot acha!**

→ let's say we want to go back to the caller, we stepped too far in

---

## Call Stack

![click last stack frame](img/vscode-stack-select.png)

???

**We're back on line 938 as we were before** but this time we're not going to hit continue

Q: Can anyone see the problem in my call stack?

A: **ANONYMOUS FUNCTION**

---

## Call Stack

![VIEWING last stack frame](img/vscode-stack-back.png)

???

* Now we can see the frame this function was called from
* Note green breakpoint marker: "NOT current location"

→ right click

---

## Call Stack

![RESTART last stack frame](img/vscode-stack-reload.png)

???

**Restart frame**: This will rewind code execution to this frame

---

## Call Stack

![RESTART last stack frame](img/vscode-stack-reloaded.png)

???

* Now we're back in the last frame, we can change things and start execution again

### talk:

* Very powerful
* Step through your application
* Go back
* See who called what etc.

→ Relaunching from shell each time is annoying (also can't catch *startup* errors)
→ Let's set this up to load from VSCode

---

## Default Launch Configurations

```no-highlight
test-app/.vscode/launch.json
```

```js
{
  "version": "0.2.0",
  "configurations": [
*   {
*     "type": "node",
*     "request": "launch",
*     "name": "Launch Program",
*     "program": "${workspaceRoot}/bin/www"
*   },
    {
      "type": "node",
      "request": "attach",
      "name": "Attach to Port",
      "address": "localhost",
      "port": 5858
    }
  ]
}
```

???

* Launch with node
* "program" = startup script
* "workspace root": VScode gives you lots of variables

→ Where did this configuration come from?

---

## `package.json`

```js
{
  "name": "test-app",
  "version": "0.0.0",
  "private": true,
* "scripts": {
*   "start": "node ./bin/www"
* },
  "dependencies": {
    "body-parser": "~1.16.0",
    "cookie-parser": "~1.4.3",
    "debug": "~2.6.0",
    "express": "~4.14.1",
    "jade": "~1.11.0",
    "morgan": "~1.7.0",
    "serve-favicon": "~2.3.2",
    "winston": "^2.3.1"
  }
}
```

???

VSCode will look for startup configurations in your package.json and automatically set them as launch configs

Here we have `npm start` but it will also pickup `package.main` if one exists

→ Kill our running script then launch from VSCode

---

## Launch from VSCode
![mouse over "launch" button](img/vscode-debug-launch.png)

???
Going to click the little green "launch" button

(Or f5)

* Now we can launch straight from VSCode

→ I added a breakpoint

---

## Launch from VSCode
![break on line 1](img/vscode-launch-break-line-one.png)

???

* Also you can (re)launch with F5 making it easy to change & relaunch
* Note that the debug output (console) is now inside vscode

→ We used default launch configs but they can get more complex:

---

## More Launch Configurations

```no-highlight
$ NODE_ENV=development node ./node_modules/.bin/node-lambda run
```

.small-list[
* Script: `./node_modules/.bin/node-lambda`
* Argument: `run`
* Environment variables: `NODE_ENV=development`
]

???
Lets say I have a command like this:

* run `node-lambda` (from node modules)
* with the argument `run`
* with environment variable `NODE_ENV=development`

```js
{
    "version": "0.3.0",
    "configurations": [{
      "name": "Launch",
      "type": "node",
      "request": "launch",
*     "program": "${workspaceRoot}/node_modules/.bin/node-lambda",
*     "args": ["run"],
*     "cwd": "${workspaceRoot}",
*     "env": {
*       "NODE_ENV": "development"
*     },
    }]
}
```

???

Starting from a utility script in node_modules

* CWD is also important

→ with that set up Let's **revisit breakpoints** and go over the other debug panes.

---

## Break on Exceptions

???

* Checked by default

```js
var express = require('express');
var router = express.Router();

*router.use(express.static());

/* GET home page. */
router.get('/', function(req, res, next) {
  res.render('index', { title: 'Express' });
});

module.exports = router;
```

???

calling a function to construct an express middleware object.

→ Run our script and...

---

## Break on Exceptions

![](img/vscode-root-path-required.png)

???

Uh-oh! there's an error: "root path required"

Go to my call stack and → Click on the frame that called this one

---

## Break on Exceptions

![](img/vscode-root-path-up-stack.png)

???

Also "Break on ALL Exceptions" (even handled ones) → Be prepared for a lot of noise

---

## Conditional Breakpoints

![](img/vscode-conditional-breakpoints.png)

???
* Enter a condition
  * only admin
  * stop when some program condition is true → useful for when you have a hard to reproduce case
* hit count: Not so useful here but useful if something is getting called 2x and you only want it called 1x (where is second call coming from?)

More breakpoints I'm not going over!

* Column (for minified code)
* Function name (break when fn by that name is executed)

---

## Watch Expressions

![watch expressions](img/vscode-watch-expressions.png);

???
Any time program is paused, it will show the current value **in the current scope**

* process.pid
* req.query.user

Useful to track change of something through steps, see where it changed

---

## Debug Console

![watch expressions](img/vscode-debug-console.png);

???

* Execute code in the current context (response.setHeader etc.)
  * Good for things you have to transform with function calls
* Also a good way to explore in-memory objects

→ Enough VS Code, let's look at debugging with the chrome debugger.

---
# Node Inspector Installation

???

Node-inspector is the name of the tool that links chrome devtools to node.js

<pre class="ansi2html">
$ npm install -g node-inspector
$ node-inspect my-script.js
</pre>

---
# ~~Node Inspector Installation~~

<pre class="ansi2html">
<strike>$ npm install -g node-inspector</strike>
<strike>$ node-inspect my-script.js</strike>
</pre>

## ✨ Bundled with Node (6.3+)✨

<pre class="ansi2html">
$ node --inspect my-script
</pre>

???

Before we jump in with chrome, let's → Quickly review the debug startup methods we've discussed so far

---

## Debug *in Terminal*

<pre class="ansi2html">
$ node debug my-app.js
< Debugger listening on [::]:5858
connecting to 127.0.0.1:5858 ... ok
break in my-app:7
...
</pre>

## Listen for *VSCode* Debugger

<pre class="ansi2html">
$ node --debug my-app.js
Debugger listening on [::]:5858
[[attach vs-code]]
</pre>

## Listen for *Chrome* Debugger

<pre class="ansi2html">
$ node --inspect my-app.js
Debugger listening on port 9229.
Warning: This is an experimental feature and could change at any time.
To start debugging, open the following URL in Chrome:
 chrome-devtools://devtools/remote/serve_file/@521e5b7e2b7cc66b4006a8a54cb9c4e57494a5ef/inspector.html?experiments=true&v8only=true&ws=localhost:9229/node
</pre>

???

Let's jump into the chrome debugger

---

# Chrome Debugger

???

Point a chrome browser to that URL....

---

# Chrome Debugger

![chrome debugger](img/chrome-debugger.png)

???

Here it is! Looks fairly similar to VSCode debugger

→ Why would you use this instead?

---

## Advantages (over VSCode) ✅

* CPU profiling
* Heap snapshots & analysis 
* Don't need to use VS Code

## Disadvantages ❌

* Outside your IDE
* Some non-node related cruft

## ✅✅✅ Use both!

???

They do different things

Use VS-Code for dev, chrome when you need more advanced debugging

breakpoints, watch expressions etc. are about the same (vscode has a slight edge in places)

→ **Profiling** is what chrome inspector is good for

---

## Chrome: Profiling

![chrome profiler overview](img/chrome-profiles-overview.png)

???
* In the profiles tab

### Tools
* Record JavaScript CPU Profile - see where execution time is spent, CPU spikes etc.
* Heap snapshot: show what's using memory
* and more!

→ Start with taking a CPU profile
→ Run some requests against our simple Node.js server with three routes: fibonacci, index, and one that loops and generates arrays of numbers

---

## Three Routes:

```js
*router.get('/', function handleIndex(req, res, next) {
  res.render('index', { title: 'Express' });
});

*router.get('/fibonacci/:iters', function handleFibonacci(req, res, next) {
    var num = fibonacci(Number(req.params.iters) || 10);
    res.render('fib', { number: num, /*...*/} )
});

*router.get('/loop/:iters', function loopHandler(req, res, next){
 /* generate a big 2D array of numbers */
 res.send(ray.map(nums => nums.join(', ')).join(' '));
});
```

???

Important bit now is the function names:

* handleIndex
* handleFibonacci
* loopHandler

→ Run some requests against our simple Node.js server with three routes: fibonacci, index, and one that loops and generates arrays of numbers

---

## CPU Profiling: Flame Charts

![normal request](img/flame-normal-request.png)

???

Zoomed in on a couple requests here

What are we looking at? This is about 10 seconds of running Express app

* Each colored bar is a function call or frame
* Lower frames are callers, call next one down
* Anonymous function calls onstat which calls next etc.
* Height is call depth
* Width is CPU time
* Colored by file

Note pink says "handleIndex" that's our handler function

→ hover over it

---

## CPU Profiling: Flame Charts

![normal request](img/flame-normal-request-hover.png)

???

Takes about 6 ms

---

## High CPU Functions

![really wide flame request](img/flame-wide-loop.png)

???

Really wide bars on our handleLoop!

---

## High CPU Functions

![wide flame request hovered: 61ms on one call](img/flame-wide-loop-hover.png)

???

Hover: 61ms

→ Click to jump to the code

---

## High CPU Functions

![](img/flame-clicked-to-loop.png)

???

← Jumped right to the line of code, with that line highlighted!

→ Another way to look is as a chart

---

## CPU Call Chart

![](img/cpu-chart-heavy-loop.png)

???

Here you can see **by function** how much time was spent

→ In our case we can see it's our loop handler function

---

## CPU Call Chart

![](img/cpu-chart-heavy-loop-hovered.png)

???

* This is another way of identifying issues
* Good if there's one function that's called from *many places* but **takes a lot of time in total**

→ Wide bar in our flame graph is lots of CPU, deep is.....

---

## Flame Charts: Recursion

![](img/flame-fibonacci.png)

???

← ... lots of recursion

* Here our fibonacci function is very deep call

→ last thing: heap snapshots

---

## Heap Snapshots

???

Capture a list of objects in memory and how much they use

Here's our new route:

```js
var sockets = [];

function CreateNewFileReader(){
* sockets.push(fs.createReadStream('/tmp/letter.txt'));
}

router.get('/leak', function(req, res){
* CreateNewFileReader();
  res.send('ok');
});
```

???

Each call to `/leak`, call a function that creates a new ReadableStream and puts it in an array

Specifically, it opens a file read stream for `/tmp/letter.txt/`

→ Start our program and take a heap snapshot

---

## Snapshot

![](img/heap-take-snapshot.png)

???
→ looks like this

---

## Snapshot: Start

![heap snapshot](img/heap-snapshot-1.png)

???

Won't explain this too much... but nothing out of the ordinary

* Sorting by retained size
* More memory is held by strings than anything else

**Now hit our `/leak/` route 6,000 times**

→ Take another snapshot

---

## Snapshot: Later on...

![snapshot after calling leak 6k times](img/heap-snapshot-2.png)

???

97% memory is in ArrayBufferData!! That doesn't look right.

→ Look at comparison from last snapshot, compare the two

---

## Snapshot: Comparison

![](img/heap-comparison-sorted-by-alloc-size.png)

???

Note the **Delta** of those object counts-- we can see that a lot were created since last snapshot (6001)

**Comparing across snapshots from different times to see what's been created or what's retained across snapshots one of the best ways to get started with memory analysis**

Note also Alloc size + Size delta: these things are using a lot of memory!

→ Let's click to open this listing of objects

---

## Snapshot: Comparison

![](img/heap-comparison-opened-system-jsarraybufferdata-tree.png)

???

What are these objects "jsarraybufferdata"?

We select one and can inspect its **retainers** at the bottom, the retainer is the thing that keeps it in memory, keeps it from being garbage collected.

Nothing is obvious right away, but if we hover over some of the objects we can see their properties →

---

## Snapshot

![](img/heap-comparison-hovered-_readableState.png)

???

Aha! We can see this readable stream has a "path" property that points to letter.txt

**This gives us a good clue for where to start looking in our codebase**

→ That's all. I hope you enjoyed the talk

---
.last-page-floater[![Great Indian Developer Summit](img/GIDSLogo.jpg)]

# Thank you!!

## Sequoia McDowell

.small-list[
* 🌐  http://sequoia.makes.software
* 🦆  @_sequoia
* 📧  sequoia.mcdowell@gmail.com
* http://sequoia.makes.software/debugging-nodejs-talk/
]

???

* you can find the slides below
* Thanks to GIDS
* Thanks for coming!