Skip to content

Time profile writes each function's definition line into Line.line, omits Function.start_line, and merges same-named functions into one Function #361

Description

@TomerAberbach

The time profiler's serializer misplaces line information, so a pprof consumer attributes every sample of a function to its definition line and cannot tell same-named functions apart.

Reproduction (repro.cjs): two distinct functions named run defined at lines 6 and 17, each burning CPU at lines 11 and 22, plus two distinct methods defined at lines 32 and 37 that V8's profiler reports under one inferred name:

const pprof = require("pprof");

// Two distinct functions, both named `run`, defined at lines 6 and 17.
// Each burns CPU on a line several lines below its definition (11 and 22).
const a = {
  run() {
    // padding so the executing line differs from the definition line
    //
    //
    let x = 0;
    for (let i = 0; i < 5e7; i++) x += Math.sqrt(i);
    return x;
  },
};

const b = {
  run() {
    //
    //
    //
    let x = 0;
    for (let i = 0; i < 5e7; i++) x += Math.cbrt(i);
    return x;
  },
};

// Two distinct methods V8's profiler reports under one inferred name,
// defined at lines 32 and 37, with loops at 34 and 39.
const s1 = Symbol();
const s2 = Symbol();
const workers = {
  [s1]() {
    let x = 0;
    for (let i = 0; i < 5e7; i++) x += Math.log1p(i);
    return x;
  },
  [s2]() {
    let x = 0;
    for (let i = 0; i < 5e7; i++) x += Math.atan(i);
    return x;
  },
};

const stop = pprof.time.start(1000);
const total = a.run() + b.run() + workers[s1]() + workers[s2]();
const profile = stop();

// `stop()` returns the profile as the package's own protobufjs model.
const num = (v) =>
  v && typeof v.toNumber === "function" ? v.toNumber() : Number(v ?? 0);
const str = (i) => profile.stringTable[num(i)] ?? "";
const functions = new Map(profile.function.map((fn) => [num(fn.id), fn]));
const linesByFunction = new Map();
for (const location of profile.location) {
  for (const line of location.line) {
    const id = num(line.functionId);
    let lines = linesByFunction.get(id);
    if (!lines) linesByFunction.set(id, (lines = new Set()));
    lines.add(num(line.line));
  }
}

for (const [id, lines] of linesByFunction) {
  const fn = functions.get(id);
  if (!str(fn.filename).endsWith("repro.cjs")) continue;
  console.log({
    name: str(fn.name),
    startLine: num(fn.startLine),
    lineValues: [...lines].sort((x, y) => x - y),
  });
}

Actual output (node repro.cjs):

{ name: '(anonymous)', startLine: 0, lineValues: [ 1 ] }
{ name: 'workers', startLine: 0, lineValues: [ 32, 37 ] }
{ name: 'run', startLine: 0, lineValues: [ 6, 17 ] }

Both runs share one Function entry, both workers methods share another, start_line is 0 everywhere, and every Line.line value is a definition line (6, 17, 32, 37). The lines the samples hit (11, 22, 34, 39) appear nowhere in the profile.

Expected: one Function entry per function with start_line at its definition line (6, 17, 32, 37), and Line.line at the sampled lines (11, 22, 34, 39). The pprof format defines Function.start_line as the function's line (profile.proto#L231-L232), and a Location as an instruction address whose Line is the source line at that address (profile.proto#L181-L216). go tool pprof's source view attributes samples by Line.line.

Environment: pprof 5.0.0 (current latest), Node.js v26.7.0, macOS (Darwin arm64). The native addon was built from source with clang, since no prebuilt binary exists for this Node version (#300). The serializer under report is the TypeScript side, unaffected by how the addon was built.

Cause, from reading the serializer at current main:

  • getLocation takes node.lineNumber as the location's line (profile-serializer.ts#L147, reaching Line.line at #L182-L185). V8 documents CpuProfileNode::GetLineNumber as "the number, 1-based, of the line where the function originates" (v8-profiler.h#L141), a definition line rather than a sampled one.
  • getFunction constructs the Function without startLine (profile-serializer.ts#L202-L207), so the definition line the profiler does have never reaches the field the spec defines for it.
  • getFunction keys functions by ${scriptId}:${name} (profile-serializer.ts#L193), so it merges every same-named function in a script. Since the key uses the name before the (anonymous) default is applied, a frame V8 reports with no name should fall into a single per-script entry keyed ${scriptId}:undefined the same way. This is read from the source, not exercised by the repro above, where V8 inferred a name for every frame.

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions