node.js - guide - Cómo leer la salida del procesador de ticks del generador interno

server on node js

Question

Estoy interesado en perfilar mi aplicación Node.js. Lo empecé con la --prof y obtuve un archivo v8.log . Tomé el procesador de Windows-tick y obtuve un registro de perfiles supuestamente legible por humanos. En la parte inferior de la pregunta hay algunos extractos pequeños del archivo de registro, que no entiendo.

Me sale el enfoque estadístico de las garrapatas. No entiendo lo que significa total contra nonlib . Además, no entiendo por qué algunas cosas tienen el prefijo LazyCompile , Function , Stub u otros términos.

La mejor respuesta que podría esperar es la documentación / guía completa para el formato de salida del procesador de ticks, que explique completamente cada término, estructura, etc.

Salvo eso, simplemente no entiendo qué es la compilación perezosa. ¿Es compilación? ¿No se compilan todas las funciones exactamente una vez? Entonces, ¿cómo puede la compilación ser una parte importante de la ejecución de mi aplicación? La aplicación se ejecutó durante horas para producir este registro, y supongo que la compilación interna de JavaScript lleva milisegundos. ¿Esto sugiere que la compilación lenta es algo que no ocurre una vez por función, sino que ocurre durante algún tipo de evaluación de código? ¿Esto significa que en todas partes tengo una definición de función (por ejemplo, una función anidada), la función interna se "compila de forma perezosa" cada vez?

No pude encontrar ninguna información sobre esto en ningún lugar, y he estado buscando en Google por DÍAS ...

También me doy cuenta de que hay muchas banderas de perfil. Referencias adicionales sobre aquellos también son bienvenidos.

[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

Answer 1

De hecho, tiene razón al suponer que el tiempo realmente pasó compilando el código: toma milisegundos (lo que podría verse con el --trace-opt ).

Ahora hablando de eso LazyCompile . Aquí hay una cita del blog de Vyacheslav Egorov (ex v8 dev):

Si está utilizando los procesadores de garrapatas V8, tenga en cuenta que el prefijo LazyCompile: no significa que este tiempo se gastó en el compilador, solo significa que la función en sí misma se compiló perezosamente.

Un asterisco antes de un nombre de función significa que el tiempo se está gastando en función optimizada, tilda, no optimizado.

Con respecto a su pregunta acerca de cuántas veces se compila una función. En realidad, el JIT (denominado full-codegen) crea una versión no optimizada de cada función cuando se ejecuta por primera vez. Pero más tarde podría ocurrir un número arbitrario (bueno, hasta cierto punto) o recompilaciones (debido a optimizaciones y rescates). Pero no verá nada de esto en este tipo de registro de perfiles.

Stub mi entender, el prefijo Stub significa que la ejecución se realizó dentro de un C-Stub, que forma parte del tiempo de ejecución y se compila junto con otras partes del motor (es decir, no es un código JS compilado por JIT).

total vs nonlib

Estas columnas simplemente significan que el x% del tiempo total / no lib se gastó allí. (Puedo referirte a una discusión here ).

Además, puede encontrar https://github.com/v8/v8/wiki/Using%20V8%E2%80%99s%20internal%20profiler útil.