使用V8和node輕松profile分析nodejs應用程序

簡介

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

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

下面就一起來看看吧结胀。

使用V8的內(nèi)置profiler工具

nodejs是運行在V8引擎上的,而V8引擎本身就提供了內(nèi)置的profile工具责循,要想直接使用V8引擎糟港,我需要下載V8源代碼,然后進行build院仿。一般來說我們有兩種build V8的方法秸抚。

使用gm來build V8

gm是一個非常方便的all-in-one的腳本速和,可以用來生成build文件,觸發(fā)build過程和運行測試用例剥汤。

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

我們可以為其創(chuàng)建一個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.觸發(fā)build欲低,3.運行測試用例

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

gn args out/foo

上面的命令將會開啟一個編輯窗口,用來輸入gn的參數(shù)畜晰。

我們可以添加list來查看所有的參數(shù)描述:

gn args out/foo --list

當然我們也可以直接指定參數(shù)砾莱,來創(chuàng)建build文件:

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

除了gn之外,我們還可以使用v8自帶的v8gen來創(chuàng)建build文件:

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

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

創(chuàng)建好build文件之后凄鼻,我們就可以進行編譯了腊瑟。

build所有的V8:

ninja -C out/x64.release

只build d8:

ninja -C out/x64.release d8

最后我們運行測試,來驗證是否構(gòu)建成功:

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

生成profile文件

build好V8之后野宜,我們就可以使用其中的命令來生成profile文件了扫步。

找到d8文件:

d8 --prof app.js

通過添加 --prof 參數(shù),我們可以生成一個v8.log文件匈子,這個文件中包含了profiling數(shù)據(jù)河胎。

注意這時候的v8.log文件雖然不是二進制格式的,但是閱讀起來還是有難度的虎敦,因為它只是簡單的做了log操作游岳,并沒有進行有效的統(tǒng)計分析。

我們看下生成的文件:

...
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
...

可以看到日志文件中只記錄了事件的發(fā)生其徙,但是并沒有統(tǒng)計信息胚迫。

分析生成的文件

如果想要生成我們看得懂的統(tǒng)計信息,則可以使用:

//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頁面來統(tǒng)一展示這個結(jié)果呢?

有的闹获,V8提供了profview工具期犬,讓我們可以從web UI來分析生成的結(jié)果。

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 還可以接其他參數(shù)鲤妥,比如 --log-timer-events佳吞, 通過使用這個參數(shù)可以用來統(tǒng)計V8引擎中花費的時間。

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

tools/plot-timer-events v8.log

第一個命令生成v8.log文件棉安,第二個命令會生成一個timer-events.png圖形文件底扳,更加直觀的展示數(shù)據(jù)。

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

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

使用nodejs的profile工具

在nodejs 4.4.0之前凳宙,只能下載V8的源代碼進行編譯,才能進行profile职祷。 而在nodejs 4.4.0之后氏涩,node命令已經(jīng)集成了V8的功能。

我們可以使用 node --v8-options 來查看 node中可用的V8參數(shù):

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
...

參數(shù)很多有梆,同樣的我們可以使用 --prof 參數(shù):

node --prof app.js

會在本地目錄生成一個類似 isolate-0x102884000-14025-v8.log 的文件是尖。

文件的內(nèi)容和V8生成的一致,這里就不列出來了泥耀。

要想分析這個文件饺汹,可以使用:

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

看下生成的分析結(jié)果:

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時間兜辞。

上面的百分百的意思是,在采樣的這些數(shù)據(jù)中夸溶,有93.2%的都在運行C++代碼逸吵。那么我們接下來就應該去看一下,到底是哪些C++代碼占用了最多的時間缝裁,并找出相應的解決辦法扫皱。

本文作者:flydean程序那些事

本文鏈接:http://www.flydean.com/nodejs-profile/

本文來源:flydean的博客

歡迎關(guān)注我的公眾號:「程序那些事」最通俗的解讀,最深刻的干貨捷绑,最簡潔的教程韩脑,眾多你不知道的小技巧等你來發(fā)現(xiàn)!

