prof-viz

changelog.md

@@ -1,3 +1,6 @@
+# v3.3.0
+* introduce experimental `--prof-viz` flag, generates additional flamegraph based on internal v8 profiling data
+
 # 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,7 +49,8 @@ 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,

lib/prof-log-convert.js

@@ -0,0 +1,51 @@
+'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 + 1]).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 = '              '
+
+  data.ticks.forEach((tick) => {
+    stream.write(`${proc} ${pid} ${tick.tm}: ${profName}:\n`)
+    stream.write(tick.stack.map(({name}) => {
+      if (!name) return 'UKNOWN'
+      if (name[0] === ' ') name = '(anonymous)' + name
+      return space + name
+    }).join('\n'))
+    stream.write('\n\n')
+  })
+  stream.end('\n')
+
+}

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, spawnSync } = 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,
@@ -50,9 +53,52 @@ module.exports = {
   noop: noop,
   createLoggers: createLoggers,
   stacksToFlamegraph,
-  phases
+  phases,
+  extraProfFlamegraph
 }
 
+function extraProfFlamegraph ({folder, pid}, args, cb) {
+  const { log } = args
+  debug('moving isolate file into folde')
+  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],
+      {
+        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
@@ -143,13 +189,14 @@ function stackLine (stacks, delay) {
   )
 }
 
-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')

platform/linux.js

@@ -50,6 +50,7 @@ function linux (args, sudo, binary) {
     perfdat,
     '--',
     node,
+    ...(args.profViz ? ['--prof', '--logfile=%p-v8.log'] : []),
     '--perf-basic-prof',
     '-r', path.join(__dirname, '..', 'lib', 'soft-exit')
   ].filter(Boolean).concat(args.argv), {

platform/sun.js

@@ -13,7 +13,8 @@ const {
   stacksToFlamegraphStream,
   tidy,
   pathTo,
-  notFound
+  notFound,
+  extraProfFlamegraph
 } = require('../lib/util')
 
 module.exports = sun
@@ -39,6 +40,11 @@ function sun (args, sudo, binary) {
     '-r', path.join(__dirname, '..', 'lib', 'soft-exit')
   ].concat(args.argv), args)
 
+  if (args.profViz) {
+    args.unshift('--prof')
+    args.unshift('--logfile=%p-v8.log')    
+  }
+
   var proc = spawn(node, args, {
     stdio: 'inherit'
   }).on('exit', function (code) {
@@ -133,32 +139,37 @@ function sun (args, sudo, binary) {
         }
         return
       }
-
-      var translate = sym({silent: true, pid: proc.pid})
-
-      if (!translate) {
-        debug('unable to find map file')
-        if (attempts) {
-          status('Unable to find map file - waiting 300ms and retrying\n')
-          debug('retrying')
-          setTimeout(capture, 300, attempts--)
+      if (args.profViz) extraProfFlamegraph({folder, pid: proc.pid}, args)
+      // else next()
+      function next () { 
+        var translate = sym({silent: true, pid: proc.pid})
+
+        if (!translate) {
+          debug('unable to find map file')
+          if (attempts) {
+            status('Unable to find map file - waiting 300ms and retrying\n')
+            debug('retrying')
+            setTimeout(capture, 300, attempts--)
+            return
+          }
+          status('Unable to find map file!\n')
+          debug('Unable to find map file after multiple attempts')
+          tidy(args)
+          ee.emit('error', Error('0x: Unable to find map file'))
           return
         }
-        status('Unable to find map file!\n')
-        debug('Unable to find map file after multiple attempts')
-        tidy(args)
-        ee.emit('error', Error('0x: Unable to find map file'))
-        return
+        pump(
+          fs.createReadStream(folder + '/.stacks.' + proc.pid + '.out'),
+          translate,
+          fs.createWriteStream(folder + '/stacks.' + proc.pid + '.out')
+        )
+        pump(
+          translate,
+          stacksToFlamegraphStream(args, {pid: proc.pid, folder}, null, () => {
+            status('')
+          })
+        )
       }
-      pump(
-        fs.createReadStream(folder + '/.stacks.' + proc.pid + '.out'),
-        translate,
-        fs.createWriteStream(folder + '/stacks.' + proc.pid + '.out')
-      )
-      pump(
-        translate,
-        stacksToFlamegraphStream(args, {pid: proc.pid, folder}, null, () => status(''))
-      )
     }
   }
 }

readme.md

@@ -220,6 +220,16 @@ outputs to a file `{name}.html` in the current folder.
 Generates an `flamegraph.svg` file in the artifact output directory,
 in addition to the `flamegraph.html` file.
 
+### --prof-viz
+
+Experimental. Create an additional flame graph using
+log output when from the V8 `--prof`. This will create 
+an additional flamegraph named according to the 
+`--name` flag, prefixed with `v8-prof-`. If `--name` 
+is set to - then flamegraph HTML will be streamed to STDOUT.
+
+Default: false 
+
 ### --phase
 
 Stage in initialization to begin aggregating stacks. 
@@ -359,6 +369,11 @@ The Profile Folder can contain the following files
 * stacks.3866.out - the traced stacks (run through [perf-sym](http://npmjs.com/perf-sym) on OS X)
 * flamegraph.html - the interactive flamegraph
 * stacks.3866.json - a JSON tree generated from the stacks, enabled with `--json-stacks`
+* isolate-0x103000600-3866-v8.log - a v8 profiling log file, only included when `--prof-viz` is enabled 
+* isolate-0x103000600-3866-v8.log.json - v8 profiling log file processed into JSON using v8s internal tick processor, only included when `--prof-viz` is enabled
+* v8-prof-stacks.77801.out - a generated stacks file based on v8 profiling data, only included when `--prof-viz` is enabled
+* v8-prof-flamegraph.html - an alternartive flamegraph that only shows JS stacks based on v8's profiling data, only included when `--prof-viz` is enabled 
+
 
 The is helpful, because there's other things you can do with
 stacks output. For instance, checkout [cpuprofilify](http://npmjs.com/cpuprofilify) and [traceviewify](http://npmjs.com/traceviewify).
@@ -500,6 +515,10 @@ See [`--output-html`](#--output-html---f)
 
 See [`--title`](#--title)
 
+### `profViz`
+
+See [`--prof-viz`](#--prof-viz)
+
 #### `phase` (number)
 
 See [`--phase`](#--phase)

usage.txt

@@ -14,6 +14,13 @@
   --open | -o             Automatically open after finishing
                           Default: false
 
+  --prof-viz              Experimental. Create an additional flame graph using
+                          log output when from the V8 --prof. This will create 
+                          an additional flamegraph named according to the 
+                          --name flag, prefixed with v8-prof-. If --name 
+                          is set to - then flamegraph HTML will be streamed
+                          to STDOUT. 
+
   --phase                 Stage in initialization to begin aggregating
                           stacks. Phase 0 visualizes from the very start,
                           this includes bootstrapping stacks and loading