精华 Node 案发现场揭秘 —— 文件句柄泄露导致进程假死
发布于 1 年前 作者 hyj1991 3248 次浏览 来自 分享

文件句柄泄露导致的进程假死

开源的 Node.js 性能监控与线上故障定位工具,欢迎大家关注:https://github.com/hyj1991/easy-monitor

好久没写 Node.js 故障案例了,今天是一枚全新的进程假死无响应案例。

特点时完全不同于之前常规遇到的类死循环引发的阻塞假死,值得记录分析的过程,希望对遇到其它的类似案例的开发者有所启发。

I. 故障现象

Easy-Monitor 开源官方讨论群里有一位同学 Midqiu 遇到了进程跑几个小时后就处于假死无响应的问题,而且神奇的是进程假死的同时,监控服务端的 **系统数据 **也同时断开:

image.png

此时 进程数据 界面则回退到实例刚刚接入还未上报数据的状态:

image.png

可以看到业务进程依旧在,检查此进程状态则显示 xprofiler 插件未启用:

image.png

可以确认这个进程在几个小时之前是正确接入了 Easy-Monitor 的监控服务端的,经过和 Midqiu 的沟通,发现从进程假死的那一刻开始, xprofiler 插件的日志就没有再生成了。

但是 xprofiler 插件在设计之初为了规避和 JS 工作主线程之间的互相干扰,所以是采用了 uv trhread 起了工作线程处理内核数据的,理论上 JS 线程卡死也不会影响它的内核日志输出。

这样现象就很奇怪了,Node.js 的 JS 主线程卡死竟然会让插件的日志也无法正常输出。

II. 初步排查问题

既然是进程假死无响应,首先猜测的就是是不是 JS 工作主线程卡死导致的,所以线下沟通 SSH 到服务器上查看假死时的 Node.js 负载:

image.png

使用 top -H -p <pid> 查看发现 CPU 占用不到 1%,内存整体在 300MB 附近也非常正常。这时候其实我还不死心,手动在服务器应用下执行了 xprofiler 插件的命令:

./node_modules/.bin/xprofctl check_version -p <pid>

然而事实证明确实不仅仅是 JS 主线程假死,连插件创建的 IPC 通信线程也假死了:

image.png

此时第一次感到这个问题可能没有想象的那么简单了,初步总结了下故障现象:

  • 运行几小时后 Node.js 服务无响应,进程还在(未重启)
  • 进程的 CPU 和 RSS 均正常
  • xprofiler 插件创建的内核日志子线程和 IPC 通信子线程也无响应

此时没什么好办法,只能祭出大招手动生成分析 Core 文件。

III. 分析 Coredump

首先在服务器上安装神器 gcore,然后执行 sudo gcore <pid> 生成 core 文件。Midqiu 将生成的 core 文件和 node 可执行文件打包发给了我,本地使用 GDB 进行分析:

 gdb ./node core.24269
 For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from ./node...done.
