前言
先把干货放前面,辅助排查的 npm 模块有:wtfnode,why-is-node-running,active-handles 等,使用方法差不多如下,可以查看各自的文档。
1 | const wtf = require('wtfnode'); |
也可以更深入地排查,因为上述模块的核心都是 Node.js 文档未标注的两个接口:
1 | process._getActiveHandles(); |
好了,本篇到这里结束了,剩下的内容,劝你还是跳过吧:流水帐警告⚠️️ 翻车警告⚠️️
问题经过
背景是为 ts + egg 项目引入 apm 探针,由于 apm 必须在“启动文件”的第一行完成加载,即整个 egg 的生命周期开始之前,因此需要使用独立的脚本或指令进行启动。具体如何处理可以参考这篇博客。
问题就出在脱离了 egg 的声明周期,得额外管理不同运行环境下 apm-server(APM 数据采集服务器)的地址配置。可能第一时间就能想到 Node.js 的环境变量,思路没错,毕竟程序和 egg-bin 绑定,NODE_ENV 环境变量的命名符合规范,主要为 development、test、production。特定环境读取特定的即可。
但调试过程中,写错了 apm-server 路径,遇到了进程启动过程中卡住的现象。解决起来很容易,但好奇是什么原因造成的,因为正常引入 elastic-apm-node 并填写一个错误的 url 并不妨碍主流程的运行。
战前准备
省略翻代码的过程,简单的结论就是:进程卡死的问题由 egg-bin 内置的 ets(egg-ts-helper)指令诱发,其使用 child_process.execSync
方法启动子进程来预加载一部分代码用作检查,而子进程卡住不退出,才导致父进程无法继续向下执行。
ets 执行 execSync 的位置:https://github.com/whxaxes/egg-ts-helper/blob/master/src/utils.ts#L107 其中 cmd 的内容是执行
./scripts/eggInfo
文件。eggInfo 指令了 egg 的 loader 来获取插件信息,因此 apm 作为生命周期之前的模块被顺便加载了。
经过检查和断点调试,已经找出进程无法正常退出的根源在 elasitc-apm-http-client
模块和 apm-server
的通讯之间。并且如果把 apm-server 的目标地址改成本机未使用的端口,如 http://localhost:8201
,进程可迅速地正常退出。但如果填写一个错误地或不存在的地址,例如 http://10.10.10.10:8200
,以致访问超时,进程就会挂起。
开始狩猎
我们已经缩小了问题重现的范围,就可以仔细阅读代码了。
首先看向 http client 创建的步骤,唯一值得注意的点是一个轮询操作。apm 创建时默认开启了 elastic-apm-http-client 的 centralConfig
选项,此功能是允许在 Kibana 看板上直接修改 apm agent 的配置而无须重启 Node.js 进程,实现原理便是轮询 apm-server 以查询最新的配置信息。
1 | Client.prototype._pollConfig = function () { |
虽然轮询可怕,但上面已经为 Timeout 调用了 unref 方法。正常来说,只要没有其他 event loop 在运行,Timer.unref()
能够让 Node.js 进程在 Timeout 回调调用前退出,可以防止程序空转。
因此问题不在这段代码,为了验证推断,关闭此选项之后,果然依旧不能正常退出。
既然进程还在运转,就一定有其他的 event loop。在 elastic-apm-http-client 中继续寻找到了另一个 Timeout,该函数每次触发数据上报时都会被调用。
1 | Client.prototype._maybeCork = function () { |
Timer.refresh()
可以重置已执行的定时任务,这里很有可能是真正的问题点。
暂停代码阅读,先盲目猜测一波:在第一次请求超时之前,进程一定不会退出,但超时之后,将在 30 秒后才会重新发起新的请求,进程退出的机会就在这 30 秒。而 _maybeCork 这里虽然每次数据上报都会触发不经过 unref 处理的 setTimeout,奈何我查了 bufferWindowTime 默认才 20 毫秒。所以问题出在这里的可能性又很渺茫了,试下把这段注释掉,果然……
但凭着对 elastic-apm-node 项目的熟悉,性能指标的上报间隔恰好也是 30 秒,这里一定有个定时任务的,但之前直接在项目中搜索关键字未找到,就忽略了。
根据相关时间字段,又检索到了定时任务的创建地点 —— measured-reporting
模块,然而这里也做了 unref 处理。
1 | _createIntervalCallback(intervalInSeconds) { |
狩猎失败/超时
在 node_modules 中全局搜索了 setTimeout 以及 setInterval,排除了所有可疑迹象,剩下的连接就难排查了,迫于“生产力”,问题暂时追踪到这里。。。
亡羊补牢
思考了对应的解决方案:
- 将 ets 改成异步执行,但可能失去了前置检查的意义
- 分析并重写 elastic-apm-node 的连接机制
- 在 ets 执行时不启动 apm
- 做好连通性检测,确保 apm 的配置可靠再 apm.start(),但网络请求是异步的,会让 apm 之后整个项目的模块加载都在异步回调中处理
1、2 的成本太高,而 4 没有做过可靠的测试,不保证不会对模块加载和优化产生副作用,所以最可行的方案是 3。
找准方向就开搞,通过 process.env 入手,关注几个比较有用的环境变量:
- process.env.NODE_ENV
- process.env.ETS_REGISTER_PID,此变量存在时,证明有 ets 参与,不启动。但特别地,单独运行
ets
时没有此变量,也没有 NODE_ENV,应对方法是将 NODE_ENV 为 undefined 的环境也排除。 - process.env.npm_lifecycle_event,是 npm 添加的当前执行的 npm script 名称标识。可以考虑为 start,restart 时才启动。
补充方案:
通过 process.env 向 apm 传递自定义参数,便于控制配置项。
最后 apm 启动头部长这个样子
1 | // 自定义 APM_ENABLE 作为开关条件 |
总结
虽然没结论,但进程挂起的根本原因是没错的。找 BUG 最耗时的是方向歪了,试过用干净的 Node.js 代码模拟,没能复现问题。而 wtfnode 和其他跟踪模块,因为 callsite 覆盖问题,也没能提供清晰的调用栈,或许应该考虑从修复 callsite 这个方向入手?
To be continue?
但是意义不大了,从这堆充满 hack 的代码中并没有学到特别有价值的东西,而且时间成本太高。倒是警醒自己在 Timer 和 socket 的底层使用上,务必留意 unref 的处理。还是把时间留给更重要的事吧,衰!