SFNode April: Instrumenting Node.js in Production

The code demoed on slide 16 can be found here: https://github.com/watson/talks/tree/master/2016/04%20SFNode/example-app

This talk covers different approaches of instrumenting a Node.js application. If applied correctly, instrumentation will allow you to discover bottlenecks or track and log application usage - even in production, without sacrificing performance.

Part one will cover the current state of tracing and instrumentation. In part two we’ll take a look at the next-gen core tracing API's being developed under the Node.js Tracing Working Group.

Transcript

1. Thomas Watson @wa7son github.com/watson
3. in production Instrumenting Node.js
7. Vocabulary • A trace is a measure of how long something takes, e.g. a database query or a network request • A transaction is a group of traces, e.g. all traces associated with an incoming HTTP request
8. Let’s create an instrumentation module
9. Goals • Create a new transaction when a new HTTP request occurs • Group traces under transactions • Instrument I/O • Instrument potential CPU expensive operations • Associate exceptions with HTTP requests • Almost no overhead • Don’t manually pass state around in the app • Plug’n’play • (Keep context across requests to microservices)
10. Problems • Multiple HTTP requests active at the same time • No API to pass state across the async boundary • Associate thrown errors with origin HTTP request
11. Solution Automagically pass state across the async boundary
12. Solution 1. Record state when a callback is queued on the event loop 2. Restore state when the callback is de-queued from the event loop
13. Solution 1. Record state when a callback is queued on the event loop 2. Restore state when the callback is de-queued from the event loop global.currentTransaction = new Transaction(req)
14. Solution 1. Record state when a callback is queued on the event loop 2. Restore state when the callback is de-queued from the event loop global.currentTransaction global.currentTransaction = new Transaction(req)
15. Patch every async operation • Timers • process.nextTick • Promise (native) • libuv…
16. Show some real code
17. Other solutions? • Domains • AsyncWrap
18. AsyncWrap https://github.com/nodejs/tracing-wg
23. user: before async_wrap: init user: after async_wrap: pre user: done async_wrap: post async_wrap: destroy
25. FATAL ERROR: node::AsyncWrap::AsyncWrap init hook threw
28. user: before async_wrap: init user: after async_wrap: pre user: done async_wrap: post async_wrap: destroy
30. > var asyncWrap = process.binding('async_wrap') undefined > asyncWrap.Providers { NONE: 0, CRYPTO: 1, FSEVENTWRAP: 2, FSREQWRAP: 3, GETADDRINFOREQWRAP: 4, GETNAMEINFOREQWRAP: 5, HTTPPARSER: 6, JSSTREAM: 7, PIPEWRAP: 8, PIPECONNECTWRAP: 9, PROCESSWRAP: 10, QUERYWRAP: 11, SHUTDOWNWRAP: 12, SIGNALWRAP: 13, STATWATCHER: 14, TCPWRAP: 15, TCPCONNECTWRAP: 16, TIMERWRAP: 17, TLSWRAP: 18, TTYWRAP: 19, UDPWRAP: 20, UDPSENDWRAP: 21, WRITEWRAP: 22, ZLIB: 23 }
32. Handle Objects Node Core Userland libuv V8 JavaScript C++
33. Handle Objects net.connect
34. Handle Objects net.connect req === this socket === this
35. Timers
36. Timers user: before #1 async_wrap: init user: after #1 user: before #2 user: after #2
37. Timers user: before #1 async_wrap: init user: after #1 user: before #2 user: after #2 async_wrap: pre user: done #1 user: done #2 async_wrap: post async_wrap: destroy
38. AsyncWrap Gotchas • Handle creation time • console.log • process.nextTick • Timers • Promises • Multiple AsyncWrap’s
39. Thank you! Any questions? @wa7son github.com/watson