Merge pull request #99 from davidmarkclements/prof-viz

--prof-viz extra flame graph based on v8 prof data

changelog.md

@@ -1,3 +1,7 @@
+# v3.3.0
+* introduce experimental `--prof-viz` flag, generates additional flamegraph based on internal v8 profiling data
+* linux fixes & tidy up
+
 # v3.2.0
 * introduce `--phase` option
 * change `--delay` from `300` to `0` - not a breaking change 

cli-schema.json

@@ -140,6 +140,12 @@
     "collectOnly": {
       "type": "boolean"
     },
+    "prof-viz": {
+      "type": "boolean"
+    },
+    "profViz": {
+      "type": "boolean"
+    },
     "--": {
       "type": "array",
       "items": {}

cmd.js

@@ -28,7 +28,7 @@ function cmd (argv, banner = defaultBanner) {
     boolean: [
       'open', 'version', 'help', 'quiet', 
       'silent', 'jsonStacks', 'svg', 'traceInfo',
-      'collectOnly', 'timestampProfiles'
+      'collectOnly', 'timestampProfiles', 'profViz'
     ],
     alias: {
       silent: 's',
@@ -49,14 +49,20 @@ function cmd (argv, banner = defaultBanner) {
       jsonStacks: 'json-stacks',
       logOutput: 'log-output',
       visualizeOnly: 'visualize-only',
-      collectOnly: 'collect-only'
+      collectOnly: 'collect-only',
+      profViz: 'prof-viz'
     },
     default: {
       delay: 0,
       phase: 2
     }
   })
 
+  if (args.profViz && process.version.substr(0, 3) === 'v6.') {
+    console.error('0x: The --prof-viz flag is only supported in Node 8 and above')
+    process.exit(1)
+  }
+
   args.name = args.name || (args.gen ? '-' : 'flamegraph')
 
   if (ajv.validate(schema, args) === false) {

lib/prof-log-convert.js

@@ -0,0 +1,61 @@
+'use strict'
+
+const { spawnSync } = require('child_process')
+const fs = require('fs')
+const { join, basename } = require('path')
+const through = require('through2')
+
+
+module.exports = profLogConvert
+
+function profLogConvert ({isolateLogPath, pid, folder, stream}, args) {
+  const { stdout, stderr, status } = spawnSync('node', ['--prof-process', '--preprocess', '-j', isolateLogPath])
+
+  if (status !== 0) {
+    args.log('prof isolateLogPath convert Failed: ', stderr + '', stdout + '')
+    return
+  }
+  const json = isolateLogPath + '.json'
+  fs.writeFileSync(json, stdout)
+  const data = require(json)
+
+  data.ticks.forEach((tick, i) => {
+    // tick.ms = Math.round(tick.tm / 1000)
+    const addr = tick.s.filter((n, i) => i % 2 === 0)
+    const offsets = tick.s.filter((n, i) => i % 2 === 1)
+    tick.stack = addr.map((n, i) => data.code[n]).filter(Boolean)
+    tick.stack = tick.stack.filter(({type}) => type === 'JS')
+    if (tick.stack.length === 0) {
+      data.ticks[i] = undefined
+      return
+    }
+  })
+
+  data.ticks = data.ticks.filter(Boolean)
+
+  const proc = 'node'
+  const profName = 'v8-perf-1ms'
+  const space = '              '
+
+  // we want the final (un)optimized compute state of the frame
+  // so go and find any frames that eventually get optimized
+  const optimized = new Set()   
+  data.ticks.forEach((tick) => {
+    tick.stack.forEach(({ name, kind }) => {
+      if (kind === 'Opt') optimized.add(name)
+    })
+  })
+
+  data.ticks.forEach((tick) => {
+    stream.write(`${proc} ${pid} ${tick.tm}: ${profName}:\n`)
+    stream.write(tick.stack.map(({name}) => {
+      if (!name) return 'UKNOWN'
+      const prefix = optimized.has(name) ? '*' : '~'
+      if (name[0] === ' ') name = '(anonymous)' + name
+      return space + prefix + name
+    }).join('\n'))
+    stream.write('\n\n')
+  })
+  stream.end('\n')
+
+}

lib/stack-convert.js

@@ -65,14 +65,11 @@ Profile.prototype.openStack = function (name) {
 
 Profile.prototype.addFrame = function (frame) {
   if (!this.stack) this.stack = []
-  frame = frame.replace(/^\s+/, '').replace(/\s+$/, '')
+  frame = frame.trim()
   if (!frame.length) return
-
   this.stack.unshift(
     frame
-      .replace(/^\w+ /, '')
-      .replace(/ \(\S+\)$/, '')
-      .replace(/(..)[(<].*/, '$1')
+      .replace(/^\w+ /, '') // removes the hex address in linux stacks, works in dtrace and v8 prof stacks because first word always has symbols
   )
 }
 

lib/util.js

@@ -1,8 +1,9 @@
 'use strict'
 
+const { EventEmitter } = require('events')
 const fs = require('fs')
 const path = require('path')
-const spawn = require('child_process').spawn
+const { spawn } = require('child_process')
 const which = require('which')
 const pump = require('pump')
 const pumpify = require('pumpify')
@@ -12,10 +13,12 @@ const convert = require('./stack-convert')
 const browserify = require('browserify')
 const multistream = require('multistream')
 const concat = require('concat-stream')
+const eos = require('end-of-stream')
 const gen = require('./gen')
 const debug = require('debug')('0x')
 const sll = require('single-line-log')
 const launch = require('opn')
+const profLogConvert = require('./prof-log-convert')
 
 const phases = [
   (frames) => frames,
@@ -40,7 +43,6 @@ const phases = [
 module.exports = {
   determineOutputDir: determineOutputDir,
   ensureDirExists: ensureDirExists,
-  stackLine: stackLine,
   stacksToFlamegraphStream: stacksToFlamegraphStream,
   tidy: tidy,
   pathTo: pathTo,
@@ -50,9 +52,52 @@ module.exports = {
   noop: noop,
   createLoggers: createLoggers,
   stacksToFlamegraph,
-  phases
+  phases,
+  v8ProfFlamegraph
 }
 
+function v8ProfFlamegraph (args, {folder, pid}, cb) {
+  const { log } = args
+  debug('moving isolate file into folder')
+  const isolateLog = fs.readdirSync(args.workingDir)
+    .find(function (f) {
+      return new RegExp(`isolate-(0x[0-9A-Fa-f]{2,12})-${pid}-v8.log`).test(f)
+    })
+
+  if (!isolateLog) {
+    log('0x: profViz fail: no isolate logfile found')
+    return
+  }
+
+  const isolateLogPath = path.join(folder, isolateLog)
+
+  fs.renameSync(path.join(args.workingDir, isolateLog), isolateLogPath)
+  const stacksOut = path.join(folder, 'v8-prof-stacks.' + pid + '.out')
+  const stream = fs.createWriteStream(stacksOut)
+  profLogConvert({pid, isolateLogPath, stream}, args)
+  stream.on('finish', () => {
+    const fg = fs.openSync(path.join(folder, 'v8-prof-' + path.basename(determineHtmlPath(args, {pid, folder}))), 'w')
+    // the stdout pipe, redirect to a file works though
+    const sp = spawn(
+      process.argv[0], 
+      [path.join(__dirname, '..', 'cmd.js'), '-g', stacksOut, '--title', args.title],
+      {
+        stdio: [
+          'ignore',
+          fg,     // can't pipe to a write stream,  spawn seems to hit a data limit on 
+          'inherit' // handy for debug output 
+        ]
+      }
+    )
+
+    sp.on('exit', () => {
+      if (cb) cb()
+    }) 
+  })
+
+}
+
+
 function createLoggers (args) {
   const { io = {} } = args
   const logStream = io.logStream || process.stderr
@@ -112,44 +157,14 @@ function ensureDirExists (path) {
   }
 }
 
-function stackLine (stacks, delay) {
-  if (!delay) {
-    return pump(stacks.stdout, split())
-  }
-
-  var start
-  var pastDelay
-
-  return pump(
-    stacks.stdout,
-    split(),
-    through(function (line, enc, cb) {
-      var diff
-      line += ''
-      if (/cpu-clock:/.test(line)) {
-        if (!start) {
-          start = parseInt(parseFloat(line.match(/[0-9]+\.[0-9]+:/)[0], 10) * 1000, 10)
-        } else {
-          diff = parseInt(parseFloat(line.match(/[0-9]+\.[0-9]+:/)[0], 10) * 1000, 10) - start
-          pastDelay = (diff > delay)
-        }
-      }
-      if (pastDelay) {
-        cb(null, line + '\n')
-      } else {
-        cb()
-      }
-    })
-  )
-}
-
-function stacksToFlamegraph (args, cb) {
+function stacksToFlamegraph (args) {
   const { ee, log } = args
   args.name = args.name || '-'
   const opts = {
     pid: args.pid, 
     folder: path.join(args.workingDir, path.dirname(args.gen))
   }
+  debug('STACKS TO FLAMEGRAPH', args.gen)
   return fs.createReadStream(args.gen)
     .pipe(stacksToFlamegraphStream(args, opts, function () {
       debug('flamegraph generated')

package.json

@@ -1,6 +1,6 @@
 {
   "name": "0x",
-  "version": "3.2.0",
+  "version": "3.3.0-rc5",
   "description": "🔥 single-command flamegraph profiling 🔥",
   "main": "index.js",
   "bin": "./cmd.js",

platform/linux.js

@@ -4,16 +4,17 @@ const path = require('path')
 const spawn = require('child_process').spawn
 const pump = require('pump')
 const split = require('split2')
+const through = require('through2')
 const debug = require('debug')('0x')
 
 const {
   determineOutputDir,
   ensureDirExists,
-  stackLine,
   stacksToFlamegraphStream,
   tidy,
   pathTo,
-  notFound
+  notFound,
+  v8ProfFlamegraph
 } = require('../lib/util')
 
 module.exports = linux
@@ -50,10 +51,11 @@ function linux (args, sudo, binary) {
     perfdat,
     '--',
     node,
+    ...(args.profViz ? ['--prof', `--logfile=${uid}-v8.log`] : []),
     '--perf-basic-prof',
     '-r', path.join(__dirname, '..', 'lib', 'soft-exit')
   ].filter(Boolean).concat(args.argv), {
-    stdio: 'inherit'
+    stdio: ['ignore', 'inherit', 'inherit']
   }).on('exit', function (code) {
     if (code !== null && code !== 0 && code !== 143 && code !== 130) {
       tidy(args)
@@ -83,28 +85,71 @@ function linux (args, sudo, binary) {
 
     if (!manual) {
       debug('Caught SIGINT, generating flamegraph')
-      status('Caught SIGINT, generating flamegraph ')
+      status('Caught SIGINT, generating flamegraph')
+      proc.on('exit', generate)
+    } else {
+      debug('Process exited, generating flamegraph')
+      status('Process exited, generating flamegraph')
+      generate()
     }
 
-    proc.on('exit', function () {
-      var stacks = spawn('sudo', ['perf', 'script', '-i', perfdat])
-
-      if (traceInfo) { stacks.stderr.pipe(process.stderr) }
-      var stacksOut = stackLine(stacks, delay)
-      pump(
-        stacksOut,
-        fs.createWriteStream(folder + '/stacks.' + proc.pid + '.out')
-      )
-      stacks.on('exit', function () {
-        pump(
-          fs.createReadStream(folder + '/stacks.' + proc.pid + '.out'),
-          stacksToFlamegraphStream(args, {pid: proc.pid, folder}, null, () => status(''))
-        )
-      })
-    })
+    function generate () {
+      if (args.profViz) v8ProfFlamegraph(args, {pid: uid, folder}, next)
+      else next()
+
+      function next() {
+
+        var stacks = spawn('sudo', ['perf', 'script', '-i', perfdat], {
+          stdio: [
+            'ignore', 
+            fs.openSync(folder + '/stacks.' + proc.pid + '.out', 'w'),
+            traceInfo ? process.stderr : 'ignore'
+          ]
+        })
+
+        stacks.on('exit', function () {
+          if (delay > 0) {
+            pump(
+              fs.createReadStream(folder + '/stacks.' + proc.pid + '.out'),
+              filterBeforeDelay(delay),
+              stacksToFlamegraphStream(args, {pid: proc.pid, folder}, null, () => status(''))
+            )
+          } else {
+            pump(
+              fs.createReadStream(folder + '/stacks.' + proc.pid + '.out'),
+              stacksToFlamegraphStream(args, {pid: proc.pid, folder}, null, () => status(''))
+            )
+          }
+        })
+      }
+    }
 
     spawn('sudo', ['kill', '-SIGINT', '' + proc.pid], {
       stdio: 'inherit'
     })
   }
 }
+
+
+function filterBeforeDelay (delay) {
+  var start
+  var pastDelay
+
+  return through(function (line, enc, cb) {
+    var diff
+    line += ''
+    if (/cpu-clock:/.test(line)) {
+      if (!start) {
+        start = parseInt(parseFloat(line.match(/[0-9]+\.[0-9]+:/)[0], 10) * 1000, 10)
+      } else {
+        diff = parseInt(parseFloat(line.match(/[0-9]+\.[0-9]+:/)[0], 10) * 1000, 10) - start
+        pastDelay = (diff > delay)
+      }
+    }
+    if (pastDelay) {
+      cb(null, line + '\n')
+    } else {
+      cb()
+    }
+  })
+}