Add profiling tooling

See the README.md for details

.eslintignore

@@ -4,3 +4,4 @@ docs
 out
 node_modules
 versions
+acmeair-nodejs

.gitignore

@@ -113,3 +113,4 @@ prebuilds.*
 docs/test.js
 !packages/*/test/**/node_modules
 dist
+acmeair-nodejs

benchmark/e2e/README.md

@@ -0,0 +1,60 @@
+# End-to-End Benchmarking
+
+The purpose of this folder is to be able to test the overhead of dd-trace on an
+application. The primary focus here is on easily measurable metrics like
+latency, RPS and throughput.
+
+We're using a sample app called AcmeAir, which is used by Node.js to benchmark
+itself (results are at <https://benchmarking.nodejs.org/>). Load is produced
+with [autocannon](https://npm.im/autocannon), which also gives us results. We
+test with and without the tracer to get a measure of overhead. We test using two
+separate endpoints that are measured independently, to get a measure of worst
+case (a static landing page) and a more realistic case (a DB call is done).
+
+## Requirements
+
+This test should work with all versions of Node.js supported by dd-trace. In
+addition, the sample app uses MongoDB, so you'll have to have that running and
+listening on the default port. If you're set up with the `docker-compose.yml` in
+the root of this repo, you should be ready.
+
+## Usage
+
+To start the test, run `node test` in this directory. This will install AcmeAir
+if it hasn't yet been installed, and populate MongoDB if that hasn't already
+been done.
+
+Next, it will run the test for 10 seconds each on each of the 2 endpoints, both
+with and without the tracer loaded. That means 40 seconds of testing. Results
+will appear on stdout.
+
+You can change the duration of the tests by setting the `DURATION` environment
+variable to the number of seconds to run. Keep in mind that this will be run 4
+times, so if you set it to `60`, you'll have to wait 4 minutes before it's done.
+
+### Profiling, Method 1
+
+To profile the app, the easiest thing to do is set the `PROF` environment
+variable to a truthy string. This adds `--prof` to the node processes, which
+writes a file called `isolate-0x${SOMEHEX}-${PID}-v8.log` for each of the 4
+tests. You can then use `node --prof-process` or a tool like
+[pflames](https://npm.im/pflames) to view the profile data.
+
+### Profiling, Method 2
+
+You can run the app manually, using a tool like [0x](https://npm.im/0x) to get
+profiling data. To do that, you'll need to run the fake agent (`node
+fake-agent.js`) and run the app using `datadog.js` as a pre-require. You'll also
+need to set `DD_ENABLE=1`, which is the switch used to turn on tracing for the
+test script (leave it off to get a non-traced baseline).
+
+For example, you might use a shell script like this:
+
+```
+node fake-agent.js > /dev/null &
+FAKE_AGENT_PID=$!
+cd acmeair-nodejs
+DD_ENABLE=1 0x -P 'autocannon http://localhost:$PORT/' -- node -r ../datadog.js app.js
+# Ctrl-C when it's done
+kill $FAKE_AGENT_PID
+```

benchmark/e2e/datadog.js

@@ -0,0 +1,11 @@
+'use strict'
+
+if (process.env.DD_ENABLE) {
+  const tracer = require('../..').init({})
+}
+const { Server } = require('http')
+const origEmit = Server.prototype.emit
+Server.prototype.emit = function (name) {
+  if (name === 'listening') { process.send && process.send({ ready: true }) }
+  return origEmit.apply(this, arguments)
+}

benchmark/e2e/fake-agent.js

@@ -0,0 +1,33 @@
+'use strict'
+const fs = require('fs')
+const http = require('http')
+const msgpack = require('msgpack-lite')
+const codec = msgpack.createCodec({ int64: true })
+
+const output = fs.createWriteStream(`./spans.nsjson`)
+
+const agent = http.createServer((req, res) => {
+  concatStream(req, body => {
+    if (body.length === 0) return res.status(200).send()
+    body = msgpack.decode(body, { codec })
+    body.forEach(trace => {
+      trace.forEach(span => {
+        output.write(JSON.stringify(span) + '\n')
+      })
+    })
+    res.statusCode = 200
+    res.end(JSON.stringify({ rate_by_service: { 'service:,env:': 1 } }))
+  })
+})
+
+agent.listen(8126, () => {
+  process.send({ ready: true })
+})
+agent.on('close', () => output.close())
+
+function concatStream (strm, cb) {
+  const bufs = []
+  strm
+    .on('data', data => bufs.push(data))
+    .on('end', () => cb(Buffer.concat(bufs)))
+}

benchmark/e2e/spans-to-dot.js

@@ -0,0 +1,77 @@
+'use strict'
+
+const { spawn } = require('child_process')
+
+const outputFormat = process.argv[2]
+
+function shorten (data) {
+  if (data.length < 20) return data
+  return '...' + data.substring(data.length - 15)
+}
+
+function labelFor (span) {
+  let label = `${span.name}\\nresource: ${span.resource}\\nservice: ${span.service}`
+  for (const name in span.meta) {
+    label += `\\n${name}: ${shorten(span.meta[name])}`
+  }
+  return label
+}
+
+function concatStream (strm, cb) {
+  const bufs = []
+  strm
+    .on('data', data => bufs.push(data))
+    .on('end', () => cb(Buffer.concat(bufs)))
+}
+
+function parseSpan (span, traces) {
+  if (!traces[span.trace_id]) {
+    traces[span.trace_id] = []
+  }
+  traces[span.trace_id].push(span)
+}
+
+concatStream(process.stdin, stdin => {
+  const lines = stdin.toString('utf8').split('\n').filter(x => x).map(trace => {
+    try {
+      return JSON.parse(trace.replace(/^Encoding trace: /, ''))
+    } catch (e) {
+      return null
+    }
+  }).filter(x => x)
+
+  const traces = {}
+
+  for (const trace of lines) {
+    if (!Array.isArray(trace)) {
+      parseSpan(trace, traces)
+    } else {
+      for (const span of trace) {
+        parseSpan(span, traces)
+      }
+    }
+  }
+
+  const dotTraces = []
+  for (const traceId in traces) {
+    const dotStatements = []
+    const linearTrace = traces[traceId]
+    for (const span of linearTrace) {
+      dotStatements.push(`span_${span.span_id} [label = "${labelFor(span)}"]`)
+      if (span.parent_id !== 0) {
+        dotStatements.push(`span_${span.parent_id} -> span_${span.span_id}`)
+      }
+    }
+    dotTraces.push([`subgraph trace_${traceId} {`, ...dotStatements, '}'].join('\n'))
+  }
+  const dotSource = `
+digraph TRACES {
+node [shape=record]
+rankdir=LR
+
+${dotTraces.join('\n')}
+}
+  `.trim()
+  const dotProc = spawn('dot', [`-T${outputFormat || 'svg'}`], { stdio: ['pipe', 'inherit', 'inherit'] })
+  dotProc.stdin.end(dotSource)
+})

benchmark/e2e/test.js

@@ -0,0 +1,171 @@
+'use strict'
+
+/* eslint-disable no-console */
+
+const { spawn, fork } = require('child_process')
+const { promisify } = require('util')
+const { stat } = require('fs')
+const { get: _get } = require('http')
+const path = require('path')
+const mongoService = require('../../packages/dd-trace/test/setup/services/mongo')
+const autocannon = require('autocannon')
+
+function cd (dir) {
+  console.log('> cd', dir)
+  process.chdir(dir)
+}
+
+function delay (ms) {
+  return new Promise((resolve, reject) => {
+    setTimeout(resolve, ms)
+  })
+}
+
+function sh (cmd) {
+  return new Promise((resolve, reject) => {
+    console.log('>', cmd)
+    spawn(cmd, [], { stdio: 'inherit', shell: true })
+      .on('error', reject)
+      .on('close', resolve)
+  })
+}
+
+function forkProcess (file, options = {}) {
+  return new Promise((resolve, reject) => {
+    console.log(`> node ${options.execArgv ? options.execArgv.join(' ') + ' ' : ''}${file}`)
+    options.stdio = 'pipe'
+    const subProcess = fork(file, options)
+    console.log('>> PID', subProcess.pid)
+    subProcess.on('message', message => {
+      if (message.ready) {
+        resolve({ subProcess })
+      }
+    })
+  })
+}
+
+const statAsync = promisify(stat)
+async function exists (filename) {
+  try {
+    const stats = await statAsync(filename)
+    return stats.isDirectory() || stats.isFile()
+  } catch (e) {
+    return false
+  }
+}
+
+function get (url) {
+  return new Promise((resolve, reject) => {
+    _get(url, res => {
+      const chunks = []
+      res.on('data', d => chunks.push(d))
+      res.on('end', () => {
+        resolve(Buffer.concat(chunks).toString())
+      })
+    })
+  })
+}
+
+async function checkDb () {
+  console.log('# checking that db is populated')
+  cd('acmeair-nodejs')
+  const { subProcess } = await forkProcess('./app.js', {
+    execArgv: process.execArgv.concat(['--require', '../datadog.js'])
+  })
+
+  const customers = await get('http://localhost:9080/rest/api/config/countCustomers')
+
+  if (parseInt(customers) < 10000) {
+    console.log('# populating db')
+    await get('http://localhost:9080/rest/api/loader/load?numCustomers=10000')
+  }
+
+  subProcess.kill()
+  cd(__dirname)
+}
+
+async function ensureAppIsInstalled () {
+  cd(__dirname)
+  if (!(await exists(path.join(__dirname, 'acmeair-nodejs')))) {
+    await sh('git clone git@github.com:acmeair/acmeair-nodejs.git')
+  }
+  if (!(await exists(path.join(__dirname, 'acmeair-nodejs', 'node_modules')))) {
+    cd('acmeair-nodejs')
+    await sh('npm install')
+    cd(__dirname)
+  }
+}
+
+function runTest (url, duration) {
+  return autocannon({ url, duration })
+}
+
+async function testBoth (url, duration, prof) {
+  cd(__dirname)
+  const { subProcess: agentProcess } = await forkProcess('./fake-agent.js')
+  cd('acmeair-nodejs')
+  const execArgv = ['--require', '../datadog.js']
+  if (prof) {
+    execArgv.unshift('--prof')
+  }
+  const { subProcess: airProcess } = await forkProcess('./app.js', {
+    execArgv: execArgv.concat(process.execArgv),
+    env: Object.assign({}, process.env, { DD_ENABLE: '1' })
+  })
+
+  await delay(2000)
+
+  const resultWithTracer = await runTest(url, duration)
+
+  airProcess.kill()
+  agentProcess.kill()
+
+  const { subProcess: airProcess2 } = await forkProcess('./app.js', {
+    execArgv: execArgv.concat(process.execArgv)
+  })
+
+  const resultWithoutTracer = await runTest(url, duration)
+
+  airProcess2.kill()
+
+  console.log(`>>>>>> RESULTS FOR ${url} RUNNING FOR ${duration} SECONDS`)
+
+  logResult(resultWithoutTracer, resultWithTracer, 'requests')
+  logResult(resultWithoutTracer, resultWithTracer, 'latency')
+  logResult(resultWithoutTracer, resultWithTracer, 'throughput')
+
+  console.log(`<<<<<< RESULTS FOR ${url} RUNNING FOR ${duration} SECONDS`)
+}
+
+function pad (str, num) {
+  return Array(num - String(str).length).fill(' ').join('') + str
+}
+
+function logResult (resultWithoutTracer, resultWithTracer, type) {
+  console.log(`\n${type.toUpperCase()}:`)
+  console.log(`                without tracer     with tracer`)
+  for (const name in resultWithoutTracer[type]) {
+    console.log(
+      pad(name, 7),
+      `\t${pad(resultWithoutTracer[type][name], 14)}`,
+      `\t${pad(resultWithTracer[type][name], 14)}`
+    )
+  }
+}
+
+async function main () {
+  const duration = process.env.DURATION ? parseInt(process.env.DURATION) : 10
+  const prof = !!process.env.PROF
+  await ensureAppIsInstalled()
+  console.log('# checking that mongo is alive')
+  await mongoService()
+  console.log('# it is alive')
+  await checkDb()
+  await testBoth('http://localhost:9080/', duration, prof)
+  await testBoth('http://localhost:9080/rest/api/config/countCustomers', duration, prof)
+}
+
+main().catch(e => {
+  console.error(e)
+  process.exitCode = 1
+})

package.json

@@ -82,6 +82,7 @@
   "devDependencies": {
     "@babel/core": "^7.6.4",
     "@babel/preset-env": "^7.6.3",
+    "autocannon": "^4.5.2",
     "axios": "^0.18.0",
     "babel-loader": "^8.0.6",
     "benchmark": "^2.1.4",