NodeConf EU 2019: The Trouble with Tracers

To get insights into the performance of your application and what specifically it’s spending time on, you need good tracing tools.

Historically however, it’s been very difficult to implement tracers in Node.js due to its async nature and the lack of an official context propagation API in core.

Throw modern deployment architectures into the mix, and you also need to deal with distributed tracing across multiple microservices.

This talk is about how tracers work behind the scenes, which pitfalls exist and the work going on in the Node.js Diagnostics Working Group, in W3C, and within other standard-organizations to improve the situation.

Transcript

1. wa7son Thomas Watson @wa7son github.com/watson
2. wa7son The Trouble with Tracers
3. 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 • Slides: github.com/watson/talks
4. wa7son Tracing 101
5. wa7son Span D Span E Span F Span B Span C Trace Graph Span A The root span Span B is a ‘child’ of Span A
6. wa7son Span D Span E Span F Span B Span C Trace Timeline Span A Time
7. wa7son const span = tracer.startSpan('query', { childOf: otherSpan }) mysql.query(sql, function (err, result) { span.end() // ... })
8. wa7son tracer.startSpan('query') mysql.query(sql, processResult) // ... function processResult (err, result) { const span = ??? span.end() // ... } TODO: Get the current span somehow
9. wa7son const span = tracer.startSpan('query') mysql.query(sql, processResult.bind(null, { span })) // ... function processResult (ctx, err, result) { const span = ctx.span span.end() // ... }
10. wa7son tracer.startSpan('query') mysql.query(sql, processResult) // ... function processResult (err, result) { const span = tracer.getCurrentSpan() span.end() // ... }
11. wa7son mysql.query(sql, function (err, result) { // ... })
12. wa7son mysql.query(sql, function (err, result) { // ... })
13. wa7son
14. wa7son Dirty Secrets Patching require No built-in context propagation Getting stack traces Patching every async call -> async_hooks - async await… thenables broken - Promise destroy hook triggerd GC - Uses numeric ids witch doesn’t play nice with weak maps => hacks in place to clean it up, but those comes with risks - What you want to patch isn’t directly exported TAV Resource management (memory, CPU etc) Injecting headers into HTTP requests Babel/TypeScript defineProperty hell Object reuse pool Metrics: Not a lot of API’s to get data from => read things from the filesystem = brittle
15. wa7son mysql.query() 1. Start a span when the ‘query’ function is called 2. Associate new span with current trace 3. Make current span child of current “active” span 4. End the span when the query finishes How do we know if mysql is used in the current project? How do we know when a mysql query is performed?
16. wa7son
17. wa7son Patching require()
18. wa7son const Module = require('module') const module = new Module() module.require('http')
19. wa7son const Module = require('module') const module = new Module() module.require('http')
20. wa7son const Module = require('module') const module = new Module() module.require('http')
21. wa7son Module.prototype.require
22. wa7son const Module = require('module') const origRequire = Module.prototype.require Module.prototype.require = function (id) { const exports = origRequire.apply(this, arguments) if (id === 'http') { const request = exports.request exports.request = function () { const req = request.apply(this, arguments) console.log('New outgoing request to', req.getHeader('Host')) return req } } return exports }
23. wa7son const Module = require('module') const origRequire = Module.prototype.require Module.prototype.require = function (id) { const exports = origRequire.apply(this, arguments) if (id === 'http') { const request = exports.request exports.request = function () { const req = request.apply(this, arguments) console.log('New outgoing request to', req.getHeader('Host')) return req } } return exports }
24. wa7son const Module = require('module') const origRequire = Module.prototype.require Module.prototype.require = function (id) { const exports = origRequire.apply(this, arguments) if (id === 'http') { const request = exports.request exports.request = function () { const req = request.apply(this, arguments) console.log('New outgoing request to', req.getHeader('Host')) return req } } return exports }
25. wa7son const Module = require('module') const origRequire = Module.prototype.require Module.prototype.require = function (id) { const exports = origRequire.apply(this, arguments) if (id === 'http') { const request = exports.request exports.request = function () { const req = request.apply(this, arguments) console.log('New outgoing request to', req.getHeader('Host')) return req } } return exports }
26. wa7son const Module = require('module') const origRequire = Module.prototype.require Module.prototype.require = function (id) { const exports = origRequire.apply(this, arguments) if (id === 'http') { const request = exports.request exports.request = function () { const req = request.apply(this, arguments) console.log('New outgoing request to', req.getHeader('Host')) return req } } return exports }
27. wa7son const Module = require('module') const origRequire = Module.prototype.require Module.prototype.require = function (id) { const exports = origRequire.apply(this, arguments) if (id === 'http') { const request = exports.request exports.request = function () { const req = request.apply(this, arguments) console.log('New outgoing request to', req.getHeader('Host')) return req } } return exports }
28. wa7son const Module = require('module') const origRequire = Module.prototype.require Module.prototype.require = function (id) { const exports = origRequire.apply(this, arguments) if (id === 'http') { const request = exports.request exports.request = function () { const req = request.apply(this, arguments) console.log('New outgoing request to', req.getHeader('Host')) return req } } return exports }
29. wa7son npm install require-in-the-middle
30. wa7son const path = require('path') const Hook = require('require-in-the-middle') // Hook into the express and mongodb module Hook(['express', 'mongodb'], function (exports, name, basedir) { const { version } = require(path.join(basedir, 'package.json')) console.log('loading %s@%s', name, version) // expose the module version as a property on its exports object exports._version = version // whatever you return will be returned by `require` return exports })
31. wa7son But wait a second…
32. wa7son ECMAScript Modules
33. wa7son Patching Transpiled Modules or: How I Learned to Stop Worrying and Love TypeScript & Babel
34. wa7son
35. wa7son
36. wa7son > const graphql = require('graphql') undefined > graphql.graphql = 'foo' 'foo' > graphql.graphql [Function: graphql] > delete graphql.graphql false
37. wa7son npm install shallow-clone-shim
38. wa7son Object.defineProperty(exports, 'foo' { enumerable: true, get: function get () { return 'hello' } }) const clone = require('shallow-clone-shim') const newExports = clone({}, exports, { foo (descriptor) { // descriptor == Object.getOwnPropertyDescriptor(exports, 'foo') const getter = descriptor.get descriptor.get = function get () { return getter() + ' world' } return descriptor } })
39. wa7son Patching Async Calls
40. wa7son const origSetTimeout = global.setTimeout global.setTimeout = function (callback, ...args) { const origSpan = tracer.currentSpan return origSetTimeout(function () { const preCallbackSpan = tracer.currentSpan tracer.currentSpan = origSpan callback.apply(this, arguments) tracer.currentSpan = preCallbackSpan }, ...args) };
41. wa7son const origSetTimeout = global.setTimeout global.setTimeout = function (callback, ...args) { const origSpan = tracer.currentSpan return origSetTimeout(function () { const preCallbackSpan = tracer.currentSpan tracer.currentSpan = origSpan callback.apply(this, arguments) tracer.currentSpan = preCallbackSpan }, ...args) };
42. wa7son const origSetTimeout = global.setTimeout global.setTimeout = function (callback, ...args) { const origSpan = tracer.currentSpan return origSetTimeout(function () { const preCallbackSpan = tracer.currentSpan tracer.currentSpan = origSpan callback.apply(this, arguments) tracer.currentSpan = preCallbackSpan }, ...args) };
43. wa7son const origSetTimeout = global.setTimeout global.setTimeout = function (callback, ...args) { const origSpan = tracer.currentSpan return origSetTimeout(function () { const preCallbackSpan = tracer.currentSpan tracer.currentSpan = origSpan callback.apply(this, arguments) tracer.currentSpan = preCallbackSpan }, ...args) };
44. wa7son const origSetTimeout = global.setTimeout global.setTimeout = function (callback, ...args) { const origSpan = tracer.currentSpan return origSetTimeout(function () { const preCallbackSpan = tracer.currentSpan tracer.currentSpan = origSpan callback.apply(this, arguments) tracer.currentSpan = preCallbackSpan }, ...args) };
45. wa7son const origSetTimeout = global.setTimeout global.setTimeout = function (callback, ...args) { const origSpan = tracer.currentSpan return origSetTimeout(function () { const preCallbackSpan = tracer.currentSpan tracer.currentSpan = origSpan callback.apply(this, arguments) tracer.currentSpan = preCallbackSpan }, ...args) };
46. wa7son const origSetTimeout = global.setTimeout global.setTimeout = function (callback, ...args) { const origSpan = tracer.currentSpan return origSetTimeout(function () { const preCallbackSpan = tracer.currentSpan tracer.currentSpan = origSpan callback.apply(this, arguments) tracer.currentSpan = preCallbackSpan }, ...args) };
47. wa7son All async API’s • net • http • child_process • timers • dns • fs • zlib • crypto • global.Promise
48. wa7son require('async_hooks')
49. wa7son But wait a second…
50. wa7son Async/await + Thenables
51. wa7son Resource Usage
52. wa7son const asyncHooks = require('async_hooks') const currentSpans = new Map() asyncHooks.createHook({ init (asyncId) { const span = tracer.currentSpan if (span) { currentSpans.set(asyncId, span) }; }, destroy (asyncId) { currentSpans.delete(asyncId) }; })
53. wa7son const asyncHooks = require('async_hooks') const currentSpans = new Map() asyncHooks.createHook({ init (asyncId) { const span = tracer.currentSpan if (span) { currentSpans.set(asyncId, span) }; }, destroy (asyncId) { currentSpans.delete(asyncId) }; })
54. wa7son const asyncHooks = require('async_hooks') const currentSpans = new Map() asyncHooks.createHook({ init (asyncId) { const span = tracer.currentSpan if (span) { currentSpans.set(asyncId, span) }; }, destroy (asyncId) { currentSpans.delete(asyncId) }; })
55. wa7son const asyncHooks = require('async_hooks') const currentSpans = new Map() asyncHooks.createHook({ init (asyncId) { const span = tracer.currentSpan if (span) { currentSpans.set(asyncId, span) }; }, destroy (asyncId) { currentSpans.delete(asyncId) }; })
56. wa7son const asyncHooks = require('async_hooks') const currentSpans = new Map() asyncHooks.createHook({ init (asyncId) { const span = tracer.currentSpan if (span) { currentSpans.set(asyncId, span) }; }, destroy (asyncId) { currentSpans.delete(asyncId) }; })
57. wa7son const asyncHooks = require('async_hooks') const currentSpans = new Map() asyncHooks.createHook({ init (asyncId) { const span = tracer.currentSpan if (span) { currentSpans.set(asyncId, span) }; }, destroy (asyncId) { currentSpans.delete(asyncId) }; })
58. wa7son const asyncHooks = require('async_hooks') const currentSpans = new Map() asyncHooks.createHook({ init (asyncId) { const span = tracer.currentSpan if (span) { currentSpans.set(asyncId, span) }; }, destroy (asyncId) { currentSpans.delete(asyncId) }; }) Not a WeakMap Can we trust (when) destroy is called?
59. wa7son Userland Callback Queues
60. wa7son class Client { constructor () { this.pool = new Pool({ size: 5 }) this.queue = [] }; request (query, callback) { const socket = this.pool.getAvailableSocket() if (socket) { socket.send(query, (err, res) => { callback(err, res) if (this.queue.length > 0) { const [query, callback] = this.queue.shift() this.request(query, callback) }; }) } else { this.queue.push([query, callback]) }; }; };
61. wa7son class Client { constructor () { this.pool = new Pool({ size: 5 }) this.queue = [] }; request (query, callback) { const socket = this.pool.getAvailableSocket() if (socket) { socket.send(query, (err, res) => { callback(err, res) if (this.queue.length > 0) { const [query, callback] = this.queue.shift() this.request(query, callback) }; }) } else { this.queue.push([query, callback]) }; }; };
62. wa7son class Client { constructor () { this.pool = new Pool({ size: 5 }) this.queue = [] }; request (query, callback) { const socket = this.pool.getAvailableSocket() if (socket) { socket.send(query, (err, res) => { callback(err, res) if (this.queue.length > 0) { const [query, callback] = this.queue.shift() this.request(query, callback) }; }) } else { this.queue.push([query, callback]) }; }; };
63. wa7son class Client { constructor () { this.pool = new Pool({ size: 5 }) this.queue = [] }; request (query, callback) { const socket = this.pool.getAvailableSocket() if (socket) { socket.send(query, (err, res) => { callback(err, res) if (this.queue.length > 0) { const [query, callback] = this.queue.shift() this.request(query, callback) }; }) } else { this.queue.push([query, callback]) }; }; };
64. wa7son class Client { constructor () { this.pool = new Pool({ size: 5 }) this.queue = [] }; request (query, callback) { const socket = this.pool.getAvailableSocket() if (socket) { socket.send(query, (err, res) => { callback(err, res) if (this.queue.length > 0) { const [query, callback] = this.queue.shift() this.request(query, callback) }; }) } else { this.queue.push([query, callback]) }; }; };
65. wa7son class Client { constructor () { this.pool = new Pool({ size: 5 }) this.queue = [] }; request (query, callback) { const socket = this.pool.getAvailableSocket() if (socket) { socket.send(query, (err, res) => { callback(err, res) if (this.queue.length > 0) { const [query, callback] = this.queue.shift() this.request(query, callback) }; }) } else { this.queue.push([query, callback]) }; }; };
66. wa7son class Client { constructor () { this.pool = new Pool({ size: 5 }) this.queue = [] }; request (query, callback) { const socket = this.pool.getAvailableSocket() if (socket) { socket.send(query, (err, res) => { callback(err, res) if (this.queue.length > 0) { const [query, callback] = this.queue.shift() this.request(query, callback) }; }) } else { this.queue.push([query, callback]) }; }; }; Called in the context of the previous `socket.send()` call
67. wa7son class Client { constructor () { this.pool = new Pool({ size: 5 }) this.queue = [] }; request (query, callback) { const socket = this.pool.getAvailableSocket() if (socket) { socket.send(query, (err, res) => { callback(err, res) if (this.queue.length > 0) { const [query, callback] = this.queue.shift() this.request(query, callback) }; }) } else { this.queue.push([query, callback]) }; }; }; Called in the context of the previous `socket.send()` call Which is called in the context of the previous `request()` call
68. wa7son class Client { constructor () { this.pool = new Pool({ size: 5 }) this.queue = [] }; request (query, callback) { const socket = this.pool.getAvailableSocket() if (socket) { socket.send(query, (err, res) => { callback(err, res) if (this.queue.length > 0) { const [query, callback] = this.queue.shift() this.request(query, callback) }; }) } else { this.queue.push([query, callback]) }; }; }; Called in the context of the previous `socket.send()` call Which is called in the context of the previous `request()` call
69. wa7son class Client { constructor () { this.pool = new Pool({ size: 5 }) this.queue = [] }; request (query, callback) { const socket = this.pool.getAvailableSocket() if (socket) { socket.send(query, (err, res) => { callback(err, res) if (this.queue.length > 0) { const [query, callback] = this.queue.shift() this.request(query, callback) }; }) } else { this.queue.push([query, callback]) }; }; }; Called in the context of the previous `socket.send()` call Which is called in the context of the previous `request()` call
70. wa7son Interservice Communication
71. wa7son Date: Mon, 29 Oct 2018 16:11:05 GMT Connection: keep-alive Content-Length: 0 GET /products HTTP/1.1 Host: www.example.com <magic header>
72. wa7son Date: Mon, 29 Oct 2018 16:11:05 GMT Connection: keep-alive Content-Length: 0 GET /products HTTP/1.1 Host: www.example.com <magic header>
73. wa7son GET /products HTTP/1.1 Host: www.example.com : - - - Date: Mon, 29 Oct 2018 16:11:05 GMT Connection: keep-alive Content-Length: 0 00 82c5500f40667e5500e9ae8e9711553c 992631f881f78c3b 01 traceparent
74. wa7son GET /products HTTP/1.1 Host: www.example.com : - - - Date: Mon, 29 Oct 2018 16:11:05 GMT Connection: keep-alive Content-Length: 0 00 82c5500f40667e5500e9ae8e9711553c 992631f881f78c3b 01 traceparent GET /products HTTP/1.1 Host: www.example.com traceparent: 00-82c5500f40667e5500e9ae8e9711553c-992631f881f78c3b-01 Date: Mon, 29 Oct 2018 16:11:05 GMT Connection: keep-alive Content-Length: 0 Trace Context Working Group Candidate Recommendation
75. wa7son GET /products HTTP/1.1 Host: www.example.com : - - - Date: Mon, 29 Oct 2018 16:11:05 GMT Connection: keep-alive Content-Length: 0 00 82c5500f40667e5500e9ae8e9711553c 992631f881f78c3b 01 traceparent
76. wa7son 00 82c5500f40667e5500e9ae8e9711553c 992631f881f78c3b 01 Version Trace ID 1 byte 8 bits 128 bit random number 64 bit random number Parent Span ID Trace Flags traceparent
77. wa7son 00 82c5500f40667e5500e9ae8e9711553c 992631f881f78c3b 01 Version Trace ID Parent Span ID Trace Flags 1 byte 8 bits 128 bit random number 64 bit random number Trace Flags Sampled — 0b00000001 traceparent
78. wa7son github.com / w3c / trace-context-binary
79. wa7son Standards
80. wa7son github.com / w3c / distributed-tracing-wg
81. wa7son w3.org / TR / trace-context
82. wa7son w3.org / TR / trace-context HTTP headers: traceparent tracestate
83. wa7son w3c.github.io / correlation-context
84. wa7son w3c.github.io / correlation-context HTTP headers: correlation-context
85. wa7son opentracing.io
86. wa7son opentracing.io
87. wa7son opentracing.io const span = tracer.startSpan('http_request') span.setTag(opentracing.Tags.ERROR, true) span.log({ event: 'error', 'error.object': err, message: err.message, stack: err.stack }) span.finish()
88. wa7son opencensus.io
89. wa7son opentelemetry.io
90. wa7son opentelemetry.io
91. wa7son github.com / nodejs / diagnostics
92. wa7son Traceable Applications
93. wa7son Traceable Applications • Bad: • Async/await + thenables • Challenges: • Userland callback queue • Custom protocols, message queues etc • Storing all data
94. wa7son Tracer friendly Node.js modules
95. wa7son Tracer friendly Node.js modules • Bad: • Userland callback queue • Async/await + thenables • Want: • Hooks
96. wa7son •Move server communication to worker thread? •Core context propagation API? •Core tracer API?
97. wa7son
98. @wa7son github.com/watson Go raibh maith agat