All Articles

Node.JS Profile 4.1 Profile实践

1. 前言

本文是系列文章Node.JS Profile的一部分,完整的文章列表请去总章查看。

本文主要负责介绍Node的命令行Profile知识及实践操作。

2. 介绍

在系列文章的前几节里,基本上已经把Node应用程序最关键的几个性能指标项目都过了一遍,这几节的主要目的都是为了Profile进行知识储备,并打好对某一方面进行针对性查错的基础。

在掌握了前几节的内容之后,就可以回过头来回到当前这个系列文章的主题Profile来了,当然我们这里说的是狭义上的Profile(时间消耗),即观察,并了解Node进程具体在做什么,每一步都花了多少时间,以便有针对性地进行查错和调优。

狭义上的Profile(时间消耗)是非常重要的。一个应用程序如果需要顺利运行需要很多资源,包括且不限于:CPU、内存、磁盘、网络,很多情况下应用程序都会去申请、消耗这些资源以完成自身的工作任务,而Profile让应用程序研发者详细了解应用程序是如何申请、消耗这些资源并完成任务的。只有了解了这些信息之后,研发者才能知道哪里出了问题,哪里还有提升空间。

Note:

本文的版本时效性可能比较敏感,关于行文及范例中使用的Node版本,请查看总章进行了解。

3. Node原生工具进行Profile

3.1 Node官方Guide

Node官方文档有一篇Guide,详细介绍了如何进行profile。本文下面主要就是对该Guide进行翻译及针对实际操作进行总结。

Node的内置Profiler来自V8,V8官方的Profiler介绍可以查看:Using V8’s internal profiler,其实和Node的Guide比起来差的不多,但更针对性地对浏览器进行了操作介绍。

3.2 版本要求

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.

3.3 Profile范例

调优前的范例代码如下,注意运行前请预先装好ApacheBench

文件夹结构:

  • bash/profile-ab.sh
  • bash/profile-server.sh
  • profile/package.json
  • profile/server.js

执行步骤:

  • cd profile
  • npm install
  • cd ..
  • chmod +x bash/profile-ab.sh
  • chmod +x bash/profile-server.sh
  • ./bash/profile-server.sh:保证服务器进程运行中
  • ./bash/profile-ab.sh
  • 查看结果

执行结果:

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个请求
  • 很糟糕

3.4 解析Profile日志

在刚才运行profile-ab.sh脚本的路径下,会产生一个文件名类似isolate-0x103000000-v8.log这样的文件。该文件比较大,就不放gist了,请自行实验获取范例。

然后使用以下命令将该日志解析生成可读的内容:

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

3.5 理解Profile日志内容

解析出来的日志文件内容有点多,原文放在附录部分,点击这里查看。

从上到下主要分为几个耗时分类,一个个细说。

3.5.1 Shared libraries

Node进程使用到的系统级动态链接库部分的时间消耗,会显示在这个分类下。

该分类的几列:

  • ticks:每个库所占用的ticks数量
  • total:每个库占用的ticks总量百分比
  • nonlib:这列在当前分类不适用,因为本来这里列的就都是类库时间消耗,nonlib当然没有数据
  • name:动态链接库的文件位置

3.5.2 JavaScript、C++、Summary

这几个分类放一起说,因为他们的列数据含义相同。

JavaScript

JavaScript代码部分的时间消耗,包括了当前项目源代码部分的时间消耗和第三方node_modules的时间消耗。

C++

Node进程在C++代码里的时间消耗,Node本身是构建在V8引擎之上的,所以一些Node标准库里的API,基本上都是C++时间消耗。当然这个分类也包含了一些作为第三方addon加载的插件的时间消耗。

Summary

这个分类应该是当前报表中最重要的部分,没有细节,就仅仅只是将所有的分类的时间消耗总量都放在一起,形成一个直观的结果。一般来说看Profile结论报表,第一个要看的就是Summary,有一个最直观的结论之后再去找对应部分的细节。

这里需要注意的有两处:

  • GC:整个报表中唯一只在这个Summary中能找到内存回收(GC)相关的时间消耗数据
  • Unaccounted:偶尔,Profiler会无法当前执行的内容到底是什么,这类的ticks就会被归类到Unaccounted这个分类下

列含义

  • ticks:占用的ticks数量
  • total:占用的ticks总量百分比
  • nonlib
    • 这列描述的是将Shared libraries所产生的时间消耗忽略之后,当前条目自身产生的时间消耗(ticks)所占的百分比
    • 举例来说:你写的JS代码中new了一个对象,然后内存分配器会问系统去要内存,这里可能就会产生/usr/lib/system/libsystem_malloc.dylib的时间消耗了,nonlib列给的百分比就是去掉这个libsystem_malloc.dylib库产生的时间消耗之后,你代码中new对象所产生的时间消耗所占的百分比
  • name:
    • JavaScript:函数名,以及其在源代码中的位置
    • C++:函数名,一般都是Node运行时和V8相关的函数
    • Summary:分类名

关于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,他们都有各自的意义,这里罗列下一般常见的(不保证全):

  • Function:普通的JS函数
  • LazyCompile:懒编译的JS函数
  • RegExp:正则表达式引擎
  • Builtin:Node运行时内建的JS函数
  • Stub:Node运行时内建的C函数

3.5.3 C++ entry points

这部分描述的是当逻辑从JS代码跨界到C++代码运行时,其中消耗的时间。

这部分的意义不是很大,毕竟如果真的有大量和C++相关的时间消耗的话,直接看C++相关的部分即可。只有一种情况是需要仔细查看这部分的,就是从JS到C++之间的交换出了问题,JS本身没有很大的性能问题,且C++也没有,而是在两者之间做数据和消息交换的时候出了问题。

范例直接看本文附带的例子即可,里面C++占了绝大部分的时间消耗,而同样的在C++ entry points也有对应的巨量时间消耗占比。

3.5.4 Bottom up (heavy) profile

这部分是性能问题的暴露部分,一般看完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报表中的这部分,性能问题都能找到原因。

4. 资料

4.1 火焰图相关

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

资料:

5. 附录

5.1 解析完成的Profile日志内容 {#ID51}

Published 2018/2/27

Some tech & personal blog posts