Pembuatan Profile NODEJS #3

node --prof-process isolate-0xnnnnnnnnnnnn-v8.log > processed.txt 




Membuka processing.txt di editor teks favorit Anda akan memberi Anda beberapa jenis informasi. File tersebut dipecah menjadi beberapa bagian yang lagi-lagi dipecah menurut bahasa. Pertama, kita melihat bagian ringkasan dan melihat:

 [Summary]:
   ticks  total  nonlib   name
     79    0.2%    0.2%  JavaScript
  36703   97.2%   99.2%  C++
    767    2.0%          Shared libraries
      7    0.0%    0.0%  GC
    215    0.6%          Unaccounted

Ini memberi tahu kita bahwa 97% dari semua sampel yang dikumpulkan terjadi dalam kode C ++ dan bahwa saat melihat bagian lain dari keluaran yang diproses, kita harus memberi perhatian paling besar pada pekerjaan yang sedang dilakukan di C ++ (sebagai lawan JavaScript). Dengan pemikiran ini, selanjutnya kita menemukan bagian [C ++] yang berisi informasi tentang fungsi C ++ mana yang paling banyak menghabiskan waktu CPU dan melihat:

 [C++]:
   ticks  total  nonlib   name
  19557   51.8%   52.9%  node::crypto::PBKDF2(v8::FunctionCallbackInfo<v8::Value> const&)
   4510   11.9%   12.2%  _sha1_block_data_order
   3165    8.4%    8.6%  _malloc_zone_malloc

Kami melihat bahwa 3 entri teratas menyumbang 72,1% dari waktu CPU yang diambil oleh program. Dari keluaran ini, kami segera melihat bahwa setidaknya 51,8% waktu CPU digunakan oleh fungsi yang disebut PBKDF2 yang sesuai dengan pembuatan hash kami dari kata sandi pengguna. Namun, mungkin tidak segera jelas bagaimana dua entri yang lebih rendah menjadi faktor dalam aplikasi kita (atau jika ya, kita akan berpura-pura sebaliknya demi contoh). Untuk lebih memahami hubungan antara fungsi-fungsi ini, selanjutnya kita akan melihat bagian [Profil bottom up (berat)] yang memberikan informasi tentang pemanggil utama dari setiap fungsi. Meneliti bagian ini, kami menemukan:

  ticks parent  name
  19557   51.8%  node::crypto::PBKDF2(v8::FunctionCallbackInfo<v8::Value> const&)
  19557  100.0%    v8::internal::Builtins::~Builtins()
   4510   11.9%  _sha1_block_data_order
  19557  100.0%      LazyCompile: ~pbkdf2 crypto.js:557:16

   4510  100.0%      LazyCompile: *exports.pbkdf2Sync crypto.js:552:30
   4510  100.0%    LazyCompile: *pbkdf2 crypto.js:557:16

   3165    8.4%  _malloc_zone_malloc
   3161  100.0%      LazyCompile: *exports.pbkdf2Sync crypto.js:552:30
   3161   99.9%    LazyCompile: *pbkdf2 crypto.js:557:16

Parsing this section takes a little more work than the raw tick counts above. Within each of the "call stacks" above, the percentage in the parent column tells you the percentage of samples for which the function in the row above was called by the function in the current row. For example, in the middle "call stack" above for _sha1_block_data_order, we see that _sha1_block_data_order occurred in 11.9% of samples, which we knew from the raw counts above. However, here, we can also tell that it was always called by the pbkdf2 function inside the Node.js crypto module. We see that similarly, _malloc_zone_malloc was called almost exclusively by the same pbkdf2 function. Thus, using the information in this view, we can tell that our hash computation from the user's password accounts not only for the 51.8% from above but also for all CPU time in the top 3 most sampled functions since the calls to _sha1_block_data_order and _malloc_zone_malloc were made on behalf of the pbkdf2 function. At this point, it is very clear that the password based hash generation should be the target of our optimization. Thankfully, you've fully internalized the benefits of asynchronous programming and you realize that the work to generate a hash from the user's password is being done in a synchronous way and thus tying down the event loop. This prevents us from working on other incoming requests while computing a hash.

BACA SELANJUTNYA