使用V8和node轻松profile分析nodejs应用程序
简介
我们使用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的博客
欢迎关注我的公众号:「程序那些事」最通俗的解读，最深刻的干货，最简洁的教程，众多你不知道的小技巧等你来发现！
