nodejs / node-v0.x-archive

Moved to https://github.com/nodejs/node
34.44k stars 7.3k forks source link

v8: --prof_lazy causes unaccounted ticks in call graph #4209

Closed bnoordhuis closed 9 years ago

bnoordhuis commented 11 years ago

This is a V8 bug but if we don't fix it, no one will. :-)

To reproduce:

$ cat test.js
require("profiler").resume();
require("fs").readFile("v8.log", function(){});
$ npm install -g profiler
$ node --log --prof --prof_lazy script.js
$ nprof v8.log
Unknown PC: 0x8226d49
Unknown PC: 0xf7fdb430
Statistical profiling result from v8.log, (2 ticks, 2 unaccounted, 0 excluded).

 [Unknown]:
   ticks  total  nonlib   name
      2  100.0%

 [Shared libraries]:
   ticks  total  nonlib   name

 [JavaScript]:
   ticks  total  nonlib   name
      1   50.0%   50.0%  LazyCompile: ~process._makeCallback node.js:241
      1   50.0%   50.0%  LazyCompile: ~<anonymous> fs.js:307

 [C++]:
   ticks  total  nonlib   name

 [GC]:
   ticks  total  nonlib   name
      0    0.0%

 [Bottom up (heavy) profile]:
  Note: percentage shows a share of a particular caller in the total
  amount of its parent calls.
  Callers occupying less than 2.0% are not shown.

   ticks parent  name
      1   50.0%  LazyCompile: ~process._makeCallback node.js:241

      1   50.0%  LazyCompile: ~<anonymous> fs.js:307
      1  100.0%    LazyCompile: ~process._makeCallback node.js:241

The salient parts:

 [Shared libraries]:
   ticks  total  nonlib   name

Shared libraries are not logged. This is fixed pending http://codereview.chromium.org/11309007

Unknown PC: 0x8226d49
Unknown PC: 0xf7fdb430

The addresses correspond to the PROT_EXEC pages that V8 mmaps, i.e. where generated code is stored.

Apparently V8 doesn't log the code generation event when the profiler is paused. That makes sense in a way but it severely limits the usefulness of --prof_lazy and is likely unintentional.

piscisaureus commented 11 years ago

I am pretty sure they keep track, but they may not flush it to the log file when the profiler is started.