|

Profiling mit Node.js und webpack

In einigen Fällen möchte man wissen, welche Aufgabe bei einem webpack-basierten Projekt am längsten benötigt und wieso. Oder wie sich die Build-Zeit ergibt.

Dies geht ganz einfach mit der Profiling-Funktion von webpack.

Wir erstellen ein sehr kleines Projekt mit der aktuellsten Version von webpack und testen anhand diesem die Werte.

In diesem Beispiel benutzen wir dafür webpack und Swiper:

npm init -y
npm i webpack webpack-cli -D
npm i swiper --save
mkdir src
touch src/index.js

Wir prüfen kurz die verwendeten Versionen:

node --version && npm --version && ./node_modules/.bin/webpack --version

Die verwendeten Versionen in unserem Beispiel sind folgende:

v10.0.0
6.0.0
4.6.0

Es folgen ein paar Zeilen Code in der index.js:

const Swiper = require('swiper')
const swiper = new Swiper()

Danach starten wir webpack mit verschiedenen Optionen:

node_modules/.bin/webpack --mode=development
node_modules/.bin/webpack --mode=development --progress --profile
node_modules/.bin/webpack --mode=production
node_modules/.bin/webpack --mode=production --progress --profile

Die Ausgabe des letzten Befehls sieht folgendermaßen aus:

319ms building modules                              
2ms finish module graph                             
1ms sealing                                
0ms basic dependencies optimization 
0ms dependencies optimization                       
1ms advanced dependencies optimization 
2ms after dependencies optimization 
0ms optimizing 
0ms basic module optimization 
0ms module optimization 
4ms advanced module optimization                           
0ms after module optimization 
1ms basic chunk optimization                             
1ms chunk optimization 
2ms advanced chunk optimization                   
0ms after chunk optimization 
0ms module and chunk tree optimization 
0ms after module and chunk tree optimization 
0ms basic chunk modules optimization 
5ms chunk modules optimization                           
0ms advanced chunk modules optimization 
0ms after chunk modules optimization 
0ms module reviving                 
1ms module order optimization                       
0ms advanced module order optimization 
0ms before module ids 
0ms module ids 
1ms module id optimization 
0ms chunk reviving                 
0ms chunk order optimization                       
1ms before chunk ids 
0ms chunk id optimization                          
0ms after chunk id optimization 
1ms record modules                 
0ms record chunks                 
6ms hashing 
0ms after hashing 
0ms record hash 
0ms module assets processing 
239ms chunk assets processing
1ms additional chunk assets processing 
0ms recording 
0ms additional asset processing 
24ms chunk asset optimization               
0ms after chunk asset optimization 
1ms asset optimization 
0ms after asset optimization 
0ms after seal 
3ms emitting 
Hash: 5bbb41e966e33503791c
Version: webpack 4.6.0
Time: 684ms
Built at: 2018-04-25 08:33:16
  Asset     Size  Chunks             Chunk Names
main.js  113 KiB       0  [emitted]  main
Entrypoint main = main.js
[0] ./node_modules/swiper/dist/js/swiper.esm.bundle.js + 2 modules 243 KiB {0} [built]
    |    3 modules
[1] ./src/index.js 60 bytes {0} [built]
    factory:52ms building:13ms = 65ms

Man kann diese Werte auch als JSON exportieren und weiterverarbeiten:
node_modules/.bin/webpack --mode=production --progress --profile --json

In der offiziellen webpack Dokumentation sind diese Optionen dokumentiert und die dort gelisteten weiterführenden Links können bei der weiteren Analyse und beim Profiling bestehender Projekte hilfreich sein.

Es gibt auch einige Node.js-Projekte, die übersichtlich weitere Infos anzeigen, zum Beispiel webpackbar.

Profiling mit Node.js

Ebenso kann man direkt über Node.js ein Profiling der Anwendung durchführen. Jedoch wird hier wesentlich mehr ausgegeben. Unter anderem werden die internen Aufrufe und die Aufrufe der nativen Module (zum Beispiel bcrypt) aufgelistet (unter [C++]) wo man entsprechende Performance-Probleme erkennen kann.

Dazu generiert man einen Profiling-Bericht und dieser wird dann in eine menschenlesbare Form umgewandelt:

NODE_ENV=production node --prof src/index.js
node --prof-process isolate-0xnnnnnnnnnnnn-v8.log > processed.txt
...
 [C++]:
   ticks  total  nonlib   name
     45   38.8%   38.8%  T node::contextify::ContextifyScript::New(v8::FunctionCallbackInfo<v8::Value> const&)
      7    6.0%    6.0%  T ___guarded_open_dprotected_np
      3    2.6%    2.6%  t v8::internal::LookupIterator::State v8::internal::LookupIterator::LookupInRegularHolder<false>(v8::internal::Map*, v8::internal::JSReceiver*)
      3    2.6%    2.6%  t node::GetBinding(v8::FunctionCallbackInfo<v8::Value> const&)
      3    2.6%    2.6%  T node::TTYWrap::New(v8::FunctionCallbackInfo<v8::Value> const&)
      3    2.6%    2.6%  T __platform_memcmp
      2    1.7%    1.7%  t std::__1::basic_ostream<char, std::__1::char_traits<char> >& std::__1::__put_character_sequence<char, std::__1::char_traits<char> >(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, char const*, unsigned long)
      2    1.7%    1.7%  T v8::internal::Scavenger::ScavengePage(v8::internal::MemoryChunk*)
      2    1.7%    1.7%  T v8::internal::InnerPointerToCodeCache::GetCacheEntry(unsigned char*)
      2    1.7%    1.7%  T _catopen
      1    0.9%    0.9%  t void v8::internal::Scanner::Advance<false, true>()
      1    0.9%    0.9%  t void std::__1::__insertion_sort_3<v8::internal::EnumIndexComparator<v8::internal::NameDictionary>&, v8::base::AtomicElement<v8::internal::Smi*>*>(v8::base::AtomicElement<v8::internal::Smi*>*, v8::base::AtomicElement<v8::internal::Smi*>*, v8::internal::EnumIndexComparator<v8::internal::NameDictionary>&)
...

Dort sieht man unter dem C++-Bereich die jeweiligen internen Aufrufe und absteigend den Anteil an der gesamten Zeit die ein Script gelaufen ist (1 Tick = 1 interne Zeiteinheit) und kann daraus die entsprechenden Schlüsse ziehen.

Zu diesem Thema gibt es eine Sammlung von Ressourcen inklusive Videos und Slides von der Hausmesse I/O von Google.