nodejs profiling; what can 'Unknown' be

Question

While profiling a nodejs program, I see that 61% of the ticks are caused by 'Unknown' (see below). What can this be? What should I look for?

gr,

Coen

Statistical profiling result from node, (14907 ticks, 9132 unaccounted, 0 excluded).

 [Unknown]:
   ticks  total  nonlib   name
   9132   61.3%

 [Shared libraries]:
   ticks  total  nonlib   name
   1067    7.2%    0.0%  C:\Windows\SYSTEM32\ntdll.dll
     55    0.4%    0.0%  C:\Windows\system32\kernel32.dll

 [JavaScript]:
   ticks  total  nonlib   name
   1381    9.3%   10.0%  LazyCompile: *RowDataPacket.parse D:\MI\packet.js:9
......

Answer 1

Are you loading any modules that have built dependencies?

Basically by "Unknown" it means "unaccounted for" (check tickprocessor.js for more explanation). For example, the GC will print messages like "scavenge,begin,..." but that is unrecognized by logreader.js.

It would help to know what profiling library your using to parse the v8.log file.

Update

The node-tick package hasn't been updated for over a year and is probably missing a lot of recent prof commands. Try using node-profiler instead. It's created by one of node's maintainers. And if you want the absolute best result you'll need to build it using node-gyp.

Update

I've parsed the v8.log output using the latest from node-profiler (the latest on master, not the latest tag) and posted the results at http://pastebin.com/pdHDPjzE

Allow me to point out a couple key entries which appear about half way down:

[GC]:
  ticks  total  nonlib   name
  2063   26.2%

[Bottom up (heavy) profile]
6578   83.4%  c:\node\node.exe
1812   27.5%    LazyCompile: ~parse native json.js:55
1811   99.9%      Function: ~<anonymous> C:\workspace\repositories\asyncnode_MySQL\lib\MySQL_DB.js:41
 736   11.2%    Function: ~Buffer.toString buffer.js:392

So 26.2% of all script type was spent in garbage collection. Which is much higher than it should be. Though it does correlate well with how much time is spent on Buffer.toString. If that many Buffers are being created then converted to strings, both would need to be gc'd when they leave scope.

Also I'm curious why so much time is spent in LazyCompile for json.js. Or more so, why would json.js even be necessary in a node application?

To help you performance tune your application I'm including a few links below that give good instructions on what to do and look for.

Nice slide deck with the basics:
https://mkw.st/p/gdd11-berlin-v8-performance-tuning-tricks/#1

More advanced examples of optimization techniques:
http://floitsch.blogspot.com/2012/03/optimizing-for-v8-introduction.html

Better use of closures:
http://mrale.ph/blog/2012/09/23/grokking-v8-closures-for-fun.html

Now as far as why you couldn't achieve the same output. If you built and used node-profiler and its provided nprof from master and it still doesn't work then I'll assume it has something to do with being on Windows. Think about filing a bug on GitHub and see if he'll help you out.

Answer 2

You are using a 64 bit version of Node.JS to run your application and a 32bit build of the d8 shell to process your v8.log. Using either a 32 bit version of Node.JS with ia32 as the build target for the d8 shell or a 64 bit version of Node.JS with x64 as the d8 shell build target should solve your problem.

Answer 3

Try to build v8 with profiling support on:

scons prof=on d8

Make sure you run node --prof with version corresponding to version of v8

Then tools/linux-tick-processor path/to/v8.log should show you the full profile info.