Fixing wrong symbols in Node.js CPU Frame Graphs

README.md

Fixing wrong symbols in Node.js CPU Frame Graphs

Motivation

I have been generating CPU Flame Graphs of Node.js applications with Linux perf command, and noticed that some of the graphs have suspicious labels. For example, with a sandbox project and Node 10.8.0, I got LazyCompile:*a.renderDOM /opt/app/node_modules/react-dom/cjs/react-dom-server.node.production.min.js:35 where it should have been something related to streams.

For example, the following is a stack trace from perf script that I used to genearte a CPU Flame Graph. 227bbdff955b has a label LazyCompile:*a.renderDOM, but it doesn't make much sense that React.renderDOM was called from _stream_readable.js and parsed JSON in it.

node 22640 56531.256247:   10101010 cpu-clock: 
	    7fff9f6b72cb finish_task_switch ([kernel.kallsyms])
	    7fff9ff92f6f __schedule ([kernel.kallsyms])
	    7fff9ff935ac schedule ([kernel.kallsyms])
	    7fff9f6055c9 exit_to_usermode_loop ([kernel.kallsyms])
	    7fff9f605b85 do_syscall_64 ([kernel.kallsyms])
	    7fffa0002081 entry_SYSCALL_64_after_hwframe ([kernel.kallsyms])
	            c715 pthread_cond_signal@@GLIBC_2.3.2 (/lib/x86_64-linux-gnu/libpthread-2.19.so)
// ...
	          b79110 _ZN2v88internal10JsonParserILb1EE14ParseJsonValueEv (/usr/local/bin/node)
	          b79173 _ZN2v88internal10JsonParserILb1EE9ParseJsonEv (/usr/local/bin/node)
	          78f1a8 _ZN2v88internal17Builtin_JsonParseEiPPNS0_6ObjectEPNS0_7IsolateE (/usr/local/bin/node)
	    227bbdc8a1dd [unknown] (/tmp/perf-22640.map)
/* ??? */   227bbdff955b LazyCompile:*a.renderDOM /opt/app/node_modules/react-dom/cjs/react-dom-server.node.production.min.js:35 (/tmp/perf-22640.map)
	    227bbdcfb0a1 LazyCompile:*endReadableNT _stream_readable.js:1074 (/tmp/perf-22640.map)
	    227bbdfd4f31 [unknown] (/tmp/perf-22640.map)
	    227bbdc90f95 Builtin:JSEntryTrampoline (/tmp/perf-22640.map)
	    227bbdc8a4a1 [unknown] (/tmp/perf-22640.map)
	          a597f3 _ZN2v88internal9Execution4CallEPNS0_7IsolateENS0_6HandleINS0_6ObjectEEES6_iPS6_ (/usr/local/bin/node)
	          6e84b3 _ZN2v88Function4CallENS_5LocalINS_7ContextEEENS1_INS_5ValueEEEiPS5_ (/usr/local/bin/node)
	          6e8671 _ZN2v88Function4CallENS_5LocalINS_5ValueEEEiPS3_ (/usr/local/bin/node)
// ...

I noticed that suspicious ones appeared more often in long-running processes than in fresh processes. So I guessed that locations of symbols in V8 changed over time.

Find an address in the symbol map

So, I wrote a small script to find an address in /tmp/perf-${pid}.map.

node symbols.js find /tmp/perf-${pid}.map ${address}

And when I ran it...

$ node symbols.js find /tmp/perf-22640.map 227bbdff955b
Total: 3285 entries
Fresh: 2063 entries
All Matches: 4 entries
    227bbdff8940 1942 LazyCompile:*a.renderDOM /opt/app/node_modules/react-dom/cjs/react-dom-server.node.production.min.js:35
    227bbdff8940 1942 LazyCompile:*a.renderDOM /opt/app/node_modules/react-dom/cjs/react-dom-server.node.production.min.js:35
    227bbdff9420 1942 LazyCompile:*a.renderDOM /opt/app/node_modules/react-dom/cjs/react-dom-server.node.production.min.js:35
    227bbdff9420 2a0 LazyCompile:*stream.on /opt/app/src/api.js:44
Fresh Matches: 1 entries
    227bbdff9420 2a0 LazyCompile:*stream.on /opt/app/src/api.js:44

The output means that the address was used for a.renderDOM for a while, but was reused for stream.on later. Because of this, perf script picked up the old label, LazyCompile:*a.renderDOM instead of LazyCompile:*stream.on.

Remove outdated addresses

node symbols.js tidy /tmp/perf-${pid}.map ${output_filename}

This command checks intersections of addresses and removes old entries that intersect with new entries. It should work as long as symbols don't move while perf record and perf script are running.

