精华 手把手测试你的JS代码性能
发布于 6 个月前 作者 hyj1991 4925 次浏览 来自 分享

手把手测试你的JS代码性能

I. 简介

在服务器端领域,对于代码的性能一般都会有所要求。而V8引擎非常的强大,很多时候并不需要我们去做额外的优化工作,但是我们仍然会想去了解更多编写的js代码执行的细节:

  • 想列出来所有执行时长超过300ms的函数该怎么做?
  • 想列出所有引擎热优化失败的函数以及优化失败的原因该怎么做呢?

下面就想通过v8-profiler以及对应的cpu日志解析的过程,来和大家探讨下我的一些实践。

II. 获取cpu-profiler日志

前面提到的函数执行耗费,以及是否被优化等信息其实在v8引擎提供的profiler api中都可以直接获取到。

v8-profiler正是基于这些引擎提供的profiler api进行了扩展,那么将收集到的数据以JSON对象的形式反馈到JS层。更详细的实现这里不展开,有兴趣的朋友可以自己阅读下源代码,其实也并不复杂。

下面我们来看看如何使用这个工具获取我们想要的cpu-profiler日志:

'use strict';
const fs = require('fs');
const http = require('http');
const profiler = require('v8-profiler');

/**
 * @description 开启cpu-profiling
 * @param1 第一个参数是本次profile的名称
 * @param2 第二个参数是是否记录采样器数据
 */
profiler.startProfiling('', true);

/**
 * @description 1分钟后关闭cpu-profiling,并把Log写入文件
 */
setTimeout(() => {
    console.log('stop');
    let result = profiler.stopProfiling('');
    fs.writeFileSync('./node.cpu.json', JSON.stringify(result));
    result.delete();
}, 60 * 1000);

/**
 * @description 路由函数,内部使用了try catch
 */
function testTryCatch(req, res) {
    try {
        res.end('tryCatchStatement success!');
    } catch (e) {
        res.end('tryCatchStatement ' + e.message);
    }
}

/**
 * @description 路由函数,强制阻塞200ms后返回
 */
function testSleep(req, res) {
    const now = Date.now();
    while (Date.now() - now < 200) {}
    res.end('testSleep success');
}

http.createServer(function (req, res) {
    if (req.url === '/tryCatchStatement') {
        return testTryCatch(req, res);
    }
    if (req.url === '/sleep') {
        return testSleep(req, res);
    }
    res.end('404');
}).listen(8081);

以上代码创建了一个http服务器,提供了一个 /tryCatchStatement/sleep 的路径的访问。可以看到一分钟后,v8-profiler 就会将收集到的cpu日志输出到当前目录的 node.cpu.json 文件中。

我们可以使用ab等测试工具通过高频词的访问来增加cpu日志中的信息反馈,先开启一个bash窗口,测试 /tryCatchStatement路径:

$ ab -n 100000 -c 100 http://127.0.0.1:8081/tryCatchStatement 

另开一个bash窗口,测试 /sleep 路径:

$ ab -n 100000 -c 100 http://127.0.0.1:8081/sleep

开始测试一分钟后,当前目录生成了 node.cpu.json 文件,里面保存了这一分钟内的cpu日志。

III. 解析cpu-profiler日志

cpu日志其实就是一个大的JSON对象,其中的 samples节点数组和timestamps节点数组中的时间戳是一一对应的,并且samples节点数组中的每一个值,其实对应了head节点的深度优先遍历ID ,明白了这一点其实很容易对日志结构进行解析,有兴趣的朋友们可以自己尝试一番。

我之前编写过一个命令行工具用来简单的对cpu日志内容进行解析,这次花了点时间全部重构了一番,支持更多的功能,展示的东西也更加清晰。下面就以上面的例子中生成的 node.cpu.json 文件为例,使用工具来获取 I节 中的两个问题答案。

安装v8-cpu-analysis

执行如下命令安装工具,mac/linux下可能需要sudo权限:

$ npm install v8-cpu-analysis -g 

安装成功后直接在终端输入:

$ va

则会显示出一些具体命令使用细节,这里不展开,大家可以自己尝试一番。更多的使用方法可以参看: https://www.npmjs.com/package/v8-cpu-analysis

