大家好,我是 世奇,笔名 ConardLi

在之前的 提升 Node.js 服务稳定性,需要关注哪些指标?这篇文章中,我们介绍了服务端稳定性需要关注的一些指标,其中有一个非常重要的指标 Libuv latency,计算方式如下:

1
2
3
4
5
const kInterval = 1000;
const start = getCurrentTs();
setTimeout(() => {
  const delay = Math.max(getCurrentTs() - start - kInterval, 0);
}, kInterval);

从代码中我们就能分析出,latency 数值较高通常意味着当前应用的 eventloop 过于繁忙,导致简单的操作也不能按时完成。

而对于 Node.js 进程来说,这类情况很可能是由调用了耗时较长的同步函数或是阻塞的 IO 操作导致。发生这类问题时,对应的线程将没办法进行正常的服务,比如对于 HTTP server 来说,在这段时间内的请求会得不到响应。因此我们需要保证主线程的 libuv latency 尽可能的小。

报警

一个平静的下午,我突然收到了 Libuv latency 的报警:

图片

我们设置的 Libuv latency 的报警阈值是 5000ms,也就是说发生报警时我的服务器至少已经产生了 5S 的延时!

图片

一般很少有 libuv latency 一直很高的情况发生。因为这类情况很可能表明进程已经不能正常服务,通常 CPU 、内存等指标也会出现很明显的异常情况。我们再来看同一时间的 CPU Load、内存、GC:

图片

可以发现这段时间内 CPU Load、内存、GC 同时升高,说明主线程正在执行一个耗时较长的同步函数导致线程阻塞。

想要知道分析出这段时间发生了什么,我们可以需要借助 CPU Profile

CPU Profile

简单理解 CPU Profile 的原理就是:在一段时间内用很高的频率不断获取当前 JavaScript 调用栈,从而我们可以分析出哪些函数耗时最长。

Profiling 技术是一种在应用运行时收集程序相关信息的动态分析手段,利用 V8Profiling API 可以帮助我们创建一个 CPU Profile,从而了解一段时间内进程在执行哪些 js 函数。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
const profiler = require ( 'v8-profiler-node8' ); 
const fs = require ( 'fs' );
const Bluebird = require ( 'bluebird' );
class PackageController extends Controller {
  async cpuProf () {
      console.log( '开始收集' );
      // Start Profiling profiler . startProfiling ( 'CPU profile' );
      await Bluebird.delay( 60000 * 5 );
      const profile = profiler.stopProfiling();
      profile.export()
      .pipe(fs.createWriteStream(`cpuprofile-${Date.now()}.cpuprofile`))
      .on('finish',() => profile. delete ());
  }
}

注意,开始生成 CPU Profile 后我们需要去立即复现问题,从而能让我们在 Profile 中看到正确的分析结果,收集完成后,得到一个 cpuProfile 文件,Chrome 自带了分析 CPU profile 日志的工具。打开 Chrome -> 调出开发者工具(DevTools) -> 单击右上角三个点的按钮 -> More tools -> JavaScript Profiler -> Load,加载刚才生成的 cpuprofile 文件。可以直接用chrome的性能分析直接读这个文件打开分析:

图片

函数占用的时间轴越长,说明这个函数耗时越长,上图我们可以很明显的看到, handleProblemRanking 这个函数占用了7秒之多。

定位代码问题

我们简化一下这个函数:

1
2
3
4
5
6
7
8
9
function handleProblemRanking(tasks) {
// ...
let problems = [];
for (let i = 0; i < problemTask.length; i++) {
  const models = problemTask[i].problems;
  problems = problems.concat(models);
}
// ...
}

里面有一个循环 concat 的操作,于是我在本地 mock 了一些数据,打印了一下执行时间,如果循环万次以上,执行时间居然都是秒级别的。如果把以上代码换成下面的代码,执行时间立马回到毫秒级别:

1
2
3
4
5
6
7
8
9
function handleProblemRanking(tasks) {
// ...
let problems = [];
for (let i = 0; i < problemTask.length; i++) {
  const models = problemTask[i].problems;
  problems.push(...models);
}
// ...
}

然后我查了一下 concat 的原生实现,大概是下面这个样子:

1
2
3
4
5
6
7
8
9
10
// 创建结果数组
var arr3 = []
// 添加 arr1
for(var i = 0; i < arr1Length; i++){
arr3[i] = arr1[i]
}
// 添加 arr2
for(var i = 0; i < arr2Length; i++){
arr3[arr1Length + i] = arr2[i]
}

然后 push 的原生实现:

1
2
3
for(var i = 0; i < arr2Length; i++){
arr1[arr1Length + i] = arr2[i]
}

很明显,concat.push 慢这么多的主要原因就是它创建了一个新数组,还需要额外将第一个数组的元素复制给这个新数组。。。

之前也想过 concat 的性能会比 push 稍微差一点,但是没想到这个性能差距居然有上千倍左右,真是大意了。

如果你想加入高质量前端交流群,或者你有任何其他事情想和我交流也可以添加我的个人微信 ConardLi