手把手测试你的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，需要重点排查此函数是否有逻辑问题。