Comment lire la sortie du processeur tick-profiler interne nodejs
Je suis intéressé par le profilage de mon nœud.application js.
Je l'ai commencé avec le drapeau --prof, et j'ai obtenu un fichier v8.log.
J'ai pris le processeur Windows-tick et obtenu un journal de profilage prétendument lisible par l'homme.
Au bas de la question se trouvent quelques petits extraits du fichier journal, que je ne comprends absolument pas.
Je reçois l'approche statistique des tiques. Je ne comprends pas ce que total vs nonlib moyens.
Aussi, je ne comprends pas pourquoi certaines choses sont préfixées avec LazyCompile, Function, Stub ou d'autres conditions.
La meilleure réponse que je pourrais espérer est la documentation complète / guide du format de sortie du processeur tick, expliquant complètement chaque terme, structure, etc...
Sauf cela, je ne comprends tout simplement pas ce qu'est lazy-compile. Est-il de la compilation? Chaque fonction n'est-elle pas compilée exactement une fois? Alors, comment la compilation peut-elle être une partie importante de l'exécution de mon application? L'application a couru pendant des heures pour produire ce journal, et je suppose que le la compilation JavaScript interne prend des millisecondes. Cela suggère que lazy-compile est quelque chose qui ne se produit pas une fois par fonction, mais qui se produit lors d'une sorte d'évaluation de code? Cela signifie-t-il que partout où j'ai une définition de fonction (par exemple une fonction imbriquée), la fonction interne est "compilée paresseuse" à chaque fois?
Je n'ai trouvé aucune information à ce sujet nulle part, et j'ai googlé pendant des jours...
Aussi, je me rends compte qu'il y a beaucoup de drapeaux de profileurs. Des références supplémentaires à ce sujet sont également les bienvenues.
[JavaScript]: ticks total nonlib name 88414 7.9% 20.1% LazyCompile: *getUniqueId C:ndevSCNAinfralibnode-jsutilsgeneral-utils.js:16 22797 2.0% 5.2% LazyCompile: *keys native v8natives.js:333 14524 1.3% 3.3% LazyCompile: Socket._flush C:ndevSCNAruntime-environmentload-generatornode_moduleszmqlibindex.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:ndevSCNAruntime-environmentload-generatornode_moduleszmqlibindex.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:ndevSCNAruntime-environmentload-generatornode_moduleszmqlibindex.js:346 4862 0.4% 1.1% LazyCompile: *sort native array.js:741 4806 0.4% 1.1% LazyCompile: _.each._.forEach C:ndevSCNAinfranode_modulesunderscoreunderscore.js:76 4481 0.4% 1.0% LazyCompile: ~_.each._.forEach C:ndevSCNAinfranode_modulesunderscoreunderscore.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:ndevSCNAinfralibnode-jsutilsobject-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:ndevSCNAruntime-environmentload-generatornode_modulesqq.js:516
88414 7.9% LazyCompile: *getUniqueId C:ndevSCNAinfralibnode-jsutilsgeneral-utils.js:16 88404 100.0% LazyCompile: *generateId C:ndevSCNAinfralibnode-jsutilsgeneral-utils.js:51 88404 100.0% LazyCompile: *register C:ndevSCNAinfralibnode-jseventspattern-dispatcher.js:72 52703 59.6% LazyCompile: * C:ndevSCNAruntime-environmentload-generatorlibvuser-drivermdrv-driver.js:216 52625 99.9% LazyCompile: *_.each._.forEach C:ndevSCNAruntime-environmentload-generatornode_modulesunderscoreunderscore.js:76 52625 100.0% LazyCompile: ~usingEventHandlerMapping C:ndevSCNAruntime-environmentload-generatorlibvuser-drivermdrv-driver.js:214 35555 40.2% LazyCompile: *once C:ndevSCNAinfralibnode-jseventspattern-dispatcher.js:88 29335 82.5% LazyCompile: ~startAction C:ndevSCNAruntime-environmentload-generatorlibvuser-drivermdrv-driver.js:201 25687 87.6% LazyCompile: ~onActionComplete C:ndevSCNAruntime-environmentload-generatorlibvuser-drivermdrv-logic.js:130 1908 6.5% LazyCompile: ~b native v8natives.js:1582 1667 5.7% LazyCompile: _fulfilled C:ndevSCNAruntime-environmentload-generatornode_modulesqq.js:795 4645 13.1% LazyCompile: ~terminate C:ndevSCNAruntime-environmentload-generatorlibvuser-drivermdrv-driver.js:160 4645 100.0% LazyCompile: ~terminate C:ndevSCNAruntime-environmentload-generatorlibvuser-drivermdrv-logic.js:171 1047 2.9% LazyCompile: *startAction C:ndevSCNAruntime-environmentload-generatorlibvuser-drivermdrv-driver.js:201 1042 99.5% LazyCompile: ~onActionComplete C:ndevSCNAruntime-environmentload-generatorlibvuser-drivermdrv-logic.js:130
1 réponses
En effet, vous avez raison dans votre hypothèse sur le temps réellement passé à compiler le code: cela prend des millisecondes (ce qui pourrait être vu avec --trace-opt flag).
On en parle maintenant LazyCompile. Voici une citation de Vyacheslav Egorov (ancien dev v8) blog :
Si vous utilisez les processeurs tick de V8, gardez à l'esprit que LazyCompile: le préfixe ne signifie pas que ce temps a été passé dans le compilateur, il suffit signifie que la fonction elle-même a été compilé paresseusement.
Un astérisque avant un nom de fonction signifie que le temps est passé dans la fonction optimisée, tilda -- not optimized.
En ce qui concerne votre question sur le nombre de fois qu'une fonction est compilée. En fait, le JIT (appelé full-codegen) crée une version non optimisée de chaque fonction lorsqu'elle est exécutée pour la première fois. Mais plus tard, un nombre arbitraire (enfin, dans une certaine mesure) ou des recompilations pourraient se produire (en raison d'optimisations et de renflouements). Mais vous ne verrez pas tout cela dans ce genre de journal de profilage.
Stub le préfixe au mieux de ma compréhension signifie que l'exécution était dans un C-Stub, qui fait partie de l'exécution et est compilé avec d'autres parties du moteur (c'est-à-dire que ce n'est pas du code JS compilé par JIT).
total vs nonlib:
Ces colonnes signifient simplement que x% du temps total/Non-lib y a été passé. (Je peux vous renvoyer à une discussionici ).
Aussi, vous pouvez trouver https://github.com/v8/v8/wiki/Using%20V8%E2%80%99s%20internal%20profiler utile.