warning: .dynamic section for "/lib64/ld-linux-x86-64.so.2" is not at the expected address (wrong library or version mismatch?)
warning: Could not load shared library symbols for 7 libraries, e.g. /lib64/libdl.so.2.
Use the "info sharedlibrary" command to see the complete listing.
Do you need "set solib-search-path" or "set sysroot"?
Core was generated by `node'.
#0  0x00007f2e584a6483 in ?? ()
[Current thread is 1 (LWP 24270)]
(gdb) bt
#0  0x00007f2e584a6483 in ?? ()
#1  0x0000000000000000 in ?? ()

好家伙全是乱码,这里显然缺少运行时的动态链接库,将服务器上的动态链接库打包后手动指定根目录:

(gdb) set sysroot /home/hyj1991/git/examples/0924/libs
Reading symbols from /home/hyj1991/git/examples/0924/libs/lib64/libdl.so.2...(no debugging symbols found)...done.
Reading symbols from /home/hyj1991/git/examples/0924/libs/lib64/libstdc++.so.6...(no debugging symbols found)...done.
Reading symbols from /home/hyj1991/git/examples/0924/libs/lib64/libm.so.6...(no debugging symbols found)...done.
Reading symbols from /home/hyj1991/git/examples/0924/libs/lib64/libgcc_s.so.1...(no debugging symbols found)...done.
Reading symbols from /home/hyj1991/git/examples/0924/libs/lib64/libpthread.so.0...(no debugging symbols found)...done.
warning: Unable to find libthread_db matching inferior's thread library, thread debugging will not be available.
Reading symbols from /home/hyj1991/git/examples/0924/libs/lib64/libc.so.6...(no debugging symbols found)...done.
Reading symbols from /home/hyj1991/git/examples/0924/libs/home/work/node/node_modules/xprofiler/build/binding/Release/node-v72-linux-x64/xprofiler.node...(no debugging symbols found)...done.

这样总算可以正常查看每一个线程的栈帧回溯:

(gdb) thread apply all bt
Thread 13 (LWP 24269):
#0  0x00007f2e584a6483 in epoll_wait () from /home/hyj1991/git/examples/0924/libs/lib64/libc.so.6
#1  0x00000000013480e0 in uv__io_poll (loop=loop@entry=0x2c9aac0 <default_loop_struct>, timeout=5526) at ../deps/uv/src/unix/linux-core.c:309
#2  0x0000000001335ddf in uv_run (loop=0x2c9aac0 <default_loop_struct>, mode=UV_RUN_DEFAULT) at ../deps/uv/src/unix/core.c:381
#3  0x0000000000a4b5f5 in node::NodeMainInstance::Run() ()
#4  0x00000000009da5a8 in node::Start(int, char**) ()
#5  0x00007f2e583ca3d5 in __libc_start_main () from /home/hyj1991/git/examples/0924/libs/lib64/libc.so.6
#6  0x0000000000979215 in _start ()

Thread 8 (LWP 24285):
#0  0x00007f2e5846ce2d in nanosleep () from /home/hyj1991/git/examples/0924/libs/lib64/libc.so.6
#1  0x00007f2e5846ccc4 in sleep () from /home/hyj1991/git/examples/0924/libs/lib64/libc.so.6
#2  0x00007f2e559809c8 in xprofiler::CreateIpcServer(void (*)(char*)) () from /home/hyj1991/git/examples/0924/libs/home/work/node/node_modules/xprofiler/build/binding/Release/node-v72-linux-x64/xprofiler.node
#3  0x00007f2e5877cdd5 in start_thread () from /home/hyj1991/git/examples/0924/libs/lib64/libpthread.so.0
#4  0x00007f2e584a5ead in clone () from /home/hyj1991/git/examples/0924/libs/lib64/libc.so.6

Thread 7 (LWP 24284):
#0  0x00007f2e5846ce2d in nanosleep () from /home/hyj1991/git/examples/0924/libs/lib64/libc.so.6
#1  0x00007f2e5846ccc4 in sleep () from /home/hyj1991/git/examples/0924/libs/lib64/libc.so.6
#2  0x00007f2e559409b4 in xprofiler::CreateLogThread(void*) () from /home/hyj1991/git/examples/0924/libs/home/work/node/node_modules/xprofiler/build/binding/Release/node-v72-linux-x64/xprofiler.node
#3  0x00007f2e5877cdd5 in start_thread () from /home/hyj1991/git/examples/0924/libs/lib64/libpthread.so.0
#4  0x00007f2e584a5ead in clone () from /home/hyj1991/git/examples/0924/libs/lib64/libc.so.6

可以看到 xprofiler 插件创建的两个线程正常工作,JS 主线程则处于 epoll_wait 状态,没有任何可疑的会导致进程假死的阻塞!

到这里我是真的疑惑了,线程堆栈完全正常,CPU 和内存也正常,那么进程为什么会处于无响应的假死状态呢?

IV. 另一个思路

连万能的 Core 分析都找不到异常的地方,似乎这个问题已经没办法排查了。

无奈之下,我又回到一开始的问题: 为什么处于子线程的 xprofiler 插件不再输出日志

回顾了一遍 xprofiler 插件中定时采集输出日志的逻辑:

static void CreateLogThread(void *unused) {
  uint64_t last_loop_time = uv_hrtime();
  while (1) {
    Sleep(1);

    SetNowCpuUsage();

    if (uv_hrtime() - last_loop_time >= GetLogInterval() * 10e8) {
      last_loop_time = uv_hrtime();
      bool log_format_alinode = GetFormatAsAlinode();

      GetMemoryInfo();
      GetLibuvHandles();

      Sleep(1);

      WriteCpuUsageInPeriod(log_format_alinode);
      WriteMemoryInfoToLog(log_format_alinode);
      WriteGcStatusToLog(log_format_alinode);
      WriteLibuvHandleInfoToLog(log_format_alinode);
      WriteHttpStatus(log_format_alinode, GetPatchHttpTimeout());
    }
  }
}

可以确定只要日志线程依旧存活,一定会走到写日志的逻辑:

#define WRITET_TO_FILE(type)                   \
  uv_mutex_lock(&logger_mutex);                \
  type##_stream.open(filepath, std::ios::app); \
  type##_stream << log;                        \
  type##_stream.close();                       \
  uv_mutex_unlock(&logger_mutex);

这里用了一个宏来将日志写到文件,本质上就是一个 ofstream 的文件流,看到这里我有一个猜测是不是这个文件流打开失败了导致内核日志没有正常写入文件。

于是去翻 Linux Man 手册 open 方法 看看哪些情况下会调用失败:

image.png

其它的看起来都不太可能,唯独和文件打开数相关的限制看起来可疑:

The system limit on the total number of open files has been reached.

到这里感觉突然峰回路转,立马联系 Midqiu 查看重启后的进程的文件打开数:

lsof -p <pid> | wc -l

并且将这个值与系统的 ulimit -n 限制进行对比:

image.png

果然,重启后的 Node.js 进程文件打开数随着访问量逐步上涨,逐渐逼近系统的限制,问题就是出在这个假死进程的文件打开数上!

V. 定位问题代码段

有了问题的方向接下来就方便很多,我们可以使用 lsof -p <pid> 查看具体是哪些句柄:

image.png

好家伙,8W+ 的 /home/work/node/logs/important/production.x-access.serverless_runtime.2020-09-24.log 这个文件的重复文件句柄!

经过沟通,这个文件是项目里面用来记录用户请求 access 日志对应的日志文件,那么猜测是记录 access 日志的中间件在重复的 fs.open 此文件。

拿到这个日志中间件的源代码,果然存在一个 Logger 类里有 fs.open 动作:

private async ensureFile(filename: string): Promise < number > {
  if(Object.keys(this.fds).length > 150) {
    for (const [_, fd] of Object.entries(this.fds)) {
      fs.close(fd);
    }
    this.fds = {};
   }
  if (!this.fds[filename]) {
    this.fds[filename] = await new Promise<number>((resolve, reject) => {
      fs.open(filename, "a", (err, fd) => {
        if (err) {
          reject(err);
        } else {
          resolve(fd);
        }
      });
    });
  }
  return this.fds[filename];
}

然后是记录日志的地方会调用这个方法获取日志文件的 fd:

private async appendLine(filename: string, line: string): Promise < void> {
  const fd = await this.ensureFile(filename);
  await new Promise(((resolve, reject) => {
    fs.write(fd, line + "\n", (err) => {
      if (err) {
        reject(err);
      } else {
        resolve();
      }
    });
  }));
}

这个 Logger 类到这里看起来也没问题,然而最后回到服务的入口文件时发现开发者竟然把 Logger 这个需要全局共享的实例初始化放到了 Express 中间件里:

app.use(function(req, res, next) {
  //...
  const logger = new Logger();
  res.locals.log = logger;
  next();
});

这就导致每来一个用户请求都会实例化一个 Logger 实例,此时记录本次请求的 access 日志就会打开一个重复的日志文件句柄,从而导致了进程文件句柄的泄露。

最后进程可使用的文件句柄数超过系统限制后进程就处于假死状态,表现为文件句柄数溢出后,后续此进程任何 I/O 相关的系统调用都会阻塞。

VI. 修复文件句柄泄露

定位到代码问题后,修复也非常简单,这里可以全局初始化 access 日志实例,请求日志共享此文件句柄即可。

另外简单点也可以直接修改 appendLine 方法为 fs.writeFile :

private async appendLine(filename: string, line: string): Promise < void> {
  await new Promise(((resolve, reject) => {
    fs.writeFile(filename, line + "\n", { flag: 'a' }, (err) => {
      if (err) {
        reject(err);
      } else {
        resolve();
      }
    });
  }));
}

这样牺牲了一部分性能但是不会有文件句柄泄露的问题。

VII. 小结

实际上 Node.js 提供的的 stream 、 net 以及 fs 里面的 fd 相关操作函数,这些模块或者函数相对 Node.js 其它封装的上层函数更接近底层库。

而历史经验告诉我们,这部分底层库相关的函数,如果自己没有完全理解千万不要随便想当然的用,大概率一写一个大坑等着你。

最后 Easy-Monitor 即将加入对监控进程自身的文件打开数的监控,帮助大家下次秒解决此类问题。

18 回复

像文件指针这种东西在C里面经常会用到,但是习惯了JS的自动释放,用到文件指针这种需要释放的东西就容易遗忘。当然本文最骚的一点是IO堵死。

这个故事告诉我们能用大众写法,就别特立独行搞花里胡哨的。为了节约一点点性能,却为后人埋深坑。

我之前遇到一个分页问题,一遇到并发分页就不对,就是有人利用了koa的this.context基类特性,结果还是给后人埋坑。

图全部403了,这让我想起了几年前做视频项目时遇到的一个问题,我们的渲染服务器是在windows上跑的,渲染完毕后会清理掉一些临时文件,这时候莫名其妙地出现程序卡在删除文件的操作上,所以我们简单的把await 去掉了,是的,无论成功还是失败我们不等了,继续进行之后的任务也能正常清理掉相应的临时文件,因为问题很偶发难以复现最终也没有深入去研究

@justjavac 图片用的语雀的,我改成本地上传

@zy445566 是的,IO 阻塞没有任何报错信息,看 strace 也只能看到系统调用挂了但是不知道为什么

@zengming00 这种事情有条件还是得跟下,要不然累积下来自己也会觉得 Node.js 不稳定不安全啥的

很强的实践例子。非常赞

其实我也有个疑问,就是8W+的句柄,还没有死之前做一次,快照对比,找到只新增没回收的对象,数量不应该很明显么

@zy445566 堆使用内存只有 100M,而且看曲线很平稳,这个显然并没有计算到堆空间里

@theanarkh thx,啥时候来写 V8 的源码分析

@hyj1991 老实说我震惊了,一开始我并不了解open方法,原来就是把原生的数字封装返回了。

这一点都不js,我觉得这个open应该叫openUnsafe。我觉得safe的open应该是返回挂在heap的对象,当该对象不被引用而回收的时候,自动执行close。而不是像数字这种基本类型,虽然也挂在heap上,但却无法做为是否引用结束的判断依据。虽然这样说有点代码评论家的意思。

@zy445566 本来就是这样,js 层返回的 fd 就是进程空间对应的文件描述符,所以这类问题看堆快照看不到问题

强,这种问题我自认为解决不了,系统编程的经验太缺乏了。如果不是从open那里发现了handler数量有限制这个不起眼的关联,根本不会去查看打开的文件数,更不会怀疑到是access的问题

@youth7 只能说有时候排查问题真的需要灵光一闪。。。再牛逼的工具也不能解决所有问题,以前我以为 Coredump 分析可以搞定一切了

@zy445566 类似故障,如果程序代码没有明显bug,那么多半是和外设IO(磁盘,网络)接口有关。 首先排查网络和磁盘相关资源开销。

@hyj1991 不,我的意思其实是 https://github.com/nodejs/node/pull/35412

但是node.js管理者,他认为:

  • 应该使用FileHandle来管理,而不是像我这样新开一个类
  • 不希望过分依赖GC来达到自动fs.close的功能
  • 弱回调不能够达到在进程退出后的更好的操作
  • 并且更希望能对fd进行跟踪

@zy445566 这个需要良好习惯养成,或者说这就是经验的体现:

  1. 避免使用过于精妙的实现(除非利益相关)。便于debug以及后期维护。
  2. 有始有终,不要怕麻烦。 比如打开文件就记得关闭,不要完全依靠底层自动关闭。 比如事务处理,显示打开就记得显示提交或者回滚(即便是中间件中)。
回到顶部