diff --git a/README.md b/README.md index 6776240..082fa30 100644 --- a/README.md +++ b/README.md @@ -85,6 +85,7 @@ Options: -s, --sourcemap-dirs Directories to search for sourcemaps (colon/semicolon-separated) --md-format Markdown format: summary (default), detailed, or adaptive --node-options Node.js CLI options to pass to the profiled process + --deopt Track V8 deoptimizations and show them on the CPU flamegraph -h, --help Show help message -v, --version Show version number ``` @@ -100,6 +101,9 @@ const { pid, toggleProfiler } = startProfiling('server.js', ['--port', '3000'], // Or start in manual mode const { pid, toggleProfiler } = startProfiling('server.js', ['--port', '3000'], { autoStart: false }) +// Track V8 deoptimizations while profiling +startProfiling('server.js', [], { autoStart: true, deopt: true }) + console.log(`Started profiling process ${pid}`) // Toggle profiling programmatically (useful in manual mode) @@ -123,6 +127,55 @@ const profile = await parseProfile('profile.pb') 4. **Interactive Visualization**: The `@platformatic/react-pprof` library generates interactive WebGL-based HTML flamegraphs for both profile types 5. **Markdown Analysis**: The `pprof-to-md` library generates LLM-friendly markdown reports with hotspot tables for AI-assisted debugging +## V8 Deoptimizations + +```bash +flame run --deopt server.js +``` + +With `--deopt`, flame records the V8 deoptimizations that happen while the +CPU profiler runs and stores them in the CPU profile. The flamegraph then: + +- marks frames that had actionable deopts (a bar along the bottom edge and a + triangle in the top-right corner) +- shows the deopt count and the most frequent reasons in the hover tooltip +- lists every deopt of the selected frame in the details panel, with its source + position and an explanation of the reason +- adds a **Highlight Deopts** checkbox to turn the markers off + +The markdown report gets a **V8 Deoptimizations** section listing the functions +with actionable deopts, their share of the profile and an explanation of each +reason. Deopts that are part of V8's normal tiering (on-stack replacement, +insufficient type feedback) are counted but not highlighted. A deopt is not a +bug by itself: it matters when it repeats in a function that takes a large +share of the profile. + +Explanations come from a catalog of V8's deopt reasons shipped with +`react-pprof`, derived from +[deoptigate's deoptimization guide](https://github.com/Uzlopak/deoptigate/blob/59e854d5cabfe2f9698246c985ad21f3a820b0b8/assets/deoptimization.md). + +### How it works + +V8 does not reliably write deopt records to its `--log-deopt` log while a CPU +profile is being recorded, so flame reads V8's deopt traces instead: the process starts +with `--trace-deopt-verbose` writing to a temporary file +(`--redirect-code-traces-to`), and the preload turns tracing off right away and +back on only while the profiler runs, including windows started with `SIGUSR2`. +At the end of each window the new traces are parsed, matched to the functions +in the profile, and stored as a JSON comment in the `.pb` file, so +`flame generate` shows them too. + +### Notes + +- Deopts that happen before profiling starts (for example during startup with + the default `--delay=until-started`) are not recorded; use `--delay=none` to + include them. +- Verbose deopt traces include the deoptimized frames, so programs that + deoptimize a lot write a large temporary file; it is removed when the process + exits. +- Worker threads are traced too, but their deopts are only matched to functions + that appear in the main thread's CPU profile. + ## Sourcemap Support When profiling transpiled or bundled applications (TypeScript, Webpack, ESBuild, etc.), the flame tool can automatically translate stack traces from generated code back to your original source files using sourcemaps. diff --git a/bin/flame.js b/bin/flame.js index d66af9f..5e7cade 100755 --- a/bin/flame.js +++ b/bin/flame.js @@ -45,6 +45,9 @@ const { values: args, positionals } = parseArgs({ }, 'md-format': { type: 'string' + }, + deopt: { + type: 'boolean' } }, allowPositionals: true @@ -73,6 +76,7 @@ Options: -n, --node-modules-source-maps Node modules to load sourcemaps from (comma-separated, e.g., "next,@next/next-server") --node-options Node.js CLI options to pass to the profiled process --md-format Markdown format: summary (default), detailed, or adaptive + --deopt Track V8 deoptimizations while profiling and show them on the flamegraph -h, --help Show this help message -v, --version Show version number @@ -85,6 +89,7 @@ Examples: flame run --sourcemap-dirs=dist:build server.js # Enable sourcemap support flame run -n next,@next/next-server server.js # Load Next.js sourcemaps from node_modules flame run --md-format=detailed server.js # Use detailed markdown format + flame run --deopt server.js # Highlight V8 deoptimizations on the flamegraph flame run --node-options="--require ts-node/register" server.ts # With Node.js options flame run --node-options="--import ./loader.js --max-old-space-size=4096" server.js flame generate profile.pb.gz @@ -154,13 +159,17 @@ async function main () { delay, sourcemapDirs, nodeModulesSourceMaps, - mdFormat + mdFormat, + deopt: args.deopt }) console.log(`🔥 Started profiling process ${pid}`) if (autoStart) { console.log('🔥 CPU profiling is active and will generate profile on exit') console.log('🔥 Profile (.pb) and interactive HTML flamegraph will be auto-generated') + if (args.deopt) { + console.log('🔥 V8 deoptimizations will be highlighted on the CPU flamegraph') + } console.log('🔥 Generated files will be saved in the current directory') console.log('Send SIGUSR2 to manually toggle profiling:') } else { diff --git a/lib/deopt.js b/lib/deopt.js new file mode 100644 index 0000000..7a47aae --- /dev/null +++ b/lib/deopt.js @@ -0,0 +1,550 @@ +'use strict' + +/** + * V8 deoptimization tracking. + * + * V8 drops most `code-deopt` records from its log (`--log-deopt`) while a CPU + * profile is being recorded, so deopts are collected from V8's deopt traces + * instead. The profiled process starts with `--trace-deopt-verbose` writing + * to a file (`--redirect-code-traces-to`); the preload turns tracing off right + * away and back on only while profiling. V8 opens the trace file when the + * flag is set at startup: enabling the flag later without it prints nothing. + * + * At the end of the profiling window the new part of the trace file is parsed + * and the deopts are attached to the CPU profile as a JSON comment (type + * `v8-deopts`) that react-pprof renders on the flamegraph. + */ + +const fs = require('fs') +const path = require('path') +const os = require('os') + +const PAYLOAD_TYPE = 'v8-deopts' +const PAYLOAD_VERSION = 1 + +/** + * Node.js CLI arguments that open the deopt trace file + * @param {string} dir - Directory for the trace file + * @returns {{ args: string[], traceFile: string }} + */ +function getDeoptNodeArgs (dir) { + const traceFile = path.join(dir, 'deopt-trace.txt') + return { + traceFile, + args: [ + // Only the verbose trace includes the source position of the deopt + '--trace-deopt-verbose', + '--redirect-code-traces', + `--redirect-code-traces-to=${traceFile}` + ] + } +} + +/** + * Create a temporary directory for the deopt trace + * @returns {string} + */ +function createDeoptTraceDir () { + return fs.mkdtempSync(path.join(os.tmpdir(), 'flame-deopt-')) +} + +// [bailout (kind: deopt-eager, reason: wrong map): begin. deoptimizing 0x... , 0x... , ...] +const BAILOUT_BEGIN = /^\[bailout \(kind: ([^,]+), reason: (.*)\): begin\. deoptimizing (?:0x[0-9a-fA-F]+ )?/ +// ;;; deoptimize at (inlined code: inlined at ) +const DEOPT_POSITION = /^\s*;;; deoptimize at (.*)$/ + +/** + * Parse a `script:line:column` position + * @param {string} str + * @returns {{ file: string, line: number, column: number } | null} + */ +function parsePosition (str) { + const match = /^(.*):(\d+):(\d+)$/.exec(str) + if (!match) return null + return { file: match[1], line: Number(match[2]), column: Number(match[3]) } +} + +/** + * Get the positions of a deopt, innermost first. For inlined code the last + * position is in the optimized function itself. + * @param {string} str + * @returns {Array<{ file: string, line: number, column: number }>} + */ +function parseDeoptPositions (str) { + return [...str.matchAll(/<([^<>]*)>/g)] + .map(match => parsePosition(match[1])) + .filter(Boolean) +} + +/** + * Parse V8 deopt traces (`--trace-deopt-verbose` output) + * @param {Buffer|string} trace + * @returns {Array<{ reason: string, bailoutType: string, functionName: string, position: string }>} + */ +function parseDeoptTrace (trace) { + const text = Buffer.isBuffer(trace) ? trace.toString('utf8') : trace + const deopts = [] + let current = null + + for (const line of text.split('\n')) { + if (line.startsWith('[bailout')) { + const begin = BAILOUT_BEGIN.exec(line) + if (begin) { + current = { + reason: begin[2], + bailoutType: begin[1], + functionName: begin[3], + position: '' + } + deopts.push(current) + } else { + // "[bailout end. ...]" + current = null + } + continue + } + + if (current && !current.position) { + const position = DEOPT_POSITION.exec(line) + if (position) { + current.position = position[1].trim() + } + } + } + + return deopts +} + +/** + * Collect the functions of a pprof profile + * @param {object} profile - pprof-format Profile + * @returns {Array<{ name: string, file: string, line: number }>} + */ +function getProfileFunctions (profile) { + const strings = profile.stringTable.strings + + // @datadog/pprof leaves Function.startLine empty and stores the function's + // start line in its locations, which is also what react-pprof shows + const locationLines = new Map() + for (const location of profile.location || []) { + for (const line of location.line || []) { + const id = String(line.functionId) + const value = Number(line.line || 0) + if (value > 0 && (!locationLines.has(id) || value < locationLines.get(id))) { + locationLines.set(id, value) + } + } + } + + const functions = [] + for (const fn of profile.function || []) { + functions.push({ + name: strings[Number(fn.name)] || '', + file: strings[Number(fn.filename)] || '', + line: Number(fn.startLine || 0) || locationLines.get(String(fn.id)) || 0 + }) + } + return functions +} + +/** + * Builds a lookup from V8's view of a deopt (function name, source position) + * to the profile's function table, so react-pprof can match them exactly. + * @param {Array<{ name: string, file: string, line: number }>} functions + */ +function createFunctionResolver (functions) { + const byFile = new Map() + const byName = new Map() + for (const fn of functions) { + if (fn.file) { + if (!byFile.has(fn.file)) byFile.set(fn.file, []) + byFile.get(fn.file).push(fn) + } + if (fn.name) { + if (!byName.has(fn.name)) byName.set(fn.name, []) + byName.get(fn.name).push(fn) + } + } + for (const list of byFile.values()) { + list.sort((a, b) => a.line - b.line) + } + + return { + /** + * @param {string} name - Name of the deoptimized function + * @param {{ file: string, line: number } | null} position - Deopt position inside that function + */ + resolve (name, position) { + if (position) { + const list = byFile.get(position.file) + if (list) { + // The function containing the position starts at or before it. + // Prefer the closest one with the same name, then the closest one. + let closest = null + let closestNamed = null + for (const fn of list) { + if (fn.line > position.line) break + if (fn.line <= 0) continue + closest = fn + if (name && fn.name === name) closestNamed = fn + } + if (closestNamed || closest) return closestNamed || closest + } + } + + if (name) { + const candidates = byName.get(name) + if (candidates && candidates.length === 1) return candidates[0] + } + return null + } + } +} + +/** + * Aggregate parsed deopts by function and build the payload stored in the + * profile. Functions are named as in the profile when they can be matched. + * @param {ReturnType} deopts + * @param {Array<{ name: string, file: string, line: number }>} [profileFunctions] + * @returns {{ type: string, version: number, functions: Array }} + */ +function buildDeoptPayload (deopts, profileFunctions = []) { + const resolver = createFunctionResolver(profileFunctions) + const functions = new Map() + + for (const deopt of deopts) { + const positions = parseDeoptPositions(deopt.position) + const outermost = positions.length > 0 ? positions[positions.length - 1] : null + + let owner = resolver.resolve(deopt.functionName, outermost) + if (!owner && deopt.functionName && outermost) { + // Not in the profile (never sampled): keep it for reporting + owner = { name: deopt.functionName, file: outermost.file, line: 0 } + } + if (!owner) continue + + const fnKey = `${owner.name}\0${owner.file}\0${owner.line}` + let fn = functions.get(fnKey) + if (!fn) { + fn = { name: owner.name, file: owner.file, line: owner.line, entries: new Map() } + functions.set(fnKey, fn) + } + + // ` inlined at ` -> `/a.js:1:2 inlined at /b.js:3:4` + const position = deopt.position.replace(/[<>]/g, '') + const entryKey = `${deopt.reason}\0${deopt.bailoutType}\0${position}` + const entry = fn.entries.get(entryKey) + if (entry) { + entry.count++ + } else { + const item = { reason: deopt.reason, bailoutType: deopt.bailoutType, count: 1 } + if (position) item.position = position + fn.entries.set(entryKey, item) + } + } + + return { + type: PAYLOAD_TYPE, + version: PAYLOAD_VERSION, + functions: [...functions.values()].map(fn => ({ + name: fn.name, + file: fn.file, + line: fn.line, + deopts: [...fn.entries.values()].sort((a, b) => b.count - a.count) + })) + } +} + +/** + * Add a deopt payload to a profile as a comment + * @param {object} profile - pprof-format Profile + * @param {object} payload + */ +function attachDeoptPayload (profile, payload) { + const index = profile.stringTable.dedup(JSON.stringify(payload)) + profile.comment = [...(profile.comment || []), index] +} + +/** + * Read the deopt payload from a profile, if it has one + * @param {object} profile - pprof-format Profile + * @returns {object | null} + */ +function extractDeoptPayload (profile) { + const strings = profile.stringTable.strings + for (const index of profile.comment || []) { + const text = strings[Number(index)] + if (typeof text !== 'string' || !text.includes(PAYLOAD_TYPE)) continue + try { + const parsed = JSON.parse(text) + if (parsed && parsed.type === PAYLOAD_TYPE && Array.isArray(parsed.functions)) { + return parsed + } + } catch { + // not a deopt payload + } + } + return null +} + +/** + * Tracks deopts in the current process. Requires the process to be started + * with the arguments from getDeoptNodeArgs(). + */ +class DeoptTracker { + #traceFile + #startOffset = null + + /** + * @param {string} traceFile - Deopt trace file opened at startup + */ + constructor (traceFile) { + this.#traceFile = traceFile + // Tracing is on from startup so V8 opens the file: turn it off until profiling starts + setTracing(false) + } + + get active () { + return this.#startOffset !== null + } + + start () { + if (this.active) return + this.#startOffset = fileSize(this.#traceFile) + setTracing(true) + } + + /** + * Stop tracking and attach the deopts of the window to a CPU profile + * @param {object} [profile] - pprof-format Profile to attach the deopts to + * @returns {{ functions: number, deopts: number } | null} - What was attached + */ + stop (profile) { + if (!this.active) return null + setTracing(false) + const startOffset = this.#startOffset + this.#startOffset = null + + if (!profile) return null + + const trace = readFrom(this.#traceFile, startOffset) + const payload = buildDeoptPayload(parseDeoptTrace(trace), getProfileFunctions(profile)) + attachDeoptPayload(profile, payload) + return { + functions: payload.functions.length, + deopts: payload.functions.reduce((sum, fn) => sum + fn.deopts.reduce((s, d) => s + d.count, 0), 0) + } + } +} + +/** + * Load the deopt reason catalog shipped with react-pprof + * @returns {Promise<{ getDeoptCategory: Function, getDeoptReasonInfo: Function }>} + */ +function loadReasonCatalog () { + return import('react-pprof/dist/deopts/index.js') +} + +/** + * Compute self and total time share for each function of a profile + * @param {object} profile - pprof-format Profile + * @returns {Map} keyed by `name\0file\0line`, as fractions of the profile + */ +function getFunctionShares (profile) { + const functions = getProfileFunctions(profile) + const keyById = new Map() + ;(profile.function || []).forEach((fn, i) => { + const f = functions[i] + keyById.set(String(fn.id), `${f.name}\0${f.file}\0${f.line}`) + }) + const keyByLocation = new Map() + for (const location of profile.location || []) { + const line = location.line && location.line[0] + if (line) keyByLocation.set(String(location.id), keyById.get(String(line.functionId))) + } + + const valueIndex = Math.max(0, (profile.sampleType || []).length - 1) + const shares = new Map() + let grandTotal = 0 + for (const sample of profile.sample || []) { + const value = Number(sample.value[valueIndex] || 0) + if (value <= 0) continue + grandTotal += value + const seen = new Set() + sample.locationId.forEach((locationId, depth) => { + const key = keyByLocation.get(String(locationId)) + if (!key) return + if (!shares.has(key)) shares.set(key, { self: 0, total: 0 }) + const share = shares.get(key) + if (depth === 0) share.self += value + if (!seen.has(key)) { + share.total += value + seen.add(key) + } + }) + } + if (grandTotal > 0) { + for (const share of shares.values()) { + share.self /= grandTotal + share.total /= grandTotal + } + } + return shares +} + +function percent (value) { + return `${(value * 100).toFixed(1)}%` +} + +function escapeCell (str) { + return String(str).replace(/\|/g, '\\|').replace(/\n/g, ' ') +} + +/** + * Render the deopts of a profile as markdown, or '' if it has none + * @param {object} profile - pprof-format Profile + * @param {object} [options] + * @param {number} [options.maxFunctions=10] - Functions described in detail + * @returns {Promise} + */ +async function formatDeoptMarkdown (profile, options = {}) { + const { maxFunctions = 10 } = options + const payload = extractDeoptPayload(profile) + if (!payload) return '' + + const { getDeoptCategory, getDeoptReasonInfo } = await loadReasonCatalog() + const shares = getFunctionShares(profile) + + let totalDeopts = 0 + let tieringDeopts = 0 + const rows = payload.functions.map(fn => { + const share = shares.get(`${fn.name}\0${fn.file}\0${fn.line}`) || { self: 0, total: 0 } + const deopts = fn.deopts.map(d => ({ ...d, category: getDeoptCategory(d.reason), info: getDeoptReasonInfo(d.reason) })) + const actionable = deopts.filter(d => d.category === 'actionable') + const count = deopts.reduce((sum, d) => sum + d.count, 0) + const actionableCount = actionable.reduce((sum, d) => sum + d.count, 0) + totalDeopts += count + tieringDeopts += count - actionableCount + return { fn, share, actionable, actionableCount } + }) + + const lines = ['', '## V8 Deoptimizations', ''] + if (totalDeopts === 0) { + lines.push('No V8 deoptimizations were recorded while profiling.', '') + return lines.join('\n') + } + + lines.push( + `${totalDeopts} deoptimizations in ${payload.functions.length} functions were recorded while profiling` + + (tieringDeopts > 0 ? `, ${tieringDeopts} of them normal tiering or engine-internal events (on-stack replacement, insufficient type feedback, ...).` : '.'), + 'A deoptimization is not a bug by itself: it matters when it repeats in a function that takes a large share of the profile.', + '' + ) + + const actionableRows = rows + .filter(row => row.actionableCount > 0) + .sort((a, b) => (b.share.self - a.share.self) || (b.actionableCount - a.actionableCount)) + + if (actionableRows.length === 0) { + lines.push('No actionable deoptimizations were recorded.', '') + return lines.join('\n') + } + + lines.push( + '| Function | Location | Self | Total | Deopts | Reasons |', + '|---|---|---|---|---|---|' + ) + for (const row of actionableRows) { + const location = row.fn.line ? `${row.fn.file}:${row.fn.line}` : row.fn.file + const reasons = [...new Set(row.actionable.map(d => d.reason))].join(', ') + lines.push(`| \`${escapeCell(row.fn.name || '(anonymous)')}\` | ${escapeCell(location)} | ${percent(row.share.self)} | ${percent(row.share.total)} | ${row.actionableCount} | ${escapeCell(reasons)} |`) + } + lines.push('') + + for (const row of actionableRows.slice(0, maxFunctions)) { + const location = row.fn.line ? `${row.fn.file}:${row.fn.line}` : row.fn.file + lines.push(`### \`${row.fn.name || '(anonymous)'}\` (${location})`, '') + for (const deopt of row.actionable) { + const name = deopt.info ? ` (\`${deopt.info.reason}\`, ${deopt.info.kind})` : '' + const at = deopt.position ? ` at ${deopt.position}` : '' + lines.push(`- **${deopt.reason}**${name} ×${deopt.count}${at}`) + if (deopt.info) lines.push(` ${deopt.info.meaning}`) + } + lines.push('') + } + + return lines.join('\n') +} + +/** + * Decode a pprof file (optionally gzipped) + * @param {string} file + * @returns {Promise} pprof-format Profile + */ +async function readProfile (file) { + let data = fs.readFileSync(file) + if (data[0] === 0x1f && data[1] === 0x8b) { + data = require('zlib').gunzipSync(data) + } + const { Profile } = await import('pprof-format') + return Profile.decode(data) +} + +/** + * Append the deopt section to a markdown report generated from a pprof file + * @param {string} pprofPath + * @param {string} markdown + * @returns {Promise} + */ +async function appendDeoptMarkdown (pprofPath, markdown) { + try { + const section = await formatDeoptMarkdown(await readProfile(pprofPath)) + return section ? `${markdown.replace(/\s*$/, '')}\n${section}` : markdown + } catch { + return markdown + } +} + +function setTracing (enabled) { + require('v8').setFlagsFromString(enabled ? '--trace-deopt-verbose' : '--no-trace-deopt-verbose') +} + +function fileSize (file) { + try { + return fs.statSync(file).size + } catch { + return 0 + } +} + +function readFrom (file, offset) { + let fd + try { + fd = fs.openSync(file, 'r') + const size = fs.fstatSync(fd).size + // The file can be truncated if another isolate (e.g. a worker) reopened it + const start = offset <= size ? offset : 0 + const buffer = Buffer.alloc(size - start) + fs.readSync(fd, buffer, 0, buffer.length, start) + return buffer + } catch { + return Buffer.alloc(0) + } finally { + if (fd !== undefined) fs.closeSync(fd) + } +} + +module.exports = { + PAYLOAD_TYPE, + getDeoptNodeArgs, + createDeoptTraceDir, + parseDeoptPositions, + parseDeoptTrace, + getProfileFunctions, + buildDeoptPayload, + attachDeoptPayload, + extractDeoptPayload, + formatDeoptMarkdown, + appendDeoptMarkdown, + DeoptTracker +} diff --git a/lib/index.js b/lib/index.js index 7a3cc57..3876d25 100644 --- a/lib/index.js +++ b/lib/index.js @@ -4,6 +4,7 @@ const fs = require('fs') const path = require('path') const zlib = require('zlib') const { spawn } = require('child_process') +const { getDeoptNodeArgs, createDeoptTraceDir, appendDeoptMarkdown } = require('./deopt.js') /** * Start profiling a Node.js process using the preload script @@ -15,6 +16,7 @@ const { spawn } = require('child_process') * @param {string} options.delay - Delay before starting profiler ('none', 'until-started', or numeric string for ms, default: 'until-started') * @param {string|string[]} options.sourcemapDirs - Directory or directories to search for sourcemaps (optional) * @param {string|string[]} options.nodeModulesSourceMaps - Node modules to load sourcemaps from (optional) + * @param {boolean} options.deopt - Track V8 deoptimizations during profiling and add them to the CPU profile (default: false) * @returns {Promise} Process information */ function startProfiling (script, args = [], options = {}) { @@ -44,8 +46,19 @@ function startProfiling (script, args = [], options = {}) { env.FLAME_NODE_MODULES_SOURCE_MAPS = mods.join(',') } + // Open the deopt trace file so the preload can enable deopt tracing while profiling + let deoptArgs = [] + let deoptTraceDir = null + if (options.deopt) { + deoptTraceDir = createDeoptTraceDir() + const { args: v8Args, traceFile } = getDeoptNodeArgs(deoptTraceDir) + deoptArgs = v8Args + env.FLAME_DEOPT_TRACE = traceFile + } + // Construct the node command with options const nodeArgs = [ + ...deoptArgs, ...(options.nodeOptions || []), '-r', preloadPath, @@ -59,6 +72,12 @@ function startProfiling (script, args = [], options = {}) { ...options }) + if (deoptTraceDir) { + child.on('exit', () => { + fs.rmSync(deoptTraceDir, { recursive: true, force: true }) + }) + } + return { pid: child.pid, process: child, @@ -157,7 +176,7 @@ async function generateMarkdown (pprofPath, outputPath, options = {}) { format: options.format || 'summary', profileName: path.basename(pprofPath) }) - fs.writeFileSync(outputPath, markdown) + fs.writeFileSync(outputPath, await appendDeoptMarkdown(pprofPath, markdown)) return { outputPath } } diff --git a/package.json b/package.json index ba768ec..9f69e24 100644 --- a/package.json +++ b/package.json @@ -41,7 +41,7 @@ "fastify": "^5.5.0", "pprof-format": "^2.2.1", "pprof-to-md": "^0.2.0", - "react-pprof": "^1.4.0" + "react-pprof": "^1.6.0" }, "devDependencies": { "@fastify/compress": "^8.1.0", diff --git a/preload.js b/preload.js index 2895b94..223a8b8 100644 --- a/preload.js +++ b/preload.js @@ -4,6 +4,7 @@ const fs = require('fs') const path = require('path') const pprof = require('@datadog/pprof') const { spawn } = require('child_process') +const { DeoptTracker, appendDeoptMarkdown } = require('./lib/deopt.js') const cpuProfiler = pprof.time const heapProfiler = pprof.heap @@ -13,6 +14,28 @@ let sourceMapper = null const autoStart = process.env.FLAME_AUTO_START === 'true' const mdFormat = process.env.FLAME_MD_FORMAT || 'summary' +// V8 deopt tracking, enabled by `flame run --deopt` +const deoptTracker = process.env.FLAME_DEOPT_TRACE ? new DeoptTracker(process.env.FLAME_DEOPT_TRACE) : null + +/** + * Stop the CPU profiler and attach the deopts of the profiling window + * @returns {object} pprof-format Profile + */ +function stopCpuProfiler () { + const cpuProfileData = cpuProfiler.stop() + if (deoptTracker) { + try { + const result = deoptTracker.stop(cpuProfileData) + if (result) { + console.log(`🔥 Recorded ${result.deopts} V8 deopts in ${result.functions} functions`) + } + } catch (error) { + console.error('Warning: Failed to collect V8 deopts:', error.message) + } + } + return cpuProfileData +} + // Initialize sourcemap support if enabled const sourcemapDirs = process.env.FLAME_SOURCEMAP_DIRS const nodeModulesSourceMaps = process.env.FLAME_NODE_MODULES_SOURCE_MAPS @@ -318,7 +341,7 @@ async function generateMarkdown (pprofPath, outputPath, format = 'summary') { format, profileName: path.basename(pprofPath) }) - fs.writeFileSync(outputPath, markdown) + fs.writeFileSync(outputPath, await appendDeoptMarkdown(pprofPath, markdown)) return { outputPath } } @@ -333,7 +356,7 @@ function stopProfilerQuick () { try { if (isCpuProfilerRunning) { - const cpuProfileData = cpuProfiler.stop() + const cpuProfileData = stopCpuProfiler() const cpuProfile = cpuProfileData.encode() const cpuFilename = `cpu-profile-${timestamp}.pb` fs.writeFileSync(cpuFilename, cpuProfile) @@ -379,7 +402,7 @@ async function stopProfilerAndSave (generateHtml = false) { try { if (isCpuProfilerRunning) { - const cpuProfileData = cpuProfiler.stop() + const cpuProfileData = stopCpuProfiler() const cpuProfile = cpuProfileData.encode() const cpuFilename = `cpu-profile-${timestamp}.pb` fs.writeFileSync(cpuFilename, cpuProfile) @@ -497,6 +520,9 @@ function toggleProfiler () { // Start CPU profiler with sourcemap support if available const cpuProfilerOptions = sourceMapper ? { sourceMapper } : undefined cpuProfiler.start(cpuProfilerOptions) + if (deoptTracker) { + deoptTracker.start() + } // Start heap profiler with default parameters // intervalBytes: 512KB (512 * 1024) // stackDepth: 64 diff --git a/test/deopt.test.js b/test/deopt.test.js new file mode 100644 index 0000000..e30fc22 --- /dev/null +++ b/test/deopt.test.js @@ -0,0 +1,231 @@ +'use strict' + +const test = require('node:test') +const assert = require('node:assert') +const { spawn } = require('child_process') +const fs = require('fs') +const os = require('os') +const path = require('path') +const { + getDeoptNodeArgs, + parseDeoptPositions, + parseDeoptTrace, + getProfileFunctions, + buildDeoptPayload, + attachDeoptPayload, + extractDeoptPayload, + formatDeoptMarkdown, + PAYLOAD_TYPE +} = require('../lib/deopt.js') + +const TRACE = `[bailout (kind: deopt-eager, reason: prepare for on stack replacement (OSR)): begin. deoptimizing 0x22ad1483f091 , 0x27f17c54f619 , opt id 6, bytecode offset 103, deopt exit 8, FP to SP delta 160, caller SP 0x00016f8a9820, pc 0x00012451715c] + ;;; deoptimize at + reading input frame => bytecode_offset=103, args=1, height=9, retval=0(#0); inputs: + 0: 0x022ad1483f091 ; [fp - 16] 0x22ad1483f091 +[bailout end. took 0.500 ms] +[bailout (kind: deopt-eager, reason: wrong map): begin. deoptimizing 0x22ad1483ef69 , 0x3ae7d2266c71 , opt id 5, bytecode offset 0, deopt exit 0, FP to SP delta 32, caller SP 0x00016f8a9740, pc 0x000124515fac] + ;;; deoptimize at +[bailout end. took 0.291 ms] +[bailout (kind: deopt-eager, reason: wrong map): begin. deoptimizing 0x22ad1483ef69 , 0x3ae7d2266c71 , opt id 7, bytecode offset 0, deopt exit 0, FP to SP delta 32, caller SP 0x00016f8a9740, pc 0x000124515fac] + ;;; deoptimize at +[bailout end. took 0.291 ms] +[bailout (kind: deopt-eager, reason: not a Smi): begin. deoptimizing 0x22ad1483ef70 , 0x3ae7d2266c72 , opt id 8, bytecode offset 4, deopt exit 1, FP to SP delta 32, caller SP 0x00016f8a9740, pc 0x000124515fad] + ;;; deoptimize at inlined at +[bailout end. took 0.100 ms] +[bailout (kind: deopt-lazy, reason: (unknown)): begin. deoptimizing 0x22ad1483ef71 , 0x3ae7d2266c73 , opt id 9, bytecode offset 4, deopt exit 1, FP to SP delta 32, caller SP 0x00016f8a9740, pc 0x000124515fae] + ;;; deoptimize at +[bailout end. took 0.100 ms] +` + +const PROFILE_FUNCTIONS = [ + { name: '(anonymous:L#1:C#1)', file: '/app/main.js', line: 1 }, + { name: 'readX', file: '/app/lib.js', line: 4 }, + { name: 'helper', file: '/app/lib.js', line: 1 }, + { name: 'outer', file: '/app/lib.js', line: 10 } +] + +test('getDeoptNodeArgs opens the trace file at startup', () => { + const { args, traceFile } = getDeoptNodeArgs('/tmp/x') + assert.strictEqual(traceFile, path.join('/tmp/x', 'deopt-trace.txt')) + assert.deepStrictEqual(args, [ + '--trace-deopt-verbose', + '--redirect-code-traces', + `--redirect-code-traces-to=${traceFile}` + ]) +}) + +test('parseDeoptTrace extracts reason, kind, function and position', () => { + const deopts = parseDeoptTrace(TRACE) + assert.deepStrictEqual(deopts, [ + { reason: 'prepare for on stack replacement (OSR)', bailoutType: 'deopt-eager', functionName: '', position: '' }, + { reason: 'wrong map', bailoutType: 'deopt-eager', functionName: 'readX', position: '' }, + { reason: 'wrong map', bailoutType: 'deopt-eager', functionName: 'readX', position: '' }, + { reason: 'not a Smi', bailoutType: 'deopt-eager', functionName: 'outer', position: ' inlined at ' }, + { reason: '(unknown)', bailoutType: 'deopt-lazy', functionName: 'neverSampled', position: '' } + ]) +}) + +test('parseDeoptTrace accepts buffers and ignores unrelated output', () => { + const deopts = parseDeoptTrace(Buffer.from('random line\n[bailout end. took 1 ms]\n' + TRACE.split('\n').slice(5, 8).join('\n'))) + assert.strictEqual(deopts.length, 1) + assert.strictEqual(deopts[0].functionName, 'readX') +}) + +test('parseDeoptPositions returns positions innermost first', () => { + assert.deepStrictEqual(parseDeoptPositions(' inlined at '), [ + { file: '/app/a.js', line: 2, column: 10 }, + { file: '/app/b.js', line: 12, column: 3 } + ]) + assert.deepStrictEqual(parseDeoptPositions(''), [ + { file: 'file:///app/c.mjs', line: 1, column: 2 } + ]) + assert.deepStrictEqual(parseDeoptPositions(''), []) +}) + +test('buildDeoptPayload groups deopts by profile function', () => { + const payload = buildDeoptPayload(parseDeoptTrace(TRACE), PROFILE_FUNCTIONS) + assert.strictEqual(payload.type, PAYLOAD_TYPE) + assert.strictEqual(payload.version, 1) + + const byName = Object.fromEntries(payload.functions.map(fn => [fn.name, fn])) + + // Anonymous functions are matched by position and named as in the profile + assert.deepStrictEqual(byName['(anonymous:L#1:C#1)'], { + name: '(anonymous:L#1:C#1)', + file: '/app/main.js', + line: 1, + deopts: [{ reason: 'prepare for on stack replacement (OSR)', bailoutType: 'deopt-eager', count: 1, position: '/app/main.js:6:1' }] + }) + + // Repeated deopts are counted + assert.deepStrictEqual(byName.readX.deopts, [ + { reason: 'wrong map', bailoutType: 'deopt-eager', count: 2, position: '/app/lib.js:5:31' } + ]) + assert.strictEqual(byName.readX.line, 4) + + // Inlined deopts belong to the optimized (outermost) function + assert.strictEqual(byName.outer.line, 10) + assert.strictEqual(byName.outer.deopts[0].position, '/app/lib.js:2:10 inlined at /app/lib.js:12:3') + assert.strictEqual(byName.helper, undefined) + + // Functions that are not in the profile are kept for reporting + assert.deepStrictEqual(byName.neverSampled, { + name: 'neverSampled', + file: '/app/other.js', + line: 0, + deopts: [{ reason: '(unknown)', bailoutType: 'deopt-lazy', count: 1, position: '/app/other.js:40:2' }] + }) +}) + +async function makeProfile () { + const { Profile, StringTable, Function, Location, Line, Sample, ValueType } = await import('pprof-format') + const stringTable = new StringTable() + const functions = PROFILE_FUNCTIONS.map((fn, i) => new Function({ + id: i + 1, + name: stringTable.dedup(fn.name), + filename: stringTable.dedup(fn.file), + // Like @datadog/pprof: no startLine, the start line is in the location + startLine: 0 + })) + const locations = PROFILE_FUNCTIONS.map((fn, i) => new Location({ + id: i + 1, + line: [new Line({ functionId: i + 1, line: fn.line })] + })) + return new Profile({ + sampleType: [ + new ValueType({ type: stringTable.dedup('sample'), unit: stringTable.dedup('count') }), + new ValueType({ type: stringTable.dedup('wall'), unit: stringTable.dedup('nanoseconds') }) + ], + sample: [ + // readX called from outer: 3 samples, readX is the leaf + new Sample({ locationId: [2, 4], value: [1, 300] }), + // outer alone + new Sample({ locationId: [4], value: [1, 100] }) + ], + location: locations, + function: functions, + stringTable + }) +} + +test('getProfileFunctions falls back to location lines', async () => { + const profile = await makeProfile() + assert.deepStrictEqual(getProfileFunctions(profile), PROFILE_FUNCTIONS) +}) + +test('the payload round-trips through an encoded profile', async () => { + const { Profile } = await import('pprof-format') + const profile = await makeProfile() + const payload = buildDeoptPayload(parseDeoptTrace(TRACE), getProfileFunctions(profile)) + attachDeoptPayload(profile, payload) + + const decoded = Profile.decode(profile.encode()) + assert.deepStrictEqual(extractDeoptPayload(decoded), payload) +}) + +test('extractDeoptPayload ignores other comments', async () => { + const profile = await makeProfile() + profile.comment = [profile.stringTable.dedup('hello'), profile.stringTable.dedup('{"type":"v8-deopts" broken')] + assert.strictEqual(extractDeoptPayload(profile), null) +}) + +test('formatDeoptMarkdown lists actionable deopts with time shares', async () => { + const profile = await makeProfile() + assert.strictEqual(await formatDeoptMarkdown(profile), '') + + attachDeoptPayload(profile, buildDeoptPayload(parseDeoptTrace(TRACE), getProfileFunctions(profile))) + const markdown = await formatDeoptMarkdown(profile) + + assert.match(markdown, /## V8 Deoptimizations/) + assert.match(markdown, /5 deoptimizations in 4 functions were recorded while profiling, 2 of them normal tiering/) + // readX: 75% self, outer: 25% self / 100% total + assert.match(markdown, /\| `readX` \| \/app\/lib\.js:4 \| 75\.0% \| 75\.0% \| 2 \| wrong map \|/) + assert.match(markdown, /\| `outer` \| \/app\/lib\.js:10 \| 25\.0% \| 100\.0% \| 1 \| not a Smi \|/) + // Tiering-only functions are not listed + assert.doesNotMatch(markdown, /anonymous:L#1/) + assert.match(markdown, /- \*\*wrong map\*\* \(`WrongMap`, eager\) ×2 at \/app\/lib\.js:5:31/) +}) + +test('flame run --deopt attaches deopts to the CPU profile', { timeout: 60000 }, async (t) => { + const cwd = fs.mkdtempSync(path.join(os.tmpdir(), 'flame-deopt-test-')) + t.after(() => fs.rmSync(cwd, { recursive: true, force: true })) + + const script = path.join(__dirname, 'fixtures', 'deopt-script.js') + const cli = path.join(__dirname, '..', 'bin', 'flame.js') + const child = spawn('node', [cli, 'run', '--deopt', '--delay=none', script], { cwd, stdio: 'pipe' }) + + let stdout = '' + child.stdout.on('data', (data) => { stdout += data }) + child.stderr.on('data', (data) => { stdout += data }) + const code = await new Promise(resolve => child.on('close', resolve)) + + assert.strictEqual(code, 0, stdout) + assert.match(stdout, /deopt-script done true/) + assert.match(stdout, /Recorded \d+ V8 deopts in \d+ functions/) + // V8's deopt traces go to a file, not to the application's output + assert.doesNotMatch(stdout, /\[bailout/) + + const cpuProfile = fs.readdirSync(cwd).find(f => f.startsWith('cpu-profile-') && f.endsWith('.pb')) + assert.ok(cpuProfile, 'CPU profile should be written') + + const { parseProfile } = require('../lib/index.js') + const profile = await parseProfile(path.join(cwd, cpuProfile)) + const payload = extractDeoptPayload(profile) + assert.ok(payload, 'CPU profile should carry deopts') + + const scriptFunctions = payload.functions.filter(fn => fn.file === script) + assert.ok(scriptFunctions.length > 0, 'deopts should be attributed to the script') + + // Deopts are attributed to functions of the profile, by the same name and line + const profileFunctions = getProfileFunctions(profile) + for (const fn of scriptFunctions) { + assert.ok( + profileFunctions.some(p => p.name === fn.name && p.file === fn.file && p.line === fn.line) || fn.line === 0, + `${fn.name}:${fn.line} should match a profile function` + ) + } + + // The markdown report includes the deopts + const markdown = fs.readFileSync(path.join(cwd, cpuProfile.replace('.pb', '.md')), 'utf8') + assert.match(markdown, /## V8 Deoptimizations/) +}) diff --git a/test/fixtures/deopt-script.js b/test/fixtures/deopt-script.js new file mode 100644 index 0000000..b26781d --- /dev/null +++ b/test/fixtures/deopt-script.js @@ -0,0 +1,34 @@ +'use strict' + +// Deoptimizes repeatedly while the profiler runs (used with --delay=none) +function readX (o) { + return o.x + o.y +} + +function makeShape (i) { + switch (i % 4) { + case 0: return { x: i, y: 1 } + case 1: return { y: 1, x: i } + case 2: return { x: i, y: 1, z: 2 } + default: return { z: 2, y: 1, x: i } + } +} + +function sum (arr) { + let total = 0 + for (let i = 0; i < arr.length; i++) total += arr[i] + return total +} + +let acc = 0 +for (let round = 0; round < 100; round++) { + for (let i = 0; i < 20000; i++) acc += readX({ x: i, y: 1 }) + for (let i = 0; i < 20000; i++) acc += readX(makeShape(i)) + const a = [] + for (let i = 0; i < 5000; i++) a.push(i) + acc += sum(a) + a.push(1.5) + acc += sum(a) +} + +console.log('deopt-script done', acc > 0)