Node.js 应用故障定位顶级技巧—动态追踪技术 [Dynamic Trace]

发表于 2年以前 | 总阅读数：545 次

背景和行文目的

在做 node 或者其他语言的软件开发时，是否有以下经历：

测试环境一切正常，发到生产环境后，出现诡异问题且难以定位
不同机器、不同容器上，某些逻辑呈现不同的结果，如时区、 host
对于时好时坏的玄学问题，束手无策，没有完整的解决思路，无头苍蝇般的各种尝试，效率低下
遇到坑，习惯搜网友解决方案,然后试很多方案，都不能解决问题，此时就会感觉头皮发麻

我相信，上述我说的经历，大多数人都会有所共鸣。本文，我将尽可能的把我所学的动态追踪技术分享给大家。

文章内容如下所示：

介绍 Dynamic Trace 的概念、优势、原理和用法(我们需要掌握的那部分)
通过 demo ，展示 Dynamic Trace 技术的强大
实战演示：搭建 node 性能监控 easy-monitor 和构建 node 应用，构造诡异故障，并阐述如何用 Dynamic Trace 去精确快速定位
分享代码：会把实战演示的代码放到 github 上，大家可以 clone 自行去体验
动态追踪技术的未来：介绍下目前最领先的 Dynamic Trace 方案
总结：做一个精简的总结
附：其他内容

话不多说，直接开整。

动态追踪技术

是什么

这里我把章亦春大佬的原话引用过来：

动态追踪技术其实是一种后现代的高级调试技术。它可以帮助软件工程师以非常低的成本，在非常短的时间内，回答一些很难的关于软件系统方面的问题，从而更快速地排查和解决问题。

优势

优势如下：

随时随地，按需采集
基于操作系统内核实现，性能损耗极小

原理

动态追踪的事件源根据事件类型不同，主要分为静态探针、动态探针以及硬件事件，其原理如下图所示：

1.png

看不懂也正常，我也看不懂，不过会用进行，就跟你不会造车，但你可以把车开的很溜。

简单点说，就是在 linux 中，进程不能直接访问硬件设备，当进程需要访问硬件设备时，如 IO 操作，必须由用户态切换至内核态，然后通过操作系统调用硬件设备。所以可以通过跟踪进程产生的系统调用，来获得参数、返回值、执行时间，从而完成动态追踪。

我们用的多的是动态探针，它可以让我们实时分析线上运行的程序。

用法

动态追踪工具有 strace 、 dtruss 、 systemtap 、 perf 、 dtrace 、 eBPF 等，我这边使用的是 strace 和 dtruss 。

也就是 linux 环境使用 strace ， macos 系统使用 dtruss 。

strace 的主要参数说明如下表所示：

参数名	含义
-v	输出所有的系统调用，一些调用关于环境变量、状态、输入输出等调用由于使用频繁，默认不输出
-s SIZE	指定输出的字符串的最大长度，默认为32，文件名一直全部输出
-p PID	跟踪指定的进程pid
-c	统计每一系统调用的所执行的时间,次数和出错的次数等
-d	输出strace关于标准错误的调试信息
-f	跟踪由fork调用所产生的子进程
-o filename	将strace的输出写入文件filename
-e trace=network	跟踪与网络有关的所有系统调用
-e trace=file	只跟踪有关文件操作的系统调用

以上参数用的最多的就是 -v 、 -s 、 -p 、 -c 。

比如我现在想看部署在 linux 上的 node 应用运行时的信息，那我就可以执行以下命令

strace -p 8000 -v -s 2048

参照参数说明表解读上述命令：跟踪 pid 为 8000 的进程（ node 应用），输出所有的运行时系统调用，同时指定字符串最大长度为 2048 。

同理， dtruss 的主要参数说明如下表所示：

参数名	含义
-a	输出所有详细信息
-p PID	跟踪指定的进程pid
-c	输出系统调用计数
-d	输出相对时间
-e	输出运行时间
-f	跟踪由fork调用所产生的子进程
-t	仅检查此系统调用
-s	输出堆栈回溯
-o	输出cpu时间

以上参数用的最多的就是 -p 、 -c 、 e 、 f 。

注意：在 macos 系统上使用 dtruss ，要先执行 csrutil disable

命令行例子就不举了，和 strace 是一样的道理。

demo 演示

场景：大家在做开发的时候，有的会遇到时区问题，比如说在我的机器上，时间是对的，但是在其他机器或者容器上，时间是不对的。然后你就很疑惑，开始搜，找到了所谓的执行下某个命令就好了。

思考：你有没有想过两台机器的时间为什么不一样，是哪个环节出了问题，比如下面代码在两台机器上的输出结果为什么不同。

console.log(new Date().toLocaleString())

如果你知道动态追踪技术，那你就可以开启 **透视眼 ** ，看看在系统内核层面，上面代码究竟做了什么事情。

动态追踪：

参照 dtruss 参数表，我们执行如下命令

sudo dtruss -of node time.js

控制台如下图：

2.png

输出了非常多的东西，没关系，我们直接搜 toLocaleString 关键词，结果如下：

3.png

会发现图中绿色框中 read(0x14, "console.log(new Date().toLocaleString())\0", 0x28) 出现了搜索的关键词，这句表达式的字面含义是：系统在读取 time.js 中的内容。

我们顺着上面语句往下阅读，会发现如下图所示重要语句：

4.png

看到上面三个绿色框内容后，已经基本确定， new Date().toLocaleString() 返回值，是系统层面读取 /etc/localtime 的内容。也就是说，这个问题的原因是不同机器的 /etc/localtime 不一样

看到这你会明白：

为什么不同机器的返回值会不一样
为什么网上给的时区解决方案是和 /etc/localtime 有关的

上面这个小 demo ，可以让我们更好的感知用 Dynamic Trace 所带来的巨大好处，所有的代码在内核层面都是裸奔的，它可以帮你更好的定位稀奇古怪的问题。

实战演示

为了更方便的演示，我这边所有操作都是在 mac 电脑进行的。我将做以下操作

搭建 easy-monitor 环境
启动一个 egg 应用
制造制造问题
结合 easy-monitor 用 Dynamic trace 进行有序精准定位
实战总结

搭建 easy-monitor 环境

花了 20 分钟左右，搭建好一个本地 easy-monitor 环境，项目结构如下图所示：

5.png

在官网文档的情况下做了一点点优化，优化如下：

将监控模块整合成 monorepo 形式，使用 pnpm 管理，上 workspace
采用 turbo ，快速拉起所有包的开发模式

搭建好，一键启动开发环境，终端如下图所示：

6.png

web 控制台如下图所示：

7.png

启动一个 egg 应用

这个按照官网文档创建一个 egg 应用，然后按照下图所示进行配置即可

8.png

过程非常简单，在上一个过程，我已经用 turbo 一起启动 egg 应用了。

制造问题

简单化，我们写一个 node 服务，加一个 bug 代码。代码如下：

const Controller = require('egg').Controller;
const fs = require('fs');

async function read() {
  const data = await fs.readFileSync(__dirname + '/home.js', 'utf-8');
  if (data) read();
}

class CpuController extends Controller {
  async index() {
    const { ctx } = this;
    ctx.body = 'cpu will be 90%';
    read();
  }
}

module.exports = CpuController;

访问路由 /cpu 的时候， node 服务进行读取 home.js 文件死循环状态。此时观察 easy-monitor``cpu 状态。如下图所示：

10.png