Update stack traces

Sometimes, it's not ideal to update /tmp/perf-${pid}.map. In that case, we can generate a stacktrace file with perf script without modifying /tmp/perf-${pid}.map and update the stacktrace file later.

for f in /tmp/perf-*.map
do
  pid=${f//[^0-9]/}
  node symbol.js update perf-${pid}.map stacks.${pid}.out stacks.${pid}.out.updated
done

To be accurate...

The solutions above may still can have a few wrong symbols if functions move around during perf record. If it's an issue, We can try merging mutiple symbols like "*stream.on /opt/app/src/api.js:44" or "LazyCompile:*a.renderDOM /opt/app/node_modules/react-dom/cjs/react-dom-server.node.production.min.js:35".

symbols.js

const fs = require('fs');
const path = require('path');

const availableCommands = [
  'tidy',
  'find',
  'update',
];

const command = process.argv[2];
if (!availableCommands.includes(command)) {
  console.error(`Available commands: ${availableCommands.join(', ')}`);
  process.exit(1);
}
const filename = process.argv[3];
if (!filename) {
  console.error('Symbol file name should be given');
  process.exit(1);
}

// Get entries
const content = fs.readFileSync(filename, { encoding: 'utf8' });
const entries = content.split(/\r?\n/).filter(Boolean).map(line => {
  const components = line.split(' ');
  return {
    start: parseInt(components[0], 16),
    size: parseInt(components[1], 16),
    name: components.slice(2).join(' '),
  };
});
console.log(`Total: ${entries.length} entries`);

// Mark outdated: O(N^2)
// TODO: Use better algorithm if necessary
const outdated = new WeakSet();
entries.forEach((entry, i) => {
  for (let j = 0; j < i; j++) {
    const previousEntry = entries[j];
    if (intersect(entry, previousEntry)) {
      outdated.add(previousEntry);
    }
  }
});
const freshEntries = entries.filter(entry => !outdated.has(entry));
console.log(`Fresh: ${freshEntries.length} entries`);

switch (command) {
  case 'find': {
    const address = parseInt(process.argv[4], 16);
    if (Number.isNaN(address)) {
      console.error('Address should be a hex number');
      process.exit(1);
    }
    const matches = entries.filter(entry => inRange(address, entry));
    printEntries('All Matches', matches);

    const freshMatches = freshEntries.filter(entry => inRange(address, entry));
    printEntries('Fresh Matches', freshMatches);
  }
  case 'tidy': {
    const outFilename = process.argv[4];
    if (!outFilename) {
      console.error('Output filename should be given');
      process.exit(1);
    }
    const output = freshEntries.map(stringifyEntry).join('\n');
    fs.writeFileSync(path.resolve(outFilename), output);
  }
  case 'update': {
    const stackFilename = process.argv[4];
    const outFilename = process.argv[5];
    if (!stackFilename) {
      console.error('Stack trace filename should be given');
      process.exit(1);
    }
    if (!outFilename) {
      console.error('Output filename should be given');
      process.exit(1);
    }

    const stacks = fs.readFileSync(stackFilename, { encoding: 'utf8' });
    const output = stacks.split(/\r?\n/).map((line) => {
      const pattern = /^(\s+)([0-9a-f]+) (.+) (\(\/tmp\/perf-[0-9]+\.map\))$/;
      const match = pattern.exec(line);
      if (!match) {
        return line;
      }
      const [_, space, addressStr, symbol, filename] = match;
      const address = parseInt(addressStr, 16);
      const newSymbol = findSymbol(freshEntries, address) || symbol;
      return `${space}${addressStr} ${newSymbol} ${filename}`;
    }).join('\n');
    fs.writeFileSync(path.resolve(outFilename), output);
  }
}

function inRange(address, { start, size }) {
  return start <= address && address < start + size;
}

function intersect(a, b) {
  // Make sure that `a` is earlier than `b`.
  if (a.start > b.start) {
    return intersect(b, a);
  }
  return a.start + a.size > b.start;
}

function printEntries(label, entries) {
  console.log(`${label}: ${entries.length} entries`);
  entries.forEach(entry => {
    console.log(`    ${stringifyEntry(entry)}`);
  });
}

function stringifyEntry(entry) {
    return `${entry.start.toString(16)} ${entry.size.toString(16)} ${entry.name}`;
}

function findSymbol(entries, address) {
  const found = entries.find(entry => inRange(address, entry));
  return found && found.name;
}

How --perf-basic-prof-only-functions flag was added to v8: https://bugs.chromium.org/p/v8/issues/detail?id=3453

Not fully tested, but a faster version https://gist.github.com/shuhei/1b0ca2735298ae331ec6b402d3bb7e70