Totally failing on profiling my application

[Nicolas Chambrier]

Hello,

I'm desperately trying to profile my application, like I used to do with other languages where I could output some file I could pass to kcachegrind which would show me when and where the runtime executed my code.

I'm running Ubuntu or Debian VM, whatever I've tried several methods:

• Using dtrace on SmartOS: OK I can run dtrace, but I'm absolutely lost on SmartOS and I need many bricks like Redis and MongoDB I'm not sure how to install properly (I've compiled everything, which was a pita). Plus I'm not a sysadmin, which makes me waste ages each time I need to configure anything. Not forgetting the most recent provided zone (node-1.3.3) includes node v0.6.8. Dafuq ?
• Using node --prof seemed very promising: simple, everything is embedded, cool :) I can generate a v8.log, OK. But then when I run "deps/v8/tools/linux-tick-processor" on it, I get no output, just an exit code 126. No idea what it means, I couldn't find information about this :(
• Using valgrind I can output a callgrind file I can then use with kcachegrind. It's cool and I get real values, I can practically see the call chain, but I can't see my real function names. Instead I get some hexadecimal names, v8:: and node:: internals. That makes it quite useless for me :(
• nodetime is great, but I'd really like a tool that doesn't rely on external service. Even if I finally stick with this solution, I need to have an alternative.

Does someone know where error 126 comes from in linux-tick-processor ?

Does what I'm looking for only exist: a profiler that would output stack and durations with the actual function names ? And easy to use on Linux x]

Thanks a lot for all the information you can provide! I really want to get through that this time ;)

[Ben Noordhuis]

Fedor has a callgrind script here[1].

Can you `npm install profiler` and check if nprof parses your v8.log
file? If not, can you open a node-profiler issue?

[1] https://github.com/indutny/callgrind.js

[Addison Higham]

In the same boat with nodetime.

Recently stumbled across this project: https://github.com/baryshev/look

Its basically a local nodetime client.

I haven't used it quite yet, but it looks promising.

--
Job Board: http://jobs.nodejs.org/
Posting guidelines: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
You received this message because you are subscribed to the Google
Groups "nodejs" group.
To post to this group, send email to nod...@googlegroups.com
To unsubscribe from this group, send email to
nodejs+un...@googlegroups.com
For more options, visit this group at
http://groups.google.com/group/nodejs?hl=en?hl=en

[Andrey]

Try node-tick-processor to read your v8.log - https://github.com/sidorares/node-tick

[Nicolas Chambrier]

Thanks for your answers. nprof and node-tick-processor have worked properly and I could retrieve information from v8.log. Now I just have to learn how to use it, it's not as obvious as I could imagine: still no function name for example :( I've made a dumb script with a fibo + other functions, and I can't see how to make the profiler tell me "fibo() is taking all your CPU". If you have any good resources to learn that, I'd be glad ;)

Thanks too for the "look" module, I'll give a try it sounds really  interesting.

I only profiled PHP and Java apps until now, and outputs are very clear, maybe this difficulty is generic to C++ apps ?

[Nicolas Chambrier]

I'll show you what I've done to train until now, so you may better understand what I'm looking for in case I'm not very clear ^^

So I wrote a basic script:

function hello() {

  console.log('.');

}

function fibo(n, cb) {

  if (n === 0) {

    process.nextTick(cb.bind(null, 0));

  } else if (n === 1) {

    process.nextTick(cb.bind(null, 1));

  } else {

    var n1, n2;

    process.nextTick(fibo.bind(null, n-1, function(n){ n1 = n; next(); }));

    process.nextTick(fibo.bind(null, n-2, function(n){ n2 = n; next(); }));

    function next() {

      if (typeof n1 === 'undefined' || typeof n2 === 'undefined') {

        return;

      }

      process.nextTick(cb.bind(null, n1+n2));

    }

  }

}

var interval = setInterval(hello, 100);

fibo(24, function (n) {

  clearInterval(interval);

  console.log(n);

});

It produces following output, where I can see how the event loop is blocked, and the whole point is to detect who is blocking it (here it's obviously fibo() but I train for less obvious cases ;))

$ time node fibo.js                                                                                                                                  ] 9:43 

.

.

.

.

.

46368

node fibo.js  0,95s user 0,06s system 99% cpu 1,021 total

nprof produces the following output:

Statistical profiling result from v8.log, (914 ticks, 0 unaccounted, 0 excluded).

…

 [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

    741   81.1%  /usr/local/bin/node

    187   25.2%    LazyCompile: bind native v8natives.js:1456

    143   76.5%      LazyCompile: *fibo /home/nchambrier/Bureau/fibo.js:5

    143  100.0%        Function: ~d native v8natives.js:1480

    142   99.3%          LazyCompile: *startup.processNextTick.process._tickCallback node.js:185

     44   23.5%      Function: ~next /home/nchambrier/Bureau/fibo.js:14

     30   68.2%        Function: ~process.nextTick.fibo.bind.n2 /home/nchambrier/Bureau/fibo.js:12

     30  100.0%          Function: ~d native v8natives.js:1480

     30  100.0%            LazyCompile: *startup.processNextTick.process._tickCallback node.js:185

     14   31.8%        Function: ~<anonymous> /home/nchambrier/Bureau/fibo.js:13

     14  100.0%          Function: ~d native v8natives.js:1480

     14  100.0%            LazyCompile: *startup.processNextTick.process._tickCallback node.js:185

…

I feel like the bold line is interesting, and I'm tempted to interpret it as "fibo() takes 76.5% of the whole CPU", but it's not so simple.

I'll give another try to valgrind, just in case.

[Vyacheslav Egorov]

> I feel like the bold line is interesting, and I'm tempted to interpret it as
> "fibo() takes 76.5% of the whole CPU", but it's not so simple.

Please read the comment about the profile:

Note: percentage shows a share of a particular caller in the total
amount of its parent calls.

In any case with with statistical profiler "function Foo takes X ticks
out of Y ticks recorded total" should be read as "profiler looked at
the program Y times and in X times he saw function Foo near the top of
the stack". Statistical profiler results do not translate into
information about event loop blocking or CPU cycles spent by
functions.

--
Vyacheslav Egorov

[Nicolas Chambrier]

Oh OK, I absolutely missed the point about statistical profiler. I see a lot more clearly now, thanks for your explanation.

The interpretation is quite hard then, it will require some experience ;)

--
Nicolas Chambrier, aka naholyr

Blog : http://naholyr.fr
Formateur Clever Institut : http://clever-institut.com/formateur/nicolas-chambrier