How to read nodejs internal profiler tick-processor output

Question

I'm interested in profiling my Node.js application. I've started it with --prof flag, and obtained a v8.log file. I've taken the windows-tick-processor and obtained a supposedly human readable profiling log. At the bottom of the question are a few a small excerpts from the log file, which I am completely failing to understand.

I get the ticks statistical approach. I don't understand what total vs nonlib means. Also I don't understand why some things are prefixed with LazyCompile, Function, Stub or other terms.

The best answer I could hope for is the complete documentation/guide to the tick-processor output format, completely explaining every term, structure etc...

Barring that, I just don't understand what lazy-compile is. Is it compilation? Doesn't every function get compiled exactly once? Then how can compilation possibly be a significant part of my application execution? The application ran for hours to produce this log, and I'm assuming the internal JavaScript compilation takes milliseconds. This suggests that lazy-compile is something that doesn't happen once per function, but happens during some kind of code evaluation? Does this mean that everywhere I've got a function definition (for example a nested function), the internal function gets "lazy-compiled" each time?

I couldn't find any information on this anywhere, and I've been googling for DAYS...

Also I realize there are a lot of profiler flags. Additional references on those are also welcome.

[JavaScript]:
   ticks  total  nonlib   name
  88414    7.9%   20.1%  LazyCompile: *getUniqueId C:\n\dev\SCNA\infra\lib\node-js\utils\general-utils.js:16
  22797    2.0%    5.2%  LazyCompile: *keys native v8natives.js:333
  14524    1.3%    3.3%  LazyCompile: Socket._flush C:\n\dev\SCNA\runtime-environment\load-generator\node_modules\zmq\lib\index.js:365
  12896    1.2%    2.9%  LazyCompile: BasicSerializeObject native json.js:244
  12346    1.1%    2.8%  LazyCompile: BasicJSONSerialize native json.js:274
   9327    0.8%    2.1%  LazyCompile: * C:\n\dev\SCNA\runtime-environment\load-generator\node_modules\zmq\lib\index.js:194
   7606    0.7%    1.7%  LazyCompile: *parse native json.js:55
   5937    0.5%    1.4%  LazyCompile: *split native string.js:554
   5138    0.5%    1.2%  LazyCompile: *Socket.send C:\n\dev\SCNA\runtime-environment\load-generator\node_modules\zmq\lib\index.js:346
   4862    0.4%    1.1%  LazyCompile: *sort native array.js:741
   4806    0.4%    1.1%  LazyCompile: _.each._.forEach C:\n\dev\SCNA\infra\node_modules\underscore\underscore.js:76
   4481    0.4%    1.0%  LazyCompile: ~_.each._.forEach C:\n\dev\SCNA\infra\node_modules\underscore\underscore.js:76
   4296    0.4%    1.0%  LazyCompile: stringify native json.js:308
   3796    0.3%    0.9%  LazyCompile: ~b native v8natives.js:1582
   3694    0.3%    0.8%  Function: ~recursivePropertiesCollector C:\n\dev\SCNA\infra\lib\node-js\utils\object-utils.js:90
   3599    0.3%    0.8%  LazyCompile: *BasicSerializeArray native json.js:181
   3578    0.3%    0.8%  LazyCompile: *Buffer.write buffer.js:315
   3157    0.3%    0.7%  Stub: CEntryStub
   2958    0.3%    0.7%  LazyCompile: promise.promiseDispatch C:\n\dev\SCNA\runtime-environment\load-generator\node_modules\q\q.js:516


88414    7.9%  LazyCompile: *getUniqueId C:\n\dev\SCNA\infra\lib\node-js\utils\general-utils.js:16
  88404  100.0%    LazyCompile: *generateId C:\n\dev\SCNA\infra\lib\node-js\utils\general-utils.js:51
  88404  100.0%      LazyCompile: *register C:\n\dev\SCNA\infra\lib\node-js\events\pattern-dispatcher.js:72
  52703   59.6%        LazyCompile: * C:\n\dev\SCNA\runtime-environment\load-generator\lib\vuser-driver\mdrv-driver.js:216
  52625   99.9%          LazyCompile: *_.each._.forEach C:\n\dev\SCNA\runtime-environment\load-generator\node_modules\underscore\underscore.js:76
  52625  100.0%            LazyCompile: ~usingEventHandlerMapping C:\n\dev\SCNA\runtime-environment\load-generator\lib\vuser-driver\mdrv-driver.js:214
  35555   40.2%        LazyCompile: *once C:\n\dev\SCNA\infra\lib\node-js\events\pattern-dispatcher.js:88
  29335   82.5%          LazyCompile: ~startAction C:\n\dev\SCNA\runtime-environment\load-generator\lib\vuser-driver\mdrv-driver.js:201
  25687   87.6%            LazyCompile: ~onActionComplete C:\n\dev\SCNA\runtime-environment\load-generator\lib\vuser-driver\mdrv-logic.js:130
   1908    6.5%            LazyCompile: ~b native v8natives.js:1582
   1667    5.7%            LazyCompile: _fulfilled C:\n\dev\SCNA\runtime-environment\load-generator\node_modules\q\q.js:795
   4645   13.1%          LazyCompile: ~terminate C:\n\dev\SCNA\runtime-environment\load-generator\lib\vuser-driver\mdrv-driver.js:160
   4645  100.0%            LazyCompile: ~terminate C:\n\dev\SCNA\runtime-environment\load-generator\lib\vuser-driver\mdrv-logic.js:171
   1047    2.9%          LazyCompile: *startAction C:\n\dev\SCNA\runtime-environment\load-generator\lib\vuser-driver\mdrv-driver.js:201
   1042   99.5%            LazyCompile: ~onActionComplete C:\n\dev\SCNA\runtime-environment\load-generator\lib\vuser-driver\mdrv-logic.js:130

Vladislav Ivanishin Vladislav Ivanishin · Accepted Answer · 2014-11-09T23:43:54

Indeed, you are right in your assumption about time actually spent compiling the code: it takes milliseconds (which could be seen with --trace-opt flag).

Now talking about that LazyCompile. Here is a quotation from Vyacheslav Egorov's (former v8 dev) blog:

If you are using V8's tick processors keep in mind that LazyCompile: prefix does not mean that this time was spent in compiler, it just means that the function itself was compiled lazily.

An asterisk before a function name means that time is being spent in optimized function, tilda -- not optimized.

Concerning your question about how many times a function gets compiled. Actually the JIT (so-called full-codegen) creates a non-optimized version of each function when it gets executed for the first time. But later on an arbitrary (well, to some extent) number or recompilations could happen (due to optimizations and bail-outs). But you won't see any of it in this kind of profiling log.

Stub prefix to the best of my understanding means the execution was inside a C-Stub, which is a part of runtime and gets compiled along with other parts of the engine (i.e. it is not JIT-compiled JS code).

total vs. nonlib:

These columns simply mean than x% of total/non-lib time was spent there. (I can refer you to a discussion here).

Also, you can find https://github.com/v8/v8/wiki/Using%20V8%E2%80%99s%20internal%20profiler useful.

How to read nodejs internal profiler tick-processor output

1 Answers