天天看點

使用V8和node輕松profile分析nodejs應用程式簡介使用V8的内置profiler工具使用nodejs的profile工具

簡介

我們使用nodejs寫好了程式之後,要是想對該程式進行性能分析的話,就需要用到profile工具了。

雖然有很多很友善和強大的第三方profile工具,但是我們這裡主要講解V8和node自帶的profile,因為他們已經足夠簡單和強大了。使用他們基本上可以滿足我們的日常分析需要。

下面就一起來看看吧。

使用V8的内置profiler工具

nodejs是運作在V8引擎上的,而V8引擎本身就提供了内置的profile工具,要想直接使用V8引擎,我需要下載下傳V8源代碼,然後進行build。一般來說我們有兩種build V8的方法。

使用gm來build V8

gm是一個非常友善的all-in-one的腳本,可以用來生成build檔案,觸發build過程和運作測試用例。

一般來說,gm腳本的位置在:/path/to/v8/tools/dev/gm.py

我們可以為其建立一個alias,友善後面的使用:

alias gm=/path/to/v8/tools/dev/gm.py           

build V8:

gm x64.release           

build之後進行用例驗證:

gm x64.release.check           

是不是很簡單?

手動build V8

手動build V8就比較麻煩了,我們也可以分為三步,1.生成build檔案,2.觸發build,3.運作測試用例

我們可以使用gn來為out/foo生成build檔案:

gn args out/foo           

上面的指令将會開啟一個編輯視窗,用來輸入gn的參數。

我們可以添加list來檢視所有的參數描述:

gn args out/foo --list           

當然我們也可以直接指定參數,來建立build檔案:

gn gen out/foo --args='is_debug=false target_cpu="x64" v8_target_cpu="arm64" use_goma=true'           

除了gn之外,我們還可以使用v8自帶的v8gen來建立build檔案:

alias v8gen=/path/to/v8/tools/dev/v8gen.py

v8gen -b 'V8 Linux64 - debug builder' -m client.v8 foo           

建立好build檔案之後,我們就可以進行編譯了。

build所有的V8:

ninja -C out/x64.release           

隻build d8:

ninja -C out/x64.release d8           

最後我們運作測試,來驗證是否建構成功:

tools/run-tests.py --outdir out/foo
//或者
tools/run-tests.py --gn           

生成profile檔案

build好V8之後,我們就可以使用其中的指令來生成profile檔案了。

找到d8檔案:

d8 --prof app.js           

通過添加 --prof 參數,我們可以生成一個v8.log檔案,這個檔案中包含了profiling資料。

注意這時候的v8.log檔案雖然不是二進制格式的,但是閱讀起來還是有難度的,因為它隻是簡單的做了log操作,并沒有進行有效的統計分析。

我們看下生成的檔案:

...
profiler,begin,1000
tick,0x7fff688bbe36,839,0,0x0,6
tick,0x7fff688bc2d2,2081,0,0x0,6
tick,0x100373430,3263,0,0x0,6
code-creation,Builtin,3,3746,0x1008aa020,1634,RecordWrite
code-creation,Builtin,3,3766,0x1008aa6a0,457,EphemeronKeyBarrier
code-creation,Builtin,3,3773,0x1008aa880,44,AdaptorWithBuiltinExitFrame
code-creation,Builtin,3,3781,0x1008aa8c0,294,ArgumentsAdaptorTrampoline
code-creation,Builtin,3,3788,0x1008aaa00,203,CallFunction_ReceiverIsNullOrUndefined
code-creation,Builtin,3,3796,0x1008aaae0,260,CallFunction_ReceiverIsNotNullOrUndefined
code-creation,Builtin,3,3804,0x1008aac00,285,CallFunction_ReceiverIsAny
code-creation,Builtin,3,3811,0x1008aad20,130,CallBoundFunction
...           

可以看到日志檔案中隻記錄了事件的發生,但是并沒有統計資訊。

分析生成的檔案

如果想要生成我們看得懂的統計資訊,則可以使用:

//windows
tools\windows-tick-processor.bat v8.log

//linux
tools/linux-tick-processor v8.log

//macOS
tools/mac-tick-processor v8.log           

來生成可以了解的日志檔案。

生成的檔案大概是下面樣子的:

Statistical profiling result from benchmarks\v8.log, (4192 ticks, 0 unaccounted, 0 excluded).

 [Shared libraries]:
   ticks  total  nonlib   name
      9    0.2%    0.0%  C:\WINDOWS\system32\ntdll.dll
      2    0.0%    0.0%  C:\WINDOWS\system32\kernel32.dll

 [JavaScript]:
   ticks  total  nonlib   name
    741   17.7%   17.7%  LazyCompile: am3 crypto.js:108
    113    2.7%    2.7%  LazyCompile: Scheduler.schedule richards.js:188
    103    2.5%    2.5%  LazyCompile: rewrite_nboyer earley-boyer.js:3604
    103    2.5%    2.5%  LazyCompile: TaskControlBlock.run richards.js:324
     96    2.3%    2.3%  Builtin: JSConstructCall
    ...           

