js调用controller_Node.js调试之性能测试篇(一)

cd3083ea-152f-eb11-8da9-e4434bdf6706.png

前言

这是性能测试篇的第一篇,主要讲解如何通过v8-profiler和Chrome开发者工具中的JavaScript Profiler分析Node应用的CPU性能。

案例分析


由于我日常工作中接触到的Node框架是egg.js,所以下面的代码是在该框架下写的,其实具体用什么框架并不重要,重要的是分析问题的思路。OK,让我们首先看一下具体的代码。

cf3083ea-152f-eb11-8da9-e4434bdf6706.png


从图中我们可以看到controller目录下有一个home.js文件,该文件下有一个HomeController类,这个类里面有两个方法:createUser和profile。createUser这个方法用crypto.pbkdf2Sync对password进行加密,然后保存在users这个全局对象中;profile这个方法利用v8-profiler收集CPU运行时的信息,并保存到test.cupprofile文件中。
具体如何使用v8-profiler,请参考:https://github.com/node-inspector/v8-profiler
接下来还需要看一下router.js,这个文件是用来将路由和controller目录下的代码关联起来。比如访问/user/create,就会去调用上面提到的createUser方法;访问/profile,就会调用上面提到的profile方法。

d13083ea-152f-eb11-8da9-e4434bdf6706.png

数据收集


在介绍如何收集Node运行时的CPU数据之前,需要先介绍一下ApacheBench,它是一款性能压测工具,能够模拟大量并发的http请求。由于我的电脑是Mac,自带该工具,命令行中为ab,所以这里就不介绍如何安装了,如果您对它有兴趣,可以参考下面链接:https://www.tutorialspoint.com/apache_bench/apache_bench_quick_guide.htm
接下来,让我们开始收集数据吧。首先通过”npm run start“命令启动egg应用,然后通过”ab -k -c 20 -n 2000 "http://127.0.0.1:7001/user/create?username=breath.wl&password=password"“模拟并发请求,其中”-n“表示发出2000个请求,”-c“表示并发请求数为20,”-k“表示http请求采用keep-alive方式。运行完该命令我们会得到以下结果:

d73083ea-152f-eb11-8da9-e4434bdf6706.png

红框框住的部分是我们需要注意的,从中我们可以看出本次测试一共消耗了87.333秒,每秒处理的请求数量为22.9个,这个并发处理的数量还是相当低的。
接下来我们在访问以下/profile,会得到一个test.cpuprofile文件,这里我们将其改名为test1.cpuprofile。

性能分析

已经得到test1.cpuprofile文件了,接下来就可以利用Chrome开发者工具中的JavaScript Profiler对其进行分析了,通过下图的步骤加载文件:

db3083ea-152f-eb11-8da9-e4434bdf6706.png

加载完毕之后,选择Heavy (Bottom Up)选项,会得到如下图,这个选项将函数按照耗时的顺序从高到底进行排序,点开还可以看到该函数的调用栈。从图中可以看到PBKDF2耗时占据95.33%,点开可以看到该函数被createUser函数中的pbkdf2Sync调用。

dc3083ea-152f-eb11-8da9-e4434bdf6706.png


除了从Heavy (Bottom Up)这个选项,让我们还从火焰图的角度分析一下,选择Chart选项,会得到如下图。

de3083ea-152f-eb11-8da9-e4434bdf6706.png


这密密麻麻的,说实话看着就有点头疼,还是让我们缩小一下范围吧。从下图中仍然可以看出pbkdf2Sync仍然是消耗时间的大头,并且几乎占据了createUser所有时间。

e13083ea-152f-eb11-8da9-e4434bdf6706.png

尝试优化


结合上面的分析,可以知道createUser中pbkdf2Sync消耗了大量时间,那么该如何优化呢?这里之所以导致应用性能不好,每秒只能处理22.9个请求,主要是因为pbkdf2Sync非常消耗CPU的计算资源,而且是同步的。这里我们可以将其改成异步,具体修改如下:

e43083ea-152f-eb11-8da9-e4434bdf6706.png


重新执行一下”ab -k -c 20 -n 2000 "http://127.0.0.1:7001/user/create?username=breath.wl&password=password"。结果如下图所示,出人意外,总时间消耗的更多了为93.127秒,每秒处理的请求次数为21.48,修改后性能竟然还下降了?

e53083ea-152f-eb11-8da9-e4434bdf6706.png


获取应用程序的运行时文件,并修改为test2.cpuprofile,利用Chome开发者工具中的JavaScript Profiler分析一下看看。下图是以Self Time排序(不保存其调用函数消耗的时间),可以看到最消耗时间的,已经不是pbkdf2了,而是garbage collector了。

e73083ea-152f-eb11-8da9-e4434bdf6706.png


以Total Time排序(包含其调用函数的时间)看看具体的情况,可以看出(anonymous)和_tickCallback分别消耗了42.19%和33.42%的时间。

e93083ea-152f-eb11-8da9-e4434bdf6706.png


为什么会导致这样的问题呢,嘿嘿,我们将会在下一篇文章中揭秘,敬请期待。

总结

本文我们利用v8-profiler和Chrome开发者工具中的JavaScript Profiler来分析Node的CPU性能,并尝试进行优化,但却没有成功,下一篇文章将会对其进行解释。


版权声明:本文为weixin_30061835原创文章,遵循CC 4.0 BY-SA版权协议,转载请附上原文出处链接和本声明。