JSNation 2019: Post-Mortem Debugging in Node.js

Post-Mortem debugging is a really powerful technique that allows you, through the use of several tools, to take a memory dump when an issue occurs in your application and later analyze it offline.

The talk will primarily focus on llnode and how you can use this tool to better understand why a Node.js process is behaving odd or is crashing.

Transcript

1. @wa7son Thomas Watson @wa7son github.com/watson
2. @wa7son
3. @wa7son Post-Mortem Debugging in Node.js
4. @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
5. @wa7son Node.js Diagnostics Working Group github.com / nodejs / diagnostics
6. @wa7son @wa7son Post-Mortem Debugging
7. @wa7son –Wikipedia “Post-mortem debugging is debugging of the program after it has already crashed.” @wa7son
8. @wa7son Tools • lldb + llnode • mdb + mdb_v8 • autopsy • node-report => --experimental-report • node-heapdump => v8.getHeapSnapshot() + v8.writeHeapSnapshot() • Chrome DevTools
9. @wa7son Core Dumps @wa7son
10. @wa7son @wa7son Source: Konstantin Lanzet License: CC BY-SA 3.0
11. @wa7son @wa7son Source: Konstantin Lanzet License: CC BY-SA 3.0
12. @wa7son @wa7son
13. @wa7son @wa7son
14. @wa7son
15. @wa7son Processor registers Program counter System flags
16. @wa7son Core Dump Formats a.out Older versions of Unix ELF Modern Linux, System V, Solaris, and BSD systems Mach-O macOS, etc
17. @wa7son Generating a Core Dump ulimit -c unlimited Maximum allowed size of core dump
18. @wa7son Generating a Core Dump node --abort-on-uncaught-exception app.js
19. @wa7son Generating a Core Dump gcore <pid> Generate a core dump form a running process on Linux ~/core.<pid>
20. @wa7son Generating a Core Dump lldb --attach-pid <PID> -b -o 'process save-core "core.<PID>"' Core dump filename Generate a core dump form a running process on macOS
21. @wa7son Next Step: The Debugger gdb, lldb, etc
22. @wa7son LLDB MacOS, iOS, Linux, FreeBSD, and Windows as in DeBugger, not DataBase
23. @wa7son
24. @wa7son brew install --with-lldb --with-toolchain llvm
25. @wa7son github.com / nodejs / llnode
26. @wa7son lldb /path/to/program -c /path/to/core-file
27. @wa7son llnode /path/to/node -c /path/to/core-file
28. @wa7son Crashes @wa7son
29. @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
30. @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
31. @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
32. @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
33. @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 /cores/core.10904
34. @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
35. @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
36. @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
37. @wa7son Demo Time!
38. @wa7son @wa7son Unresponsive Process
39. @wa7son What is your program doing right now?
40. @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 }))
41. @wa7son Demo Time!
42. @wa7son Alternative: CPU Profiling
43. @wa7son Recap 1/2 Production Server • gcore <pid> • lldb --attach-pid <PID> -b -o 'process save-core "core.<PID>"'
44. @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 <addr> Inspect object at address
45. @wa7son @wa7son Memory Leaks
46. @wa7son FATAL ERROR: CALL_AND_RETRY_2 Allocation failed - process out of memory Abort trap: 6
47. @wa7son What are Memory Leaks in JS?
48. @wa7son What are Memory Leaks in JS? No memory leak (will be garbage collected)
49. @wa7son What are Memory Leaks in JS?
50. @wa7son What are Memory Leaks in JS?
51. @wa7son (llnode) v8 findjsobjects
52. @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
53. @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
54. @wa7son (llnode) v8 findjsinstances -d Visit
55. @wa7son (llnode) v8 findjsinstances -d Visit 0x0000176d04402201:<Object: Visit properties { .visit_id=<Smi: 82704>, .headers=0x0000176d7d99f1c9:<Object: Object>}> 0x0000176d04402229:<Object: Visit properties { .visit_id=<Smi: 82705>, .headers=0x0000176d7d99f191:<Object: Object>}> 0x0000176d04402251:<Object: Visit properties { .visit_id=<Smi: 82706>, .headers=0x0000176d7d99f159:<Object: Object>}> 0x0000176d04402279:<Object: Visit properties { .visit_id=<Smi: 82707>, .headers=0x0000176d7d99f121:<Object: Object>}> 0x0000176d044022a1:<Object: Visit properties { .visit_id=<Smi: 82708>, .headers=0x0000176d7d99f0e9:<Object: Object>}>
56. @wa7son 0x0000176d044022c9:<Object: Visit properties { .visit_id=<Smi: 82709>, .headers=0x0000176d7d99f0b1:<Object: Object>}> // A thousand miles later... 0x0000176dffba62d9:<Object: Visit properties { .visit_id=<Smi: 156026>, .headers=0x0000176dffbef559:<Object: Object>}> 0x0000176dffba6301:<Object: Visit properties { .visit_id=<Smi: 156027>, .headers=0x0000176dffbef8a9:<Object: Object>}> 0x0000176dffba6329:<Object: Visit properties { .visit_id=<Smi: 156028>, .headers=0x0000176dffb82481:<Object: Object>}>
57. @wa7son (llnode) v8 inspect -m 0x0000176dffba6329
58. @wa7son (llnode) v8 inspect -m 0x0000176dffba6329 0x0000176dffba6329(map=0x0000176d689cec29):<Object: Visit properties { .visit_id=<Smi: 156028>, .headers=0x0000176dffb82481:<Object: Object>}>
59. @wa7son (llnode) v8 inspect 0x0000176d689cec29
60. @wa7son (llnode) v8 inspect 0x0000176d689cec29 0x0000176d689cec29:<Map own_descriptors=2 in_object_size=2 instance_size=40 descriptors=0x0000176d7f284569:<FixedArray, len=8 contents={ [0]=<Smi: 2>, [1]=<Smi: 0>, [2]=0x0000176dd8566a11:<String: "visit_id">, [3]=<Smi: 320>, [4]=<Smi: 1>, [5]=0x0000176dd8566a31:<String: "headers">, [6]=<Smi: 1050112>, [7]=0x0000176d117509f9:<unknown>}>>
61. @wa7son (llnode) v8 findrefs 0x0000176dffba6329
62. @wa7son (llnode) v8 findrefs 0x0000176dffba6329 0x176d1f4fac41: (Array)[156027]=0x176dffba6329
63. @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
64. @wa7son Heap Dump Diffing
65. @wa7son Heap Dump Diffing Find common ancestor
66. @wa7son Writing heap snapshots process.on('SIGUSR2', () => { const { writeHeapSnapshot } = require('v8') console.log('Heap snapshot written:’, writeHeapSnapshot()) }) Returns name of file written kill -SIGUSR2 <pid> (For now, works only on Node.js 11.13.0+)
67. @wa7son Load two heap snapshots Make a diff Sort by Delta
68. @wa7son
69. @wa7son Recap Dev machine • llnode node -c core llnode • v8 help Get help • v8 findjsobjects -d List all objects sorted by count • v8 inspect <addr> Inspect object at address • v8 findrefs <addr> Find all references to object at address
70. @wa7son github.com/watson Bedankt