?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請聯(lián)系作者
  • 序言:七十年代末胎食,一起剝皮案震驚了整個濱河市扰才,隨后出現(xiàn)的幾起案子,更是在濱河造成了極大的恐慌厕怜,老刑警劉巖衩匣,帶你破解...
    沈念sama閱讀 222,000評論 6 515
  • 序言:濱河連續(xù)發(fā)生了三起死亡事件蕾总,死亡現(xiàn)場離奇詭異,居然都是意外死亡琅捏,警方通過查閱死者的電腦和手機教硫,發(fā)現(xiàn)死者居然都...
    沈念sama閱讀 94,745評論 3 399
  • 文/潘曉璐 我一進店門,熙熙樓的掌柜王于貴愁眉苦臉地迎上來几苍,“玉大人挎峦,你說我怎么就攤上這事∷寻桑” “怎么了市俊?”我有些...
    開封第一講書人閱讀 168,561評論 0 360
  • 文/不壞的土叔 我叫張陵,是天一觀的道長滤奈。 經(jīng)常有香客問我摆昧,道長,這世上最難降的妖魔是什么蜒程? 我笑而不...
    開封第一講書人閱讀 59,782評論 1 298
  • 正文 為了忘掉前任绅你,我火速辦了婚禮,結(jié)果婚禮上昭躺,老公的妹妹穿的比我還像新娘忌锯。我一直安慰自己,他們只是感情好领炫,可當我...
    茶點故事閱讀 68,798評論 6 397
  • 文/花漫 我一把揭開白布偶垮。 她就那樣靜靜地躺著,像睡著了一般帝洪。 火紅的嫁衣襯著肌膚如雪针史。 梳的紋絲不亂的頭發(fā)上,一...
    開封第一講書人閱讀 52,394評論 1 310
  • 那天碟狞,我揣著相機與錄音啄枕,去河邊找鬼。 笑死族沃,一個胖子當著我的面吹牛频祝,可吹牛的內(nèi)容都是我干的。 我是一名探鬼主播脆淹,決...
    沈念sama閱讀 40,952評論 3 421
  • 文/蒼蘭香墨 我猛地睜開眼常空,長吁一口氣:“原來是場噩夢啊……” “哼!你這毒婦竟也來了盖溺?” 一聲冷哼從身側(cè)響起漓糙,我...
    開封第一講書人閱讀 39,852評論 0 276
  • 序言:老撾萬榮一對情侶失蹤,失蹤者是張志新(化名)和其女友劉穎烘嘱,沒想到半個月后昆禽,有當?shù)厝嗽跇淞掷锇l(fā)現(xiàn)了一具尸體蝗蛙,經(jīng)...
    沈念sama閱讀 46,409評論 1 318
  • 正文 獨居荒郊野嶺守林人離奇死亡,尸身上長有42處帶血的膿包…… 初始之章·張勛 以下內(nèi)容為張勛視角 年9月15日...
    茶點故事閱讀 38,483評論 3 341
  • 正文 我和宋清朗相戀三年醉鳖,在試婚紗的時候發(fā)現(xiàn)自己被綠了捡硅。 大學時的朋友給我發(fā)了我未婚夫和他白月光在一起吃飯的照片。...
    茶點故事閱讀 40,615評論 1 352
  • 序言:一個原本活蹦亂跳的男人離奇死亡盗棵,死狀恐怖壮韭,靈堂內(nèi)的尸體忽然破棺而出,到底是詐尸還是另有隱情纹因,我是刑警寧澤喷屋,帶...
    沈念sama閱讀 36,303評論 5 350
  • 正文 年R本政府宣布,位于F島的核電站瞭恰,受9級特大地震影響逼蒙,放射性物質(zhì)發(fā)生泄漏。R本人自食惡果不足惜寄疏,卻給世界環(huán)境...
    茶點故事閱讀 41,979評論 3 334
  • 文/蒙蒙 一、第九天 我趴在偏房一處隱蔽的房頂上張望僵井。 院中可真熱鬧陕截,春花似錦、人聲如沸批什。這莊子的主人今日做“春日...
    開封第一講書人閱讀 32,470評論 0 24
  • 文/蒼蘭香墨 我抬頭看了看天上的太陽驻债。三九已至乳规,卻和暖如春,著一層夾襖步出監(jiān)牢的瞬間合呐,已是汗流浹背暮的。 一陣腳步聲響...
    開封第一講書人閱讀 33,571評論 1 272
  • 我被黑心中介騙來泰國打工, 沒想到剛下飛機就差點兒被人妖公主榨干…… 1. 我叫王不留淌实,地道東北人冻辩。 一個月前我還...
    沈念sama閱讀 49,041評論 3 377
  • 正文 我出身青樓,卻偏偏與公主長得像拆祈,于是被迫代替她去往敵國和親恨闪。 傳聞我的和親對象是個殘疾皇子,可洞房花燭夜當晚...
    茶點故事閱讀 45,630評論 2 359

推薦閱讀更多精彩內(nèi)容