用慣的IDE的同學可能在想,能不能有個web頁面來統一展示這個結果呢?

有的,V8提供了profview工具,讓我們可以從web UI來分析生成的結果。

profview是一個html工具,我們可以從 https://chromium.googlesource.com/v8/v8.git/+/master/tools/profview/ 下載下傳。

如果要使用profview,我們還需要對第一步生成的v8.log檔案進行預處理:

linux-tick-processor --preprocess > v8.json           

然後在profview頁面上傳v8.json進行分析即可。

生成時間線圖

--prof 還可以接其他參數,比如 --log-timer-events, 通過使用這個參數可以用來統計V8引擎中花費的時間。

d8 --prof --log-timer-events app.js

tools/plot-timer-events v8.log           

第一個指令生成v8.log檔案,第二個指令會生成一個timer-events.png圖形檔案,更加直覺的展示資料。

因為生成日志實際上對程式的性能是有一定的影響的,我們還可以為plot-timer-events添加失真因子,來糾正這個問題。如果我們沒有指定糾正因子,腳本會自動進行查找。當然,我們也可以向下面這樣手動指定:

tools/plot-timer-events --distortion=4500 v8.log           

使用nodejs的profile工具

在nodejs 4.4.0之前,隻能下載下傳V8的源代碼進行編譯,才能進行profile。 而在nodejs 4.4.0之後,node指令已經內建了V8的功能。

我們可以使用 node --v8-options 來檢視 node中可用的V8參數:

node  --v8-options
SSE3=1 SSSE3=1 SSE4_1=1 SAHF=1 AVX=1 FMA3=1 BMI1=1 BMI2=1 LZCNT=1 POPCNT=1 ATOM=0
Synopsis:
  shell [options] [--shell] [<file>...]
  d8 [options] [-e <string>] [--shell] [[--module] <file>...]

  -e        execute a string in V8
  --shell   run an interactive JavaScript shell
  --module  execute a file as a JavaScript module

Note: the --module option is implicitly enabled for *.mjs files.

The following syntax for options is accepted (both '-' and '--' are ok):
  --flag        (bool flags only)
  --no-flag     (bool flags only)
  --flag=value  (non-bool flags only, no spaces around '=')
  --flag value  (non-bool flags only)
  --            (captures all remaining args in JavaScript)

Options:
  --use-strict (enforce strict mode)
        type: bool  default: false
  --es-staging (enable test-worthy harmony features (for internal use only))
        type: bool  default: false
...           

參數很多,同樣的我們可以使用 --prof 參數:

node --prof app.js           

會在本地目錄生成一個類似 isolate-0x102884000-14025-v8.log 的檔案。

檔案的内容和V8生成的一緻,這裡就不列出來了。

要想分析這個檔案,可以使用:

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

看下生成的分析結果:

Statistical profiling result from isolate-0x102884000-14025-v8.log, (296 ticks, 4 unaccounted, 0 excluded).
  
 [Shared libraries]:
   ticks  total  nonlib   name
      6    2.0%          /usr/lib/system/libsystem_pthread.dylib
      6    2.0%          /usr/lib/system/libsystem_kernel.dylib
      2    0.7%          /usr/lib/system/libsystem_malloc.dylib
      1    0.3%          /usr/lib/system/libmacho.dylib
      1    0.3%          /usr/lib/system/libcorecrypto.dylib

 [JavaScript]:
   ticks  total  nonlib   name

...

 [Summary]:
   ticks  total  nonlib   name
      0    0.0%    0.0%  JavaScript
    276   93.2%   98.6%  C++
     24    8.1%    8.6%  GC
     16    5.4%          Shared libraries
      4    1.4%          Unaccounted

 [C++ entry points]:
   ticks    cpp   total   name
    142   63.1%   48.0%  T __ZN2v88internal21Builtin_HandleApiCallEiPmPNS0_7IsolateE
     82   36.4%   27.7%  T __ZN2v88internal40Builtin_CallSitePrototypeGetPromiseIndexEiPmPNS0_7IsolateE
      1    0.4%    0.3%  T __ZN2v88internal36Builtin_CallSitePrototypeGetFileNameEiPmPNS0_7IsolateE
...

           

和V8的也很類似。

從Summary和各個entry points中,我們可以進一步分析程式中到底哪一塊占用了較多的CPU時間。

上面的百分百的意思是,在采樣的這些資料中,有93.2%的都在運作C++代碼。那麼我們接下來就應該去看一下,到底是哪些C++代碼占用了最多的時間,并找出相應的解決辦法。

本文作者:flydean程式那些事

本文連結:

http://www.flydean.com/nodejs-profile/

本文來源:flydean的部落格

歡迎關注我的公衆号:「程式那些事」最通俗的解讀,最深刻的幹貨,最簡潔的教程,衆多你不知道的小技巧等你來發現!