JSNation 2019: Post-Mortem Debugging in Node.js

Slide 1

Slide 1 text

@wa7son Thomas Watson @wa7son github.com/watson

Slide 2

Slide 2 text

@wa7son

Slide 3

Slide 3 text

@wa7son Post-Mortem Debugging in Node.js

Slide 4

Slide 4 text

@wa7son Who am I? • Thomas Watson • Open Source developer at github.com/watson • Principal Software Engineer at Elastic • Node.js Core Member • Tweets as @wa7son

Slide 5

Slide 5 text

@wa7son Node.js Diagnostics Working Group github.com / nodejs / diagnostics

Slide 6

Slide 6 text

@wa7son @wa7son Post-Mortem Debugging

Slide 7

Slide 7 text

@wa7son –Wikipedia “Post-mortem debugging is debugging of the program after it has already crashed.” @wa7son

Slide 8

Slide 8 text

@wa7son Tools • lldb + llnode • mdb + mdb_v8 • autopsy • node-report => --experimental-report • node-heapdump => v8.getHeapSnapshot() + v8.writeHeapSnapshot() • Chrome DevTools

Slide 9

Slide 9 text

@wa7son Core Dumps @wa7son

Slide 10

Slide 10 text

@wa7son @wa7son Source: Konstantin Lanzet License: CC BY-SA 3.0

Slide 11

Slide 11 text

@wa7son @wa7son Source: Konstantin Lanzet License: CC BY-SA 3.0

Slide 12

Slide 12 text

@wa7son @wa7son

Slide 13

Slide 13 text

@wa7son @wa7son

Slide 14

Slide 14 text

@wa7son

Slide 15

Slide 15 text

@wa7son Processor registers Program counter System ﬂags

Slide 16

Slide 16 text

@wa7son Core Dump Formats a.out Older versions of Unix ELF Modern Linux, System V, Solaris, and BSD systems Mach-O macOS, etc

Slide 17

Slide 17 text

@wa7son Generating a Core Dump ulimit -c unlimited Maximum allowed size of core dump

Slide 18

Slide 18 text

@wa7son Generating a Core Dump node --abort-on-uncaught-exception app.js

Slide 19

Slide 19 text

@wa7son Generating a Core Dump gcore Generate a core dump form a running process on Linux ~/core.

Slide 20

Slide 20 text

@wa7son Generating a Core Dump lldb --attach-pid -b -o 'process save-core "core."' Core dump ﬁlename Generate a core dump form a running process on macOS

Slide 21

Slide 21 text

@wa7son Next Step: The Debugger gdb, lldb, etc

Slide 22

Slide 22 text

@wa7son LLDB MacOS, iOS, Linux, FreeBSD, and Windows as in DeBugger, not DataBase

Slide 23

Slide 23 text

@wa7son

Slide 24

Slide 24 text

@wa7son brew install --with-lldb --with-toolchain llvm

Slide 25

Slide 25 text

@wa7son github.com / nodejs / llnode

Slide 26

Slide 26 text

@wa7son lldb /path/to/program -c /path/to/core-file

Slide 27

Slide 27 text

@wa7son llnode /path/to/node -c /path/to/core-file

Slide 28

Slide 28 text

@wa7son Crashes @wa7son

Slide 29

Slide 29 text

@wa7son Error: boom! at /app/server.js:4:13 at /app/server.js:5:7 at /app/server.js:6:5 at processTicksAndRejections (internal/process/task_queues.js:79:9) at process.runNextTicks [as _tickCallback] (internal/process/task_queues.js:56:3) at Function.Module.runMain (internal/modules/cjs/loader.js:871:11) at internal/main/run_main_module.js:21:11

Slide 30

Slide 30 text

@wa7son $ node --abort-on-uncaught-exception server.js Server is listening on port 3000 POST /signup Uncaught TypeError: Cannot read property 'first' of undefined FROM onSave (/app/server.js:16:36) Timeout._onTimeout (/app/server.js:31:5) listOnTimeout (internal/timers.js:531:17) processTimers (internal/timers.js:475:7) [1] 10904 illegal hardware instruction (core dumped) node --abort-on-uncaught-exception server.js

Slide 31

Slide 31 text

Slide 32

Slide 32 text

Slide 33

Slide 33 text

Slide 34

Slide 34 text

Slide 35

Slide 35 text

Slide 36

Slide 36 text

@wa7son app.post('/signup', function singupRoute (req, res) { save(req.body, function onSave (err, user) { if (err) return res.status(500).send('Error: ' + err.message) res.end('Welcome ' + user.name.first) }) }) Cannot read property 'first' of undefined

Slide 37

Slide 37 text

@wa7son Demo Time!

Slide 38

Slide 38 text

@wa7son @wa7son Unresponsive Process

Slide 39

Slide 39 text

@wa7son What is your program doing right now?

Slide 40

Slide 40 text

@wa7son const stringify = require('./lib/stringify') // Turn this: // { foo: 1, bar: 2 } // Into this: // { foo: "1", bar: "2" } console.log(stringify({ foo: 1, bar: 2 }))

Slide 41

Slide 41 text

@wa7son Demo Time!

Slide 42

Slide 42 text

@wa7son Alternative: CPU Proﬁling

Slide 43

