Import from node profiles via v8 logs (#98)

This is inspired by https://github.com/mapbox/flamebearer
2018-07-21 16:00:25 -07:00
parent fb5d148780
commit ea8f982c10
12 changed files with 3038 additions and 22 deletions
@@ -1,3 +1,9 @@
+## [Unreleased]
+
+### Added
+
+* Support for importing v8 logs from node
+
 ## [0.3.0] - 2018-07-18

 ### Added
@@ -31,6 +31,21 @@ https://medium.com/@paul_irish/debugging-node-js-nightlies-with-chrome-devtools-

 The `profile.json` file format output by Firefox can be saved and import into speedscope: https://developer.mozilla.org/en-US/docs/Tools/Performance

+### Node
+
+If you record profiling information like so:
+
+    node --prof /path/to/my/script.js
+
+Then this will generate a bunch of `isolate*.log` files. Process one of them
+into usable JSON like so:
+
+    node --prof-process -preprocess -j isolate*.log > profile.v8log.json
+
+Then drop the resulting `profile.v8log.json` file into speedscope, or run
+
+    speedscope profile.v8log.json
+
 ### Instruments.app

 You can import call trees from OSX Instruments.app into speedscope by
@@ -0,0 +1,260 @@
+// Jest Snapshot v1, https://goo.gl/fbAQLP
+
+exports[`importFromV8ProfLog 1`] = `
+Object {
+  "frames": Array [
+    Frame {
+      "col": 10,
+      "file": "bootstrap_node.js",
+      "key": " bootstrap_node.js:10:10",
+      "line": 10,
+      "name": "(anonymous)",
+      "selfWeight": 0,
+      "totalWeight": 116424,
+    },
+    Frame {
+      "col": 19,
+      "file": "bootstrap_node.js",
+      "key": "startup bootstrap_node.js:12:19",
+      "line": 12,
+      "name": "startup",
+      "selfWeight": 0,
+      "totalWeight": 116424,
+    },
+    Frame {
+      "col": 32,
+      "file": "bootstrap_node.js",
+      "key": "setupGlobalVariables bootstrap_node.js:265:32",
+      "line": 265,
+      "name": "setupGlobalVariables",
+      "selfWeight": 0,
+      "totalWeight": 29385,
+    },
+    Frame {
+      "col": 34,
+      "file": "bootstrap_node.js",
+      "key": "NativeModule.require bootstrap_node.js:534:34",
+      "line": 534,
+      "name": "NativeModule.require",
+      "selfWeight": 0,
+      "totalWeight": 52273,
+    },
+    Frame {
+      "col": 44,
+      "file": "bootstrap_node.js",
+      "key": "NativeModule.compile bootstrap_node.js:602:44",
+      "line": 602,
+      "name": "NativeModule.compile",
+      "selfWeight": 0,
+      "totalWeight": 52273,
+    },
+    Frame {
+      "col": 11,
+      "file": "util.js",
+      "key": " util.js:1:11",
+      "line": 1,
+      "name": "(anonymous)",
+      "selfWeight": 0,
+      "totalWeight": 29385,
+    },
+    Frame {
+      "col": 11,
+      "file": "internal/encoding.js",
+      "key": " internal/encoding.js:1:11",
+      "line": 1,
+      "name": "(anonymous)",
+      "selfWeight": 0,
+      "totalWeight": 29385,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "(c++) v8::internal::Runtime_CreateArrayLiteral",
+      "line": undefined,
+      "name": "(c++) v8::internal::Runtime_CreateArrayLiteral",
+      "selfWeight": 0,
+      "totalWeight": 29385,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "(c++) v8::internal::JSFunction::EnsureHasInitialMap",
+      "line": undefined,
+      "name": "(c++) v8::internal::JSFunction::EnsureHasInitialMap",
+      "selfWeight": 29385,
+      "totalWeight": 29385,
+    },
+    Frame {
+      "col": 30,
+      "file": "bootstrap_node.js",
+      "key": "setupGlobalConsole bootstrap_node.js:320:30",
+      "line": 320,
+      "name": "setupGlobalConsole",
+      "selfWeight": 0,
+      "totalWeight": 22888,
+    },
+    Frame {
+      "col": 40,
+      "file": "bootstrap_node.js",
+      "key": "setupInspectorCommandLineAPI bootstrap_node.js:364:40",
+      "line": 364,
+      "name": "setupInspectorCommandLineAPI",
+      "selfWeight": 0,
+      "totalWeight": 22888,
+    },
+    Frame {
+      "col": 11,
+      "file": "module.js",
+      "key": " module.js:1:11",
+      "line": 1,
+      "name": "(anonymous)",
+      "selfWeight": 0,
+      "totalWeight": 22888,
+    },
+    Frame {
+      "col": 11,
+      "file": "fs.js",
+      "key": " fs.js:1:11",
+      "line": 1,
+      "name": "(anonymous)",
+      "selfWeight": 0,
+      "totalWeight": 22888,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "(c++) v8::internal::Runtime_StoreIC_Miss",
+      "line": undefined,
+      "name": "(c++) v8::internal::Runtime_StoreIC_Miss",
+      "selfWeight": 0,
+      "totalWeight": 22888,
+    },
+    Frame {
+      "col": undefined,
+      "file": undefined,
+      "key": "(c++) v8::internal::Map::RawCopy",
+      "line": undefined,
+      "name": "(c++) v8::internal::Map::RawCopy",
+      "selfWeight": 22888,
+      "totalWeight": 22888,
+    },
+    Frame {
+      "col": 26,
+      "file": "module.js",
+      "key": "Module.runMain module.js:663:26",
+      "line": 663,
+      "name": "Module.runMain",
+      "selfWeight": 0,
+      "totalWeight": 64151,
+    },
+    Frame {
+      "col": 24,
+      "file": "module.js",
+      "key": "Module._load module.js:443:24",
+      "line": 443,
+      "name": "Module._load",
+      "selfWeight": 0,
+      "totalWeight": 64151,
+    },
+    Frame {
+      "col": 23,
+      "file": "module.js",
+      "key": "tryModuleLoad module.js:505:23",
+      "line": 505,
+      "name": "tryModuleLoad",
+      "selfWeight": 0,
+      "totalWeight": 64151,
+    },
+    Frame {
+      "col": 33,
+      "file": "module.js",
+      "key": "Module.load module.js:536:33",
+      "line": 536,
+      "name": "Module.load",
+      "selfWeight": 0,
+      "totalWeight": 64151,
+    },
+    Frame {
+      "col": 37,
+      "file": "module.js",
+      "key": "Module._extensions..js module.js:633:37",
+      "line": 633,
+      "name": "Module._extensions..js",
+      "selfWeight": 0,
+      "totalWeight": 64151,
+    },
+    Frame {
+      "col": 37,
+      "file": "module.js",
+      "key": "Module._compile module.js:581:37",
+      "line": 581,
+      "name": "Module._compile",
+      "selfWeight": 0,
+      "totalWeight": 64151,
+    },
+    Frame {
+      "col": 11,
+      "file": "/Users/jlfwong/code/speedscope/sample/programs/javascript/simple.js",
+      "key": " /Users/jlfwong/code/speedscope/sample/programs/javascript/simple.js:1:11",
+      "line": 1,
+      "name": "(anonymous)",
+      "selfWeight": 0,
+      "totalWeight": 64151,
+    },
+    Frame {
+      "col": 73,
+      "file": "/Users/jlfwong/code/speedscope/sample/programs/javascript/simple.js",
+      "key": "a /Users/jlfwong/code/speedscope/sample/programs/javascript/simple.js:1:73",
+      "line": 1,
+      "name": "a",
+      "selfWeight": 0,
+      "totalWeight": 64151,
+    },
+    Frame {
+      "col": 11,
+      "file": "/Users/jlfwong/code/speedscope/sample/programs/javascript/simple.js",
+      "key": "b /Users/jlfwong/code/speedscope/sample/programs/javascript/simple.js:8:11",
+      "line": 8,
+      "name": "b",
+      "selfWeight": 10044,
+      "totalWeight": 53997,
+    },
+    Frame {
+      "col": 11,
+      "file": "/Users/jlfwong/code/speedscope/sample/programs/javascript/simple.js",
+      "key": "d /Users/jlfwong/code/speedscope/sample/programs/javascript/simple.js:20:11",
+      "line": 20,
+      "name": "d",
+      "selfWeight": 51562,
+      "totalWeight": 51562,
+    },
+    Frame {
+      "col": 11,
+      "file": "/Users/jlfwong/code/speedscope/sample/programs/javascript/simple.js",
+      "key": "c /Users/jlfwong/code/speedscope/sample/programs/javascript/simple.js:14:11",
+      "line": 14,
+      "name": "c",
+      "selfWeight": 2545,
+      "totalWeight": 10154,
+    },
+  ],
+  "stacks": Array [
+    "(anonymous);startup;setupGlobalVariables;NativeModule.require;NativeModule.compile;(anonymous);NativeModule.require;NativeModule.compile;(anonymous);(c++) v8::internal::Runtime_CreateArrayLiteral;(c++) v8::internal::JSFunction::EnsureHasInitialMap 29.38ms",
+    "(anonymous);startup;setupGlobalConsole;setupInspectorCommandLineAPI;NativeModule.require;NativeModule.compile;(anonymous);NativeModule.require;NativeModule.compile;(anonymous);(c++) v8::internal::Runtime_StoreIC_Miss;(c++) v8::internal::Map::RawCopy 22.89ms",
+    "(anonymous);startup;Module.runMain;Module._load;tryModuleLoad;Module.load;Module._extensions..js;Module._compile;(anonymous);a;b;d 37.52ms",
+    "(anonymous);startup;Module.runMain;Module._load;tryModuleLoad;Module.load;Module._extensions..js;Module._compile;(anonymous);a;c;d 1.28ms",
+    "(anonymous);startup;Module.runMain;Module._load;tryModuleLoad;Module.load;Module._extensions..js;Module._compile;(anonymous);a;b;d 2.55ms",
+    "(anonymous);startup;Module.runMain;Module._load;tryModuleLoad;Module.load;Module._extensions..js;Module._compile;(anonymous);a;c;d 1.27ms",
+    "(anonymous);startup;Module.runMain;Module._load;tryModuleLoad;Module.load;Module._extensions..js;Module._compile;(anonymous);a;b;d 1.28ms",
+    "(anonymous);startup;Module.runMain;Module._load;tryModuleLoad;Module.load;Module._extensions..js;Module._compile;(anonymous);a;c;d 1.27ms",
+    "(anonymous);startup;Module.runMain;Module._load;tryModuleLoad;Module.load;Module._extensions..js;Module._compile;(anonymous);a;b;d 1.29ms",
+    "(anonymous);startup;Module.runMain;Module._load;tryModuleLoad;Module.load;Module._extensions..js;Module._compile;(anonymous);a;c;d 1.26ms",
+    "(anonymous);startup;Module.runMain;Module._load;tryModuleLoad;Module.load;Module._extensions..js;Module._compile;(anonymous);a;b;d 1.31ms",
+    "(anonymous);startup;Module.runMain;Module._load;tryModuleLoad;Module.load;Module._extensions..js;Module._compile;(anonymous);a;c;d 2.52ms",
+    "(anonymous);startup;Module.runMain;Module._load;tryModuleLoad;Module.load;Module._extensions..js;Module._compile;(anonymous);a;c 1.27ms",
+    "(anonymous);startup;Module.runMain;Module._load;tryModuleLoad;Module.load;Module._extensions..js;Module._compile;(anonymous);a;b 3.62ms",
+    "(anonymous);startup;Module.runMain;Module._load;tryModuleLoad;Module.load;Module._extensions..js;Module._compile;(anonymous);a;c 1.28ms",
+    "(anonymous);startup;Module.runMain;Module._load;tryModuleLoad;Module.load;Module._extensions..js;Module._compile;(anonymous);a;b 6.42ms",
+  ],
+}
+`;
@@ -8,6 +8,7 @@ import {importFromBGFlameGraph} from './bg-flamegraph'
 import {importFromFirefox} from './firefox'
 import {importSpeedscopeProfiles} from '../file-format'
 import {FileFormat} from '../file-format-spec'
+import {importFromV8ProfLog} from './v8proflog'

 export async function importProfile(fileName: string, contents: string): Promise<Profile | null> {
  const profile = await _importProfile(fileName, contents)
@@ -45,6 +46,9 @@ async function _importProfile(fileName: string, contents: string): Promise<Profi
  } else if (fileName.endsWith('.collapsedstack.txt')) {
    console.log('Importing as collapsed stack format')
    return importFromBGFlameGraph(contents)
+  } else if (fileName.endsWith('.v8log.json')) {
+    console.log('Importing as --prof-process v8 log')
+    return importFromV8ProfLog(JSON.parse(contents))
  }

  // Second pass: Try to guess what file format it is based on structure
@@ -68,6 +72,9 @@ async function _importProfile(fileName: string, contents: string): Promise<Profi
    } else if ('mode' in parsed && 'frames' in parsed) {
      console.log('Importing as stackprof profile')
      return importFromStackprof(parsed)
+    } else if ('code' in parsed && 'functions' in parsed && 'ticks' in parsed) {
+      console.log('Importing as --prof-process v8 log')
+      return importFromV8ProfLog(parsed)
    }
  } else {
    // Format is not JSON
@@ -0,0 +1,5 @@
+import {checkProfileSnapshot} from '../test-utils'
+
+test('importFromV8ProfLog', async () => {
+  await checkProfileSnapshot('./sample/profiles/node/8.5.0/simple.v8log.json')
+})
@@ -0,0 +1,188 @@
+import {Profile, FrameInfo, StackListProfileBuilder} from '../profile'
+import {getOrInsert, sortBy} from '../utils'
+import {TimeFormatter} from '../value-formatters'
+
+// This imports profiles generated by a combination of the following commands:
+//
+//    node --prof /path/to/my/script.js
+//    node --prof-process -preprocess -j isolate*.log > profile.v8log.json
+
+// References:
+// - https://github.com/nodejs/node/blob/7edd0a17af8d74dce7dd6c7554a8b8523f83efdc/lib/internal/v8_prof_processor.js#L5
+// - https://github.com/nodejs/node/blob/7edd0a17af8d74dce7dd6c7554a8b8523f83efdc/deps/v8/tools/tickprocessor.js
+// - https://github.com/nodejs/node/blob/2db2857c72c219e5ba1642a345e52cfdd8c44a66/deps/v8/tools/logreader.js#L147
+// - https://github.com/mapbox/flamebearer/blob/a8d4d5c0061ed439660783c613c43ab28b751219/index.js#L53
+
+interface Code {
+  name: string
+  type: 'CODE' | 'CPP' | 'JS' | 'SHARED_LIB'
+  timestamp?: number
+  kind?:
+    | 'Bultin'
+    | 'BytecodeHandler'
+    | 'Handler'
+    | 'KeyedLoadIC'
+    | 'KeyedStoreIC'
+    | 'LoadGlobalIC'
+    | 'LoadIC'
+    | 'Opt'
+    | 'StoreIC'
+    | 'Stub'
+    | 'Unopt'
+    | 'Builtin'
+    | 'RegExp'
+  func?: number
+  tm?: number
+}
+
+interface Function {
+  name: string
+  codes: number[]
+}
+
+interface Tick {
+  // Timestamp
+  tm: number
+
+  // Virtual machine state?
+  vm: number
+
+  // stack
+  s: number[]
+}
+
+interface V8LogProfile {
+  code: Code[]
+  functions: Function[]
+  ticks: Tick[]
+}
+
+function codeToFrameInfo(code: Code, v8log: V8LogProfile): FrameInfo {
+  if (!code || !code.type) {
+    return {
+      key: '(unknown type)',
+      name: '(unknown type)',
+    }
+  }
+
+  let name = code.name
+  switch (code.type) {
+    case 'CPP': {
+      const matches = name.match(/[tT] ([^(<]*)/)
+      if (matches) name = `(c++) ${matches[1]}`
+      break
+    }
+
+    case 'SHARED_LIB':
+      name = '(LIB) ' + name
+      break
+
+    case 'JS': {
+      const matches = name.match(/([a-zA-Z0-9\._\-$]*) ([a-zA-Z0-9\.\-_\/$]*):(\d+):(\d+)/)
+      if (matches) {
+        return {
+          key: name,
+          name: matches[1].length > 0 ? matches[1] : '(anonymous)',
+          file: matches[2].length > 0 ? matches[2] : '(unknown file)',
+          line: parseInt(matches[3], 10),
+          col: parseInt(matches[4], 10),
+        }
+      }
+      break
+    }
+
+    case 'CODE': {
+      switch (code.kind) {
+        case 'LoadIC':
+        case 'StoreIC':
+        case 'KeyedStoreIC':
+        case 'KeyedLoadIC':
+        case 'LoadGlobalIC':
+        case 'Handler':
+          name = '(IC) ' + name
+          break
+
+        case 'BytecodeHandler':
+          name = '(bytecode) ~' + name
+          break
+        case 'Stub':
+          name = '(stub) ' + name
+          break
+        case 'Builtin':
+          name = '(builtin) ' + name
+          break
+        case 'RegExp':
+          name = '(regexp) ' + name
+          break
+      }
+      break
+    }
+
+    default: {
+      name = `(${code.type}) ${name}`
+      break
+    }
+  }
+
+  return {key: name, name}
+}
+
+export function importFromV8ProfLog(v8log: V8LogProfile): Profile {
+  const profile = new StackListProfileBuilder()
+
+  const sToFrameInfo = new Map<number, FrameInfo>()
+  function getFrameInfo(t: number) {
+    return getOrInsert(sToFrameInfo, t, t => {
+      const code = v8log.code[t]
+      return codeToFrameInfo(code, v8log)
+    })
+  }
+
+  let lastTm = 0
+
+  sortBy(v8log.ticks, tick => tick.tm)
+
+  for (let tick of v8log.ticks) {
+    const stack: FrameInfo[] = []
+
+    // tick.s holds the call stack at the time the sample was taken. The
+    // structure is a little strange -- it seems to be capturing both the
+    // JavaScript stack & the parallel C++ stack by interleaving the two.
+    // Because the stacks might not be the same length, it looks like the
+    // shorter stack is padded with indices of -1, so we'll just ignore those
+    // stacks.
+    //
+    // If you change the start index to `let i = tick.s.length - 1` instead,
+    // you'll see the C++ stack instead.
+    //
+    // Mostly the numbers in the stack seem to be indices into the `v8log.code`
+    // array, but some of the numbers in the C++ stack seem to be raw memory
+    // addresses.
+
+    for (let i = tick.s.length - 2; i >= 0; i -= 2) {
+      const id = tick.s[i]
+
+      if (id === -1) continue
+      if (id > v8log.code.length) {
+        // Treat this like a memory address
+        stack.push({
+          key: id,
+          name: `0x${id.toString(16)}`,
+        })
+        continue
+      }
+      stack.push(getFrameInfo(id))
+    }
+    profile.appendSample(stack, tick.tm - lastTm)
+    lastTm = tick.tm
+  }
+
+  // Despite the code in the v8 processing library indicating that the
+  // timestamps come from a variable called "time_ns", from making empirical
+  // recordings, it really seems like these profiles are recording timestamps in
+  // microseconds, not nanoseconds.
+  // https://github.com/nodejs/node/blob/c39caa997c751473d0c8f50af8c6b14bcd389fa0/deps/v8/tools/profile.js#L1076
+  profile.setValueFormatter(new TimeFormatter('microseconds'))
+
+  return profile.build()
+}
@@ -11,20 +11,13 @@
    "prepack": "./build-release.sh",
    "prettier": "prettier --write './**/*.ts' './**/*.tsx'",
    "lint": "eslint './**/*.ts' './**/*.tsx'",
-    "jest": "jest",
+    "jest": "./test-setup.sh && jest",
    "coverage": "npm run jest -- --coverage && coveralls < coverage/lcov.info",
    "test": "tsc --noEmit && npm run lint && npm run coverage",
    "serve": "parcel index.html --open --no-autoinstall"
  },
-  "files": [
-    "cli.js",
-    "dist/release/**",
-    "!*.map"
-  ],
-  "browserslist": [
-    "last 2 Chrome versions",
-    "last 2 Firefox versions"
-  ],
+  "files": ["cli.js", "dist/release/**", "!*.map"],
+  "browserslist": ["last 2 Chrome versions", "last 2 Firefox versions"],
  "author": "",
  "license": "MIT",
  "devDependencies": {
@@ -55,17 +48,8 @@
      "^.+\\.tsx?$": "ts-jest"
    },
    "testRegex": "\\.test\\.tsx?$",
-    "collectCoverageFrom": [
-      "**/*.{ts,tsx}",
-      "!**/*.d.{ts,tsx}"
-    ],
-    "moduleFileExtensions": [
-      "ts",
-      "tsx",
-      "js",
-      "jsx",
-      "json"
-    ]
+    "collectCoverageFrom": ["**/*.{ts,tsx}", "!**/*.d.{ts,tsx}"],
+    "moduleFileExtensions": ["ts", "tsx", "js", "jsx", "json"]
  },
  "dependencies": {
    "opn": "5.3.0"
@@ -0,0 +1 @@
+*.v8log.json
@@ -0,0 +1,6 @@
+#!/bin/bash
+set -e
+
+for f in `find sample/profiles -name '*.zip' | grep -v Instruments`; do
+  unzip -o $f -d $(dirname $f);
+done
@@ -22,7 +22,7 @@ export class TimeFormatter implements ValueFormatter {
    else this.multiplier = 1
  }

-  format(v: number) {
+  formatUnsigned(v: number) {
    const s = v * this.multiplier

    if (s / 60 >= 1) return `${(s / 60).toFixed(2)}min`
@@ -31,6 +31,10 @@ export class TimeFormatter implements ValueFormatter {
    if (s / 1e-6 >= 1) return `${(s / 1e-6).toFixed(2)}µs`
    else return `${(s / 1e-9).toFixed(2)}ns`
  }
+
+  format(v: number) {
+    return `${v < 0 ? '-' : ''}${this.formatUnsigned(Math.abs(v))}`
+  }
 }

 export class ByteFormatter implements ValueFormatter {