本文是系列文章Node.JS Profile的一部分，完整的文章列表请去总章查看。
本文主要负责介绍Node的命令行Profile知识及实践操作。
在系列文章的前几节里，基本上已经把Node应用程序最关键的几个性能指标项目都过了一遍，这几节的主要目的都是为了Profile进行知识储备，并打好对某一方面进行针对性查错的基础。
在掌握了前几节的内容之后，就可以回过头来回到当前这个系列文章的主题Profile来了，当然我们这里说的是狭义上的Profile（时间消耗），即观察，并了解Node进程具体在做什么，每一步都花了多少时间，以便有针对性地进行查错和调优。
狭义上的Profile（时间消耗）是非常重要的。一个应用程序如果需要顺利运行需要很多资源，包括且不限于：CPU、内存、磁盘、网络，很多情况下应用程序都会去申请、消耗这些资源以完成自身的工作任务，而Profile让应用程序研发者详细了解应用程序是如何申请、消耗这些资源并完成任务的。只有了解了这些信息之后，研发者才能知道哪里出了问题，哪里还有提升空间。
Note：
本文的版本时效性可能比较敏感，关于行文及范例中使用的Node版本，请查看总章进行了解。
Node官方文档有一篇Guide，详细介绍了如何进行profile。本文下面主要就是对该Guide进行翻译及针对实际操作进行总结。
Node的内置Profiler来自V8，V8官方的Profiler介绍可以查看：Using V8’s internal profiler，其实和Node的Guide比起来差的不多，但更针对性地对浏览器进行了操作介绍。
Node官方的Profiler内嵌自版本4.4.0，所以请至少使用这个及以上的版本：
Luckily, tools have recently been introduced into Node.js 4.4.0 that facilitate the consumption of this information without separately building V8 from source.
调优前的范例代码如下，注意运行前请预先装好ApacheBench：
文件夹结构：
执行步骤：
执行结果：
Benchmarking localhost (be patient)
Completed 100 requests
Completed 200 requests
Finished 250 requests
Server Software:
Server Hostname: localhost
Server Port: 5000
Document Path: /auth?username=matt&password=password
Document Length: 2 bytes
Concurrency Level: 20
Time taken for tests: 24.817 seconds
Complete requests: 250
Failed requests: 0
Keep-Alive requests: 250
Total transferred: 51500 bytes
HTML transferred: 500 bytes
Requests per second: 10.07 [#/sec] (mean)
Time per request: 1985.384 [ms] (mean)
Time per request: 99.269 [ms] (mean, across all concurrent requests)
Transfer rate: 2.03 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 0.1 0 1
Processing: 99 1909 305.1 1985 2019
Waiting: 99 1909 305.1 1985 2019
Total: 100 1909 304.9 1985 2019
Percentage of the requests served within a certain time (ms)
50% 1985
66% 1991
75% 1995
80% 1997
90% 2002
95% 2005
98% 2011
99% 2014
100% 2019 (longest request)结论：
20个并发，完成250个请求，耗时24.817秒10.07个请求在刚才运行profile-ab.sh脚本的路径下，会产生一个文件名类似isolate-0x103000000-v8.log这样的文件。该文件比较大，就不放gist了，请自行实验获取范例。
然后使用以下命令将该日志解析生成可读的内容：
node —prof-process isolate-0x103000000-v8.log > processed.txt
解析出来的日志文件内容有点多，原文放在附录部分，点击这里查看。
从上到下主要分为几个耗时分类，一个个细说。
Node进程使用到的系统级动态链接库部分的时间消耗，会显示在这个分类下。
该分类的几列：
这几个分类放一起说，因为他们的列数据含义相同。
JavaScript代码部分的时间消耗，包括了当前项目源代码部分的时间消耗和第三方node_modules的时间消耗。
Node进程在C++代码里的时间消耗，Node本身是构建在V8引擎之上的，所以一些Node标准库里的API，基本上都是C++时间消耗。当然这个分类也包含了一些作为第三方addon加载的插件的时间消耗。
这个分类应该是当前报表中最重要的部分，没有细节，就仅仅只是将所有的分类的时间消耗总量都放在一起，形成一个直观的结果。一般来说看Profile结论报表，第一个要看的就是Summary，有一个最直观的结论之后再去找对应部分的细节。
这里需要注意的有两处：
内存回收（GC）相关的时间消耗数据Unaccounted这个分类下nonlib：
Shared libraries所产生的时间消耗忽略之后，当前条目自身产生的时间消耗（ticks）所占的百分比/usr/lib/system/libsystem_malloc.dylib的时间消耗了，nonlib列给的百分比就是去掉这个libsystem_malloc.dylib库产生的时间消耗之后，你代码中new对象所产生的时间消耗所占的百分比关于JavaScript的name列，还有一些细节可以说一下：
每个name列实际函数名之前一般会有一个*或~，星号表示该函数得到了优化，而波浪号则表示没有。这个例子里只有未优化的范例，下面放一个有优化的例子：
ticks parent name
3567 16.9% Builtin: StringEqual
3567 100.0% LazyCompile: *<anonymous> .../node_modules/typeorm/query-builder/transformer/RawSqlResultsToEntityTransformer.js:43:54
3567 100.0% LazyCompile: *InnerArrayFind native array.js:843:24
3441 96.5% LazyCompile: *find native array.js:855:19
3278 95.3% LazyCompile: *<anonymous> .../node_modules/typeorm/query-builder/transformer/RawSqlResultsToEntityTransformer.js:39:37
3278 100.0% Builtin: ArrayForEach
163 4.7% Function: ~<anonymous> .../node_modules/typeorm/query-builder/transformer/RawSqlResultsToEntityTransformer.js:39:37
163 100.0% Builtin: ArrayForEach
126 3.5% Function: ~find native array.js:855:19
114 90.5% LazyCompile: *<anonymous> .../node_modules/typeorm/query-builder/transformer/RawSqlResultsToEntityTransformer.js:39:37
114 100.0% Builtin: ArrayForEach
12 9.5% Function: ~<anonymous> .../node_modules/typeorm/query-builder/transformer/RawSqlResultsToEntityTransformer.js:39:37
12 100.0% Builtin: ArrayForEach此外，函数名之前都会有一个前缀，例如：LazyCompile，他们都有各自的意义，这里罗列下一般常见的（不保证全）：
这部分描述的是当逻辑从JS代码跨界到C++代码运行时，其中消耗的时间。
这部分的意义不是很大，毕竟如果真的有大量和C++相关的时间消耗的话，直接看C++相关的部分即可。只有一种情况是需要仔细查看这部分的，就是从JS到C++之间的交换出了问题，JS本身没有很大的性能问题，且C++也没有，而是在两者之间做数据和消息交换的时候出了问题。
范例直接看本文附带的例子即可，里面C++占了绝大部分的时间消耗，而同样的在C++ entry points也有对应的巨量时间消耗占比。
这部分是性能问题的暴露部分，一般看完Summery不想了解其细节就直接来看这部分是解决问题的最快方案。
和之前其他分类耗时部分不同的是，在这部分里按空行分隔的不同段落都是一个个单独的性能瓶颈点，每个段落的多行表示的是一个调用栈。
此外，这个部分的列内容也和之前的略有不同（主要是parent字段），parent列的百分比意味着：当前行有X%的统计结果会调用当前行的上一行里的函数。
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.
一般情况下，看完Profile报表中的这部分，性能问题都能找到原因。
MAC下的简单生成步骤：
$ npm install stackvis -g
$ NODE_ENV=production node profile/server.js
Server started, listening on port 5000 ...
$ ps aux | grep node | grep -v grep
XXX 69941 0.0 0.2 4920704 34256 s003 S+ 2:45Pm 0:00.43 node profile/server.js
$ sudo dtrace -n 'profile-99 /pid == 69941 && arg1/ { @[ustack()] = count(); }' > stacks.out
$ ./bash/profile-ab.sh
$ stackvis dtrace flamegraph-svg < stacks.out > stacks.svg
# 在浏览器中打开 stacks.svg资料：