README.md中提供了中文文档(在README的下半部分)。

获取所有未被v8引擎优化的函数及未优化原因

在命令行执行如下命令,即可获取到所有未被优化的函数:

$ va bailout node.cpu.json --only

这里加了 --only 参数表示只展示那些未优化的函数,如下:

Functions V8 Engine Optimization Failed List(Sort By HitTimes DESC):
1. testTryCatch (TryCatchStatement) (/Users/huangyijun/git/examples/testHttpServer.js 26)
2. NativeModule.compile (TryFinallyStatement) (bootstrap_node.js 485)
3. tryModuleLoad (TryFinallyStatement) (module.js 443)
4. createServerHandle (TryCatchStatement) (net.js 1157)
5. tryOnTimeout (TryFinallyStatement) (timers.js 233)

这里做了排序,和提示中的一样,是对未优化函数命中次数,从多到少做了排序,即 意味着排在第一位的函数是最热点的未优化函数

每一行 按照 函数名 (未优化原因) (函数具体路径) 的形式 组织起来,这里可以看到,排名第一的 testTryCatch 函数是最热点的未被优化函数,其未被引擎优化的原因是函数内部的 try{} catch 造成的。

获取所有执行时长超过300ms的函数

在命令行执行如下命令,即可获取到所有未被优化的函数:

$ va timeout node.cpu.json 300 --only

这里加了 --only 参数表示只展示那些执行时长超过300ms的函数,如下:

Function Execute Time > 300ms List:
1. (idle) (2.50s 3.64%) 
2. parserOnHeadersComplete (798.3ms 1.16%) (_http_common.js 45)
3. parserOnIncoming (798.3ms 100.00%) (_http_server.js 463)
4. emit (798.3ms 100.00%) (events.js 136)
5. emitTwo (798.3ms 100.00%) (events.js 104)
6. anonymous (798.3ms 100.00%) (/Users/huangyijun/git/examples/testHttpServer.js 43)
7. testSleep (410.3ms 51.39%) (/Users/huangyijun/git/examples/testHttpServer.js 37)
8. parserOnHeadersComplete (737.5ms 1.07%) (_http_common.js 45)
9. parserOnIncoming (737.5ms 100.00%) (_http_server.js 463)

由于结果比较长,只展示了前九行,这里加了 --only 参数同样是为了只列出执行时长超过300ms的函数。

这里的每一行 按照 函数名 (本函数执行时长 占据父函数总执行时长百分比) (函数具体路径) 的形式 组织起来。这里可以看到,排除掉所有的库函数,我们编写的testSleep函数执行时长多于300ms,需要重点排查此函数是否有逻辑问题。

结语

其实我觉得现在接触到的都还是外围的一些知识,有空想要仔细研究下引擎内部的profiler原理。

与之相对的,后面也打算利用工作之余做一个 v8-mem-analysis 工具,用来调试内存泄漏的问题。

更大的理想是能实现对线上的进程进行这些深入底层的监控,来保障Node进程能更加稳定的运行。

最后项目地址在: https://github.com/hyj1991/v8-cpu-analysis

欢迎有兴趣的朋友一起开发完善~

13 回复

很不错,加精

测试性能的推荐https://github.com/mcollina/autocannon,这样更node,哈哈

@i5ting 真是个好东西,回头研究下。做这个工具的目的主要是想反馈下代码中未被引擎优化的部分,以及未优化的原因,加以改进。以前有朴大的node-profiler,然而这个工具只更新到0.12.x就没有后续了。

@hyj1991 加油,看好你~

正好测试一下我刚写的小项目。

@szy0syz 好的哇,有什么问题可以在这里讨论下

试了一下,但是,执行超时的函数调用并没有解析出来。

@haijianyang 这是纯函数执行时长,异步操作不会一起统计的,拿来查找优化: 长cpu类的逻辑运算

来自酷炫的 CNodeMD

@hyj1991 发的东西都很实用啊,在实际应用很普遍

这个 很实用 ,代码性能测试 , 为重构 提供依据

@helloyokoy 最近在做重构,暂时用 vue 做 UI 部分的重构,正好完成了cpu数据采集解析部分的新 ui,有兴趣可以看看这个 demo http://hyj1991.ml/easy-monitor/demo

回到顶部