Slide 43 text

@wa7son Recap 1/2 Production Server • gcore • lldb --attach-pid -b -o 'process save-core "core."'

Slide 44

Slide 44 text

@wa7son Recap 2/2 Dev machine • llnode node -c core llnode • v8 help Get help • v8 bt Get stack trace at crash • frame select 3 Select stack frame #3 • v8 source list Show source code at selected stack frame • v8 inspect Inspect object at address

Slide 45

Slide 45 text

@wa7son @wa7son Memory Leaks

Slide 46

Slide 46 text

@wa7son FATAL ERROR: CALL_AND_RETRY_2 Allocation failed - process out of memory Abort trap: 6

Slide 47

Slide 47 text

@wa7son What are Memory Leaks in JS?

Slide 48

Slide 48 text

@wa7son What are Memory Leaks in JS? No memory leak (will be garbage collected)

Slide 49

Slide 49 text

@wa7son What are Memory Leaks in JS?

Slide 50

Slide 50 text

@wa7son What are Memory Leaks in JS?

Slide 51

Slide 51 text

@wa7son (llnode) v8 findjsobjects

Slide 52

Slide 52 text

@wa7son (llnode) v8 findjsobjects Instances Total Size Name ---------- ---------- ---- 1 24 AssertionError 1 24 AsyncResource 1 24 Control 1 24 FastBuffer 1 24 Loader 1 24 ModuleJob 1 24 ModuleMap 1 24 Performance 1 24 PerformanceObserver 1 24 SafeMap 1 24 SafePromise 1 24 SafeSet 1 24 SocketListReceive

Slide 53

Slide 53 text

@wa7son 12 384 TCP 12 2688 WritableState 15 1360 (ArrayBufferView) 74 4736 NativeModule 5715 1234440 IncomingMessage 5744 781184 ServerResponse 5747 1103424 ReadableState 5748 275880 BufferList 45980 2942680 TickObject 69344 2219008 (Array) 235515 9420584 Visit 293720 15437744 Object 615411 3750984 (String) ---------- ---------- 1283140 37182200

Slide 54

Slide 54 text

@wa7son (llnode) v8 findjsinstances -d Visit

Slide 55

Slide 55 text

@wa7son (llnode) v8 findjsinstances -d Visit 0x0000176d04402201:, .headers=0x0000176d7d99f1c9:}> 0x0000176d04402229:, .headers=0x0000176d7d99f191:}> 0x0000176d04402251:, .headers=0x0000176d7d99f159:}> 0x0000176d04402279:, .headers=0x0000176d7d99f121:}> 0x0000176d044022a1:, .headers=0x0000176d7d99f0e9:}>

Slide 56

Slide 56 text

@wa7son 0x0000176d044022c9:, .headers=0x0000176d7d99f0b1:}> // A thousand miles later... 0x0000176dffba62d9:, .headers=0x0000176dffbef559:}> 0x0000176dffba6301:, .headers=0x0000176dffbef8a9:}> 0x0000176dffba6329:, .headers=0x0000176dffb82481:}>

Slide 57

Slide 57 text

@wa7son (llnode) v8 inspect -m 0x0000176dffba6329

Slide 58

Slide 58 text

@wa7son (llnode) v8 inspect -m 0x0000176dffba6329 0x0000176dffba6329(map=0x0000176d689cec29):, .headers=0x0000176dffb82481:}>

Slide 59

Slide 59 text

@wa7son (llnode) v8 inspect 0x0000176d689cec29

Slide 60

Slide 60 text

@wa7son (llnode) v8 inspect 0x0000176d689cec29 0x0000176d689cec29:, [1]=, [2]=0x0000176dd8566a11:, [3]=, [4]=, [5]=0x0000176dd8566a31:, [6]=, [7]=0x0000176d117509f9:}>>

Slide 61

Slide 61 text

@wa7son (llnode) v8 findrefs 0x0000176dffba6329

Slide 62

Slide 62 text

@wa7son (llnode) v8 findrefs 0x0000176dffba6329 0x176d1f4fac41: (Array)[156027]=0x176dffba6329

Slide 63

Slide 63 text

@wa7son Can this be improved? • Convert a core dump to a heap snapshot • Allow user to trigger a gc + heap snapshot from outside the process

Slide 64

Slide 64 text

@wa7son Heap Dump Difﬁng

Slide 65

Slide 65 text

@wa7son Heap Dump Difﬁng Find common ancestor

Slide 66

Slide 66 text

@wa7son Writing heap snapshots process.on('SIGUSR2', () => { const { writeHeapSnapshot } = require('v8') console.log('Heap snapshot written:’, writeHeapSnapshot()) }) Returns name of ﬁle written kill -SIGUSR2 (For now, works only on Node.js 11.13.0+)

Slide 67

Slide 67 text

@wa7son Load two heap snapshots Make a diﬀ Sort by Delta

Slide 68

Slide 68 text

@wa7son

Slide 69

Slide 69 text

@wa7son Recap Dev machine • llnode node -c core llnode • v8 help Get help • v8 findjsobjects -d List all objects sorted by count • v8 inspect Inspect object at address • v8 findrefs Find all references to object at address

Slide 70

Slide 70 text

@wa7son github.com/watson Bedankt