Как читать вывод процессора-обработчика nodejs

Мне интересно профилировать мое приложение Node.js. Я начал его с флага --prof и получил файл v8.log. Я взял обработчик windows-tick и получил якобы читаемый человеком журнал профилирования. В нижней части вопроса находятся несколько небольших отрывков из файла журнала, которые я полностью не понимаю.

Я получаю статистический подход тиков. Я не понимаю, что означает total vs nonlib. Также я не понимаю, почему некоторые вещи имеют префикс LazyCompile, Function, Stub или другие термины.

Лучший ответ, на который я мог бы надеяться, - полная документация/руководство по выходному формату tick-processor, полностью объясняющая каждый термин, структуру и т.д.

Запрет на то, что я просто не понимаю, что такое ленивый компилятор. Это компиляция? Разве не каждую команду компилируется ровно один раз? Тогда как компиляция может быть значительной частью выполнения моего приложения? Приложение работало часами, чтобы создать этот журнал, и я предполагаю, что внутренняя компиляция JavaScript занимает миллисекунды. Это говорит о том, что ленивый компилятор - это то, что не происходит один раз за функцию, но происходит во время какой-либо оценки кода? Означает ли это, что везде, где у меня есть определение функции (например, вложенная функция), внутренняя функция получает "lazy-compiled" каждый раз?

Я не мог найти никакой информации об этом в любом месте, и я искал в Google DAYS...

Также я понимаю, что есть много флагов профайлера. Дополнительные ссылки на них также приветствуются.

[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

Ответы

Ответ 1

В самом деле, вы правы в своем предположении о том, что время фактически потрачено на компиляцию кода: он принимает миллисекунды (что можно увидеть с флагом --trace-opt).

Теперь поговорим об этом LazyCompile. Вот цитата из Вячеслава Егорова (бывший v8 dev) blog:

Если вы используете процессоры V8, помните, что LazyCompile: префикс не означает, что это время было потрачено на компилятор, это просто означает, что сама функция была составлена ​​лениво.

Звездочка перед именем функции означает, что время тратится на оптимизированную функцию, тильда - не оптимизирована.

Относительно вашего вопроса о том, сколько раз функция компилируется. На самом деле JIT (так называемый full-codegen) создает неоптимизированную версию каждой функции, когда она запускается в первый раз. Но позже на произвольном (ну, в некоторой степени) количестве или перекомпиляции могло случиться (из-за оптимизации и спасения). Но вы не увидите этого в этом профилировании журнала.

Префикс

Stub, насколько мне известно, означает, что выполнение было внутри C-Stub, которое является частью среды выполнения и скомпилировано вместе с другими частями движка (то есть это не JIS-скомпилированный JS-код).

total vs. nonlib:

Эти столбцы просто означают, что там было потрачено x% от общего времени/не-lib. (Я могу отнести вас к обсуждению здесь).

Кроме того, вы можете найти https://github.com/v8/v8/wiki/Using%20V8%E2%80%99s%20internal